terça-feira, 11 de janeiro de 2011

SSIS Fuzzy Lookup e SQLDumper

Ontem eu passei por um bug do SSIS que já está registrado no Connect, mas ainda não tem nenhuma informação de solução. Aproveitei para me distrair um pouco com o dump e resolvi blogar o bug, pois talvez você possa passar pelo mesmo. Então vamos lá...

Estou com minha máquina x64 e usando o BIDS montei um pacote simples que utilize fuzzy lookup (no meu caso contra uma tabela com 1 milhão de registros). Porém quando disparei a execução do pacote, no meio dela apareceu um prompt invocando o SQLDumper e a execução do pacote simplesmente parou, mostrando o mesmo em execução (amarelo), sem falhar ou terminar com sucesso. Mudei um parâmetro ou outro, a massa de dados e nada de resolver o problema, a execução do pacote sempre parava da mesma forma.

Uma pesquisa rápida na internet me mostrou a resposta, que estava lá no connect: Fuzzy lookup triggers SQLDUMPER, even with very small dataset with Run64BitRuntime set to false. Então basta ir à configuração do projeto, em Debugging, e colocar a opção Run64BitRuntime como true. Tentei novamente e tudo funcionou, mas particularmente ainda espero uma resposta definitiva, pois poderia ser um caso onde eu não tenho um driver 32 bits (veja comentário no connect) ou então eu quero após o lookup debugar um script component e, como vocês sabem, tenho que definir a opção acima como false para meu breakpoint funcionar corretamente.

Por curiosidade, peguei o mini dump no caminho “C:\Program Files (x86)\Microsoft SQL Server\100\Shared\ErrorDumps\SQLDmpr0003.mdmp” e abri no Visual Studio 2010, onde no dump summary podemos ver descrito claramente um access violation (0xC0000005) com a informação: “The thread tried to read from or write to a virtual address for which it does not have the appropriate access.”
 
Continuando a diversão, peguei o minidump e abri no windbg, então logo de cara ele mostra a thread de nosso interesse (número 204):

This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(36d0.204): Access violation - code c0000005 (first/second chance not available)

Carreguei os símbolos corretos e deu uma olhada na thread stack:

# 24 Id: 36d0.204 Suspend: 0 Teb: fff0e000 Unfrozen
ChildEBP RetAddr Args to Child
1186ea28 76c10816 00000770 00000000 1186ea70 ntdll!ZwWaitForSingleObject+0x15
1186ea94 75511184 00000770 00000064 00000000 KERNELBASE!WaitForSingleObjectEx+0x98
1186eaac 75511138 00000770 00000064 00000000 kernel32!WaitForSingleObjectExImplementation+0x75
1186eac0 00a9a0be 00000770 00000064 73773105 kernel32!WaitForSingleObject+0x12
1186eb48 00a99c99 737731c9 00000000 00000104 DtsDebugHost!CDmpDump::DumpInternal+0x32e
1186eb84 00a9325a 00a9d5fc 73773799 644b3000 DtsDebugHost!CDmpDump::Dump+0x59
1186edd4 00a932db 1186eea8 00000000 1186edf0 DtsDebugHost!SSISInternalPerformDump+0x19a
1186ede4 6419cccf 1186eea8 1186ee78 75539d57 DtsDebugHost!WEDExceptionFilter+0xf
1186edf0 75539d57 1186eea8 708ea443 00000000 mscorwks!InternalUnhandledExceptionFilter+0x16
1186ee78 774306e7 1186eea8 774305c4 00000000 kernel32!UnhandledExceptionFilter+0x127
1186ee80 774305c4 00000000 1186fb70 773ec390 ntdll!__RtlUserThreadStart+0x62
1186ee94 77430469 00000000 00000000 00000000 ntdll!_EH4_CallFilterFunc+0x12
1186eebc 77418799 fffffffe 1186fb60 1186eff8 ntdll!_except_handler4+0x8e
1186eee0 7741876b 1186efa8 1186fb60 1186eff8 ntdll!ExecuteHandler2+0x26
1186ef90 773d010f 0086efa8 1186eff8 1186efa8 ntdll!ExecuteHandler+0x24
1186ef90 769c99e4 0086efa8 1186eff8 1186efa8 ntdll!KiUserExceptionDispatcher+0xf
1186f2e8 75c4747e 80010088 660330a8 40600000 msvcrt!memcpy+0x1e0
1186f308 75404c78 1186f324 8001007c 1186f7f4 oleaut32!BSTR_UserMarshal+0x50
1186f344 75404c0d 1186f7f4 00359f8a 80010078 rpcrt4!NdrpUserMarshalMarshall+0x4b
1186f374 753e6f8a 1186f3e4 1186f7f4 00359f8a rpcrt4!NdrUserMarshalMarshall+0xd8
1186f3a0 7548013d 708da17a 1186f7ec 0300002c rpcrt4!NdrpClientMarshal+0xf6

1186f7b4 75c0ba02 00359b50 00359f28 1186f7ec rpcrt4!NdrClientCall2+0x19a
1186f7d4 75afc95d 00000020 00000014 1186f894 ole32!ObjectStublessClient+0xa2
1186f7e4 21c571a0 0f81a67c 02379a6c 660330a8 ole32!ObjectStubless+0xf
1186f894 21c571a0 000db174 02379a6c 660330a8 DTS!CGenericEventsImpl::OnCustomEvent+0x2d1
1186f944 21c57a84 000dcbc4 02379a6c 660330a8 DTS!CGenericEventsImpl::OnCustomEvent+0x2d1
1186f96c 227ec729 02379a6c 660330a8 003b8404 DTS!CComponentEventsImpl::FireCustomEvent+0x47
1186f998 227d6d5f 00000000 660330a8 003b8404 DTSPipeline!CErrorHandler::FireCustom+0x52
1186f9b8 6605a756 023eb850 660330a8 003b8404 DTSPipeline!CComponentMetaDataObject::FireCustomEvent+0x26
1186fa2c 2280f75f 023ea488 00000014 1fb555e0 TxBestMatch!CTxFuzzyLookup::ProcessInput+0x107
1186fa94 2280f387 2401e670 00000000 023f3c8c DTSPipeline!CPathExecutionItem::DoWorkPI+0x21a
1186fab4 228119b7 1186fad3 023ef018 00000000 DTSPipeline!CPathExecutionItem::DoWork+0x3d
1186fad4 22811a71 00000000 00000000 1186fb1c DTSPipeline!CSchedulerThread::ProcessWork+0x55
1186fae4 728d29bb 023f3c8c 708dad70 00000000 DTSPipeline!CSchedulerThread::ProcessWorkThreadProc+0x1f
1186fb1c 728d2a47 00000000 75513677 023ef018 msvcr80!_endthreadex+0x3b
1186fb24 75513677 023ef018 1186fb70 773f9d42 msvcr80!_endthreadex+0xc7
1186fb30 773f9d42 023ef018 597c16c4 00000000 kernel32!BaseThreadInitThunk+0xe

1186fb70 773f9d15 728d29e1 023ef018 00000000 ntdll!__RtlUserThreadStart+0x70
1186fb88 00000000 728d29e1 023ef018 00000000 ntdll!_RtlUserThreadStart+0x1b

Olhando a pilha acima, vemos que o pipeline do SSIS estava em execução e processando o nosso fuzzy lookup, quando ele foi fazer uma cópia de memória (memcpy), que gerou a exceção, pois logo depois temos o dispatcher da exceção que em breve utiliza o CDmpDump para gerar o mini dump.

Se executarmos a instrução .ecxr poderemos ver efetivamente que foi a instrução memcpy que gerou a exceção, inclusive quais foram as posições de memória, armazenadas nos registradores ESI e EDI, com o correto ajuste de segmento.

0:024> .ecxr
eax=a66330a8 ebx=1186f7f4 ecx=067f73d6 edx=00000000 esi=8000fffc edi=99fecfdc
eip=769c99e4 esp=1186f2e0 ebp=1186f2e8 iopl=0 nv dn ei pl nz ac po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00010612
msvcrt!memcpy+0x1e0:
769c99e4 f3a5 rep movs dword ptr es:[edi],dword ptr [esi]

Erro simples e solução mais ainda, mas valeu a diversão. Espero que você tenha gostado e até um próximo post!

 
[]s
Luciano Caixeta Moreira - {Luti}
luciano.moreira@srnimbus.com.br
www.twitter.com/luticm
www.srnimbus.com.br

5 comentários:

  1. Luti, você disse que a solução foi simples? não entendi, você só descobriu o módulo que falhou certo?

    Abraço

    ResponderExcluir
  2. hahahaha Solução realmente não é o melhor termo, a Microsoft ainda não deu solução para o problema, o que temos é um workaround, colocando o modo de execução em 64 bits.

    []s
    Luti

    ResponderExcluir
  3. I am reading this blog entry translated by Google, so please forgive me if this question makes little sense…

    I am seeing a crash with a similar backtrace (less detailed) on a 32-bit system.

    msvcrt.dll!_memcpy() + 0x250 bytes
    oleaut32.dll!_BSTR_UserMarshal@12() + 0x50 bytes
    rpcrt4.dll!NdrpUserMarshalMarshall() + 0x52 bytes
    rpcrt4.dll!_NdrUserMarshalMarshall@12() + 0x88 bytes
    rpcrt4.dll!@NdrpClientMarshal@8() + 0xa3 bytes
    rpcrt4.dll!_NdrClientCall2() + 0x138 bytes
    ole32.dll!_ObjectStublessClient@8() + 0x7a bytes
    ole32.dll!_ObjectStubless@0() + 0xf bytes

    I do not have the option of changing my program to be 64-bit.

    Has anybody learned anything more about this issue?

    ResponderExcluir
  4. I should note this crash occurs only on Windows 7; XP handles the call just fine.

    ResponderExcluir
  5. I was passing a string literal instead of a BSTR. BSTR is one of the most deceptive declarations I have ever seen. It's declared as WCHAR*, but it points into the middle of an object.

    ResponderExcluir