Rodrigo Riccitelli Vieira

Posted on Jan 31, 2022

Como resolvemos um bug que afetava 3000 usuários e nos custaria milhões por ano

#microsoft #threading #dump #windbg

Nas últimas semanas, estive envolvido em uma frente de trabalho para identificar o motivo do congelamento em uma aplicação Windows Forms C# x86.

A aplicação é uma RPA que faz uso de algumas bibliotecas de automação bem conhecidas como Microsoft UI Automation, Selenium e White da TestStack.

O sintoma
O que estava em jogo
Um pouco de contexto
Blindando o time
Estudando o código e removendo o "lixo"
Método de trabalho
Expectativa e frustração
Enfim, a luz
Conclusão
Links úteis

O sintoma

Sem aviso, depois de poucos minutos ou horas em uso, a aplicação simplesmente deixava de responder quando a sua tela principal recebia alguma interação do usuário com uma mensagem semelhante a essa:

Quem já precisou investigar bugs, sabe que os intermitentes são os piores de se resolver. Não havia um padrão aparente ou nada muito óbvio naquele momento.

O que estava em jogo

Tínhamos cerca de duas semanas para identificar e resolver o problema, sob o risco de ter que substituir o nosso sistema, desenvolvido internamente, por uma solução de mercado. Com isso, teríamos um valor alto a pagar pelo licenciamento da solução de mercado ao fornecedor e um grande impacto no resultado do negócio da empresa.

Um pouco de contexto

Quando cheguei na equipe que já estava dedicada para a investigação, escutei logo do programador, que havia herdado o sistema há pouco mais de um mês:

“O cara que cuidava desse programa me falou que ele só funciona em Debug”

Pensei: "Bom, talvez tenha alguma diretiva de compilação no código que justifique essa bizarrice".

Mandei: “Beleza, vamos anotar e em releases futuras olhamos pra isso”.

Pedi acesso ao repositório e clonei a solução.

Blindando o time

Enfrentando situações que demandam uma análise aprofundada, venho acumulando cicatrizes há muitos anos e com elas fui conquistando a confiança da diretoria, o que me dava alguma autoridade.

Na semana anterior à que fui chamado para este trabalho, eu estava participando de outra sala de crise, na qual atuei na identificação de falha em outra aplicação. Neste caso tivemos sucesso na resolução do problema.

Neste fórum para o qual fui designado para identificar o motivo do congelamento da aplicação, eu atuei com mais duas pessoas, sendo que uma delas era a que havia recebido o rollout de um dos antigos programadores algumas semanas antes. O antigo programador já não fazia mais parte da empresa.

Logo nas primeiras horas ficou evidente que a cobrança por status seria constante. Quebrar a linha de raciocínio para entrar em reuniões e explicar o que estava sendo feito só atrasaria mais a descoberta da falha. Reforçamos a importância de deixar os programadores focados no problema e o gestor da antiga equipe que construiu o programa ficou responsável por atualizar a gerência.

Estudando o código e removendo o “lixo”

Depois de algum tempo analisando o projeto, algumas coisas começavam a me incomodar:

Application.DoEvents pra tudo quanto é lado;
O projeto referencia uma DLL solitária em uma pasta “Lib”. Infelizmente, ela estava em uso, então não poderia tirar ela de lá (ainda);
Uma classe, que posteriormente batizamos de ThreadPoolFromHell, é encontrada tentando se esconder em uma pasta chamada “Util”. Essa classe é responsável por receber uma Action e enfileirar a Task para execução de forma serial em uma nova Thread em primeiro plano com o Apartment State em STA. O enfileiramento e retirada dessa fila é feito através de um lock explícito em uma lista estática.

Todas as automações eram responsabilidade dessa classe. Enquanto o usuário interagia com outros sistemas, a aplicação sob investigação coletava e extraía dados de vários elementos desses sistemas. Dada a sua aparente importância, resolvo checar as suas alterações na linha do tempo e encontro:

“Alterações na tentativa de melhorar a performance e evitar o fechamento...”

Interessante, não? No commit #f42e786f o programador adicionou o Dispose nas Tasks criadas a partir das Actions, responsáveis pelas automações, na tentativa de solucionar o problema de travamento que, aparentemente, existia desde 2019! Bom, isso certamente não surtiu o efeito esperado, ou eu não estaria agora escrevendo esse texto...

Método de trabalho

Embora tivesse uma interface bastante simples, com alguns poucos botões e um menu lateral, o código era muito modularizado e estava bastante sujo.

Era comum encontrar blocos com dezenas de linhas comentadas que eram prontamente removidas quando nos deparávamos com elas. Com o código no Azure Repos e não tendo mais os antigos programadores no time, não havia nenhum motivo para manter a sujeira que só atrapalhava o entendimento do que estava escrito ali.

A cada nova versão que soltávamos, o código era enviado ao repositório. Embora exista uma solução para entrega automatizada do programa, decidimos gerar o executável diretamente através do Visual Studio, em Debug, como o antigo programador “orientou”.

Com o programa sendo compilado em modo Debug, automaticamente, os arquivos PDB usados para – de forma bastante resumida - linkar o código de máquina ao código fonte, já estavam sendo distribuídos com o restante das dependências.

Ainda sem implementar nenhuma modificação no código, instruímos a equipe responsável por prestar suporte aos usuários para que gerasse e coletasse o dump/arquivo de despejo da aplicação assim que o travamento fosse identificado.

O dump é uma “foto” do conteúdo da memória alocada por um determinado processo. Ele contém, entre outras coisas, o valor de variáveis e as threads em execução. Por se tratar de uma aplicação x86/32 bits, o arquivo de despejo precisava ser gerado pelo Task Manager também 32 bits, disponível em %WINDIR%\SYSWOW64.

Expectativa e frustração

De posse do primeiro arquivo de despejo, ainda sem nenhuma modificação na aplicação, identificamos 14 threads diferentes tentando executar a mesma ação: Reposicionar a janela da aplicação.

Essa ação também era responsabilidade da ThreadPoolFromHell, que inicialmente acreditávamos ter como carga de trabalho apenas as automações. Por não se tratar de uma funcionalidade crítica para o programa, decidimos temporariamente remover essa implementação.

Ainda no primeiro arquivo de despejo, identificamos também threads executando código relacionado à biblioteca Windows UI Automation. Por não acreditar ser um ofensor naquele momento, mantivemos e soltamos a versão #26, sem a thread responsável pelo reposicionamento da janela.

Versão #26 no ar e instantes depois chegaram os primeiros relatos de congelamento. Solicitamos novamente o arquivo de despejo e, como era de se esperar, o código que aparecia em 14 threads diferentes na análise anterior, não estava mais lá. Agora, pela primeira vez, a classe que se escondia sob a pasta “Util”, mostrava sua cara.

Neste relatório gerado pelo Debug Diagnostic Tool (menos poderoso que o WinDbg, conhecido por sua complexidade, porém produtivo), fica evidente que há um deadlock. A thread #15 está há 2 minutos tentando adicionar uma Task de automação na lista cujo lock está ativo na thread #7.

Embora não haja evidente relação direta da thread de automação com a janela principal da aplicação, fica claro que as engrenagens do programa não estão em harmonia.

Decidimos substituir o lock explícito existente no método “Add” da ThreadPoolFromHell por uma ConcurrentQueue, cuja garantia de acesso/consistência por threads distintas é assegurada pelo .Net Framework.

Ainda na ThreadPoolFromHell, alteramos as threads para Background e o Apartment State de STA para MTA. Não conseguimos identificar um motivo para que as tasks de automação ficassem em primeiro plano e o Apartment State foi modificado conforme orientação da documentação do Windows UI Automation.

Soltamos a versão #27. Muita expectativa, mas essa ainda não seria a que nos levaria até o outro lado...

Mais uma vez, arquivo de despejo solicitado e voltamos a avaliar os pontos onde as threads estavam paradas.

O lock explícito não mais aparecia no arquivo de despejo, porém ainda haviam pontos que precisavam de atenção. A cada nova versão, mais sujeira era removida do programa.

Threads do Windows UI Automation seguiam sendo evidenciadas, além de algumas outras relacionadas a elementos de tela, que, naquele momento, ainda não despertavam atenção.

Decidimos remover todo o código que estava relacionado às automações através do Windows UI Automation.

Nova versão no ar e mais uma vez o congelamento que, a essa altura, já nos assombrava há 9 dias.

Enfim, a luz

Além de remover a automação, entre as versões #26 e a #44, diversas outras melhorias foram feitas com base nos pontos que eram indicados a partir da análise dos arquivos de despejo.

Com muito menos código em execução, de posse do mais novo arquivo de despejo, iniciamos a análise.

Neste momento, apelo para o Visual Studio, onde ficaria mais fácil navegar até o código fonte a partir das threads em execução.

A imagem abaixo mostra uma thread durante a análise tentando modificar a visibilidade de um controle presente na tela principal.

Não é possível manipular um elemento de tela a partir de uma thread que não seja a thread principal da aplicação. Por este motivo, é feito um teste no InvokeRequired. Caso este código seja executado por uma thread secundária, a manipulação neste controle deve ser feita pelo formulário que é o “proprietário” do controle.

Este código SEMPRE é executado a partir de uma thread secundária, que é iniciada por uma das automações. O teste sobre o InvokeRequired neste ponto é desnecessário, porém, a implementação, em teoria, está correta! Em nenhuma circunstância a linha que está em execução de acordo com o arquivo de despejo deveria ser acionada.

Removemos o teste sobre o InvokeRequired neste ponto e disponibilizamos a versão #46. Mais uma vez, expectativa, mas depois de tantas frustrações, acompanhávamos as interações do usuário já esperando pelo congelamento provocado por algum outro trecho de código.

As horas foram passando, mais máquinas recebiam a nova versão. Estávamos em contato direto com os usuários e apreensivos por qualquer novo relato. Nenhum novo congelamento foi reportado, retornamos as automações que haviam sido inibidas e, até então, seguimos em laboratório, tentando reproduzir o problema e buscando entender o que fez o InvokeRequired falhar naquele trecho!

Conclusão

Com mais de 20 anos em TI, eu não me lembro de ter trabalho em um código tão maltratado.

Em mais de uma oportunidade, encontramos trechos semelhantes a este:

if(condicaoA)
___if(condicaoA)
______...

Apesar de focados na busca pela solução, não podíamos ignorar coisas assim. Não temos todo o histórico por trás deste sistema, mas, se cada um dos programadores que passaram por ele, tivesse o deixado um pouco melhor a cada commit, certamente ele não estaria tão deteriorado como quando começamos a trabalhar nele.

E pra finalizar, sem deixar nenhuma ponta solta...

Lembram da DLL aparentemente perdida sob a pasta "Lib"? Identificamos a sua origem e a substituímos pelo pacote Nuget mais recente disponível.

E quanto aos Application.DoEvents? Removemos todos!

Cuidado com o Invoke ao manipular controles de tela, ele pode travar seu programa! Considere sua substituição por BeginInvoke.

Evite os loops infinitos. Avalie o uso de CancellationToken sempre que possível.