Como o tempo linear se transforma no Windows em O (n²)

Recentemente, tive atrasos de vários minutos em minha estação de trabalho. Após a investigação, descobriu-se que a causa do problema era uma trava, que poderia durar cinco minutos, durante os quais a fonte da trava girou basicamente em um ciclo de nove instruções.

É muito importante escolher bons títulos para minhas postagens, mas lembrei-me imediatamente de que o nome apropriado "48 núcleos são bloqueados por nove instruções" já foi usado [ tradução em Habré] por uma postagem escrita há menos de um mês. O número de processadores bloqueados é diferente e o ciclo é um pouco mais longo, mas, na verdade, tudo isso faz você experimentar o déjà vu. Portanto, enquanto explico o novo problema encontrado, queria refletir sobre por que isso acontece o tempo todo .

Por que isso está acontecendo?

Grosso modo, tais problemas surgem como resultado de uma observação que chamarei de Primeira Lei de Computação de Dawson: O (n ² ) é um ímã para algoritmos que não escalam bem : são rápidos o suficiente para entrar em produção, mas lentos o suficiente para estragar tudo, quando eles chegarem lá.


O (n ² ) em ação - dados extraídos do meu caso

O que está havendo? O desenvolvedor escreve o código e usa o algoritmo O (n ² ). Talvez ele não perceba isso, ou o algoritmo se torne O (n ² ) devido a um bug , ou o desenvolvedor sabe que ele é O (n ² ), mas ele acha que isso nunca será importante. Em condições de laboratório, a velocidade do código é aceitável e aceitável para a maioria dos usuários no mundo real, mas alguém cria 7.000 processos com o App Verifier ativado ou cria um arquivo binário com 180.000 elementos CFG ou coleta uma DLL tão grande que é constantemente uma lista vinculada única é examinada , o que leva todo o processador. Ao trabalhar no tempo de inicialização do mecanismo Valve Source 2, encontrei muitos algoritmos O (n ² ), cada um deles acrescentando cerca de 30 segundos ao tempo de inicialização do mecanismo, ou seja, esse problema ocorre com desenvolvedores muito diferentes.

O (n ² ) é um ímã para algoritmos que não escalam bem: eles são rápidos o suficiente para entrar em produção, mas lentos o suficiente para estragar tudo quando chegam lá.

Exatamente.

Por exemplo, a criação dos nomes dos arquivos de log do App Verifier é realizada em tempo linear para cada processo em execução, e isso é normal até você perceber que isso leva a O (n ² ) se muitos processos estiverem em execução. Às vezes, nem é óbvio que existem loops aninhados, ou que formalmente não é O (n ² ), ou não é óbvio que os loops podem correr por tanto tempo que podem afetar significativamente a velocidade ...

Portanto, considere esta oportunidade, pense ao escrever código, monitore como o desempenho é dimensionado sob cargas pesadas e examine seções suspeitas de código ao criar um perfil dessas cargas pesadas. Ou deixe comigo para que eu possa procurá-los e escrever artigos no meu blog.

Vamos voltar às nossas reclamações habituais

Como sempre, trabalhei na minha empresa trabalhando em minha estação de trabalho desatualizada, mas ainda poderosa, com 48 processadores lógicos e 96 GB de RAM. Eu introduzi o ninja chrome para criar o Chromium, mas ... nada aconteceu. Olhei e esperei vinte segundos, mas a montagem nunca começou. Então, é claro, mudei para o UIforETW para registrar o rastreamento ETW . Mais precisamente, tentei fazê-lo. Tentando iniciar a gravação de rastreamento, o UIforETW congela . Pela primeira vez no meu consultório, um bug usou medidas de proteção para me impedir de explorá-lo!

Após um ou dois minutos, a montagem do Chromium começou e o UIforETW iniciou o rastreamento, mas começou tarde demais e eu não tinha as menores informações sobre o que aconteceu.


Opções do UIforETW com rastreamento de buffer circular selecionado

Quando a mesma coisa aconteceu alguns dias depois, o UIforETW novamente não conseguiu fazer nada. Dessa vez, deixei o rastreamento para trabalhar em buffers de memória circular, para estar preparado para o fato de que o travamento ocorreria pela terceira vez. No entanto, isso reduziu bastante a velocidade das minhas ferramentas de construção, então, depois de algumas horas, desisti.

Então essa situação se repetiu novamente . Dessa vez, executei a ferramenta de registro de rastreamento ETW criada pela Microsoft - wprui e pude iniciar a gravação. Cerca de 40 segundos depois, a montagem começou a funcionar e eu tenho um rastro!

Posso iniciar a investigação agora?

Anteriormente, notei no "Gerenciador de tarefas" que o WinMgmt.exe estava sendo executado durante esses congelamentos . Observando os dados de Uso da CPU (Preciso) no WPA, eu estava convencido de que, após mais de quarenta segundos, durante os quais o WinMgmt.exe era quase o único processo de trabalho, minha máquina ganhou vida depois que o WinMgmt.exe foi desligado :


Aguardamos o despertar dos processos após a conclusão do WinMgmt.exe

Tudo isso é bastante suspeito, mas meus sábios leitores sabem que "depois" não significa "devido a" e exigirá prova.

Como na última vez , aproximei o momento de desbloqueio no gráfico, classificando as alternâncias de contexto por Hora da alternância e procurando a primeira alternância com um valor longo desde o último tempo (indicando o período de tempo durante o qual o encadeamento não foi executado). Tendo perdido uma dúzia de threads que eram apenas tempos de inatividade curtos, encontrei o primeiro de muitos que esperou 41,57 segundos. O encadeamento adormecido não ativou o WinMgmt.exe , mas rapidamente descobri que ele acordou com o encadeamento que despertou o WinMgmt.exe uma fração de milissegundo antes.

Para obter uma explicação dos gráficos de uso da CPU (preciso) e dos conceitos de thread de preparação / novo segmento, consulte este tutorial ou esta documentação .

Na captura de tela com os dados de troca de conteúdo, a linha 17 contém o fluxo 72.748 (WinMgmt.exe) , que ativa o fluxo 74.156 (svchost.exe). Em seguida, na linha 19, o segmento 74.156 (svchost.exe) ativa o segmento 58.704 (svchost.exe) , que estava aguardando 41.57 segundos. Este é o primeiro fio que acorda após um longo sono e a partir disso continua a cadeia de ativação dos fluxos. Os encadeamentos que acabaram de ser ativados podem ser vistos na coluna Novo ID do Encadeamento , depois desça algumas linhas e veja-os na coluna Id do Encadeamento de Leitura , ativando outro encadeamento. Os nomes e os IDs do processo ajudam a entender o contexto. A linha 17 está associada às linhas 18 e 19, a linha 19 está associada ao 20, que está associada à linha 23, que está associada à linha 27 e assim por diante; cada segmento é ativado pelo segmento anterior na cadeia:


O monstro desperta - longos fios ociosos ganham vida

41,57 é muito tempo para bloquear um encadeamento, mas, na realidade, centenas de encadeamentos foram bloqueados e bloqueados por muito mais tempo. O único motivo pelo qual o valor Tempo desde o último é de cerca de 41,5 segundos é porque a duração do rastreamento antes da interrupção foi resolvida.

Parece que os resultados são consistentes com a teoria de que o problema está no WinMgmt.exe , mas não o provam. Minha confiança aumentou quando olhei para svchost.exe (3024) em Trace-> System Configuration-> Services e descobri que é um serviço Winmgmt , mas ainda precisava de mais certeza.

Tendo vasculhado um pouco mais (vagando para frente e para trás no tempo), decidi que as interações são muito complicadas para analisá-las em detalhes, especialmente sem nomes de fluxos que possam sugerir o que 25 threads diferentes no svchost.exe (3024) estão fazendo.

Prova!

Decidi abordar a prova de culpa do WinMgmt.exe de maneira diferente. Talvez valesse a pena começar com isso, mas seria muito simples. Peguei a linha de comando WinMgmt.exe da tabela Processes no WPA e a iniciei manualmente. O comando tem o formato:

winmgmt.exe / Checkerrepository

e levou cerca de cinco minutos para ser concluído. Enquanto funcionava (e eu tinha muito tempo), descobri que não era possível iniciar o rastreamento ETW no UIforETW . Essa evidência era melhor do que qualquer análise intricada que eu pudesse fazer.


Configuração para exibir apenas threads inativos há muito tempo

Em seguida, executei a reprodução novamente com o rastreamento já em execução; Após analisar o rastreamento, descobri mais de cem processos cujos threads foram bloqueados por mais de cinco minutos!

E novamente ao ponto ...

Por hábito, olhei novamente para os dados de Uso da CPU (Amostrado) para ver em que WinMgmt.exe estava perdendo tempo. Eu rapidamente descobri que 96,5% das amostras estavam no repdrvfs.dll! CPageCache :: Read () , chamado em quatro pilhas diferentes:


Quatro caminhos que me levaram ao CPageCache :: Read

Uma árvore de pilhas completas para esta função é mostrada aqui, principalmente para pessoas da Microsoft que desejam pesquisar esse problema:


Pilhas completas que levam ao CPageCache :: Leia de três maneiras

Adicionei uma coluna de endereço e descobri que 95,3% das amostras estavam em um ciclo de nove instruções (as amostras sempre caíam em apenas sete das nove instruções (se você quiser saber o porquê, veja aqui ), mas o depurador mostrou o tamanho completo do ciclo) :


Amostras por endereço - sete endereços muito "quentes"

Em seguida, iniciei o winmgmt.exe / verifique o repositório manualmente e, ao mesmo tempo , coletei dados do contador da CPU sobre as instruções de ramificação que estavam sendo executadas . A partir disso, pude descobrir quantas vezes o loop foi executado. Provavelmente isso não era necessário, mas eu queria ter certeza de que o loop fosse executado muitas vezes e não fosse executado lentamente (por algum motivo). Eu pensei que era muito legal poder fazer isso simplesmente, basta fazer uma pequena alteração no arquivo em lotes. Descobri que o WinMgmt.exe executava aproximadamente uma instrução de ramificação por ciclo, ou seja, o ciclo (que, como eu já sabia, consumia a maior parte do tempo da CPU) era extremamente rápido e a desaceleração se devia ao fato de ele ter rodado centenas de milhões vezes.

Atraso do Xperf

Por uma questão de meticulosidade, decidi ver por que o UIforETW não pôde iniciar o rastreamento durante esse incidente. Aconteceu que o UIforETW estava executando o xperf , mas o xperf ficou inativo por 41,5 segundos (na verdade mais longo) nesta pilha de chamadas:

xperf.exe! wmain
xperf.exe! CStopTrace :: Execute
perfctrl.dll! LoggingSession :: EnumLoggers
perfctrl.dll! LoggingSession :: LoggingSession
perfctrl.dll! LoggingSession :: CreateProviderList
perfctrl.dll! GetProviderInfoCache
perfctrl.dll! CProviderInfoCache :: CProviderInfoCache
tdh.dll! TdhfEnumerateProviders
tdh.dll! TdhpWbemConnect
wbemprox.dll! CLocator :: ConnectServer
wbemprox.dll! CDCOMTrans :: DoActualConnection

Em resumo, o xperf é chamado pelo Wbem e, portanto, é bloqueado por esse problema. O xperf tenta interromper o rastreamento antes de iniciá-lo, porque adicionei esse comportamento para tornar o início do rastreamento mais tolerante a falhas . Suspeito que ainda ocorra um travamento, mas não tenho certeza.

Criamos gráficos de complexidade computacional

Percebi que o WinMgmt.exe verifica o diretório c: \ windows \ System32 \ wbem \ Repository , que é de 1,9 GB na minha máquina, então perguntei no trabalho e no Twitter para saber quanto esse diretório leva para obter pontos de dados. Também pedi às pessoas para corrigir o tempo de execução de winmgmt.exe / verifique o repositório e comecei a agendar. Embora esses testes tenham sido realizados em máquinas completamente diferentes com diferentes velocidades de CPU, o gráfico ficou bem claro:


A relação entre a raiz quadrada do tempo e o tamanho do repositório

Este gráfico da proporção entre sqrt (tempo) e tamanho do repositório é incrivelmente ideal para dados recebidos de seis máquinas diferentes e, no entanto, é real. Obviamente, a função VerifyRepository tem desempenho O (n ² ). Se n for o tamanho do diretório Repository em GB , o VerifyRepository levará cerca de 1,6 * n ² minutos. Essa é uma boa estimativa aproximada para todos os valores - de uma fração de segundo a dez minutos.

Relevância

Ou tenho sorte ou sou apenas observador, porque por algumas semanas ninguém mais encontrou esse problema - pensei que coisas estranhas estavam acontecendo com meu carro. Mas de repente comecei a ouvir queixas suspeitamente semelhantes de colegas. Um deles tinha um repositório de 2,6 GB, que levou dez minutos para verificar. O problema afetou alguns de nossos desenvolvedores de IC e, em graus diferentes, outras pessoas. Meus colegas geralmente sabem que, em caso de problemas com o desempenho de máquinas Windows, preciso dizer isso para mim, no entanto, provavelmente existem muitos outros funcionários do Google trabalhando no Windows que são impedidos por esse bug, mas eles não percebem isso.

Felizmente, eu já comecei a trabalhar com nosso departamento de TI. Encontrei o script que lançou o WinMgmt e descobri que ele é executado a cada hora. Isso significava que minha máquina estava executando o WinMgmt.exe / verifique o repositório 10% das vezes e alguns de meus colegas tinham mais de 16% das vezes. Há uma probabilidade bastante alta de obter um atraso de dez minutos antes da montagem.

Quando os relatórios começaram a chegar, a correção já estava a caminho da produção. O script era opcional e certamente não valeu os problemas que causou, portanto a correção foi desativar a chamada.

Sumário

O winmgmt.exe / verificarepository contém um ciclo de nove instruções, cujo número de iterações de execução é proporcional ao quadrado do tamanho do repositório wbem . Por esse motivo, a execução do comando pode levar até dez minutos, embora na realidade deva ser executada em apenas alguns segundos. Isso é ruim em si mesmo.

Pior ainda, a equipe executa um bloqueio WMI ( Windows Management Instrumentation ) durante sua operação; portanto, qualquer processo que execute operações WMI será congelado.

Enigmas incríveis

O script que executava o winmgmt.exe / verifique o repositório a cada hora fazia isso por muitos anos, mas o comportamento problemático começou a aparecer apenas de um a dois meses atrás. Presumivelmente, isso significa que o repositório wbem recentemente se tornou muito maior. Atrasos de 0,5 GB são facilmente ignorados, mas a partir de 1,0 GB e acima eles já podem ser pesados. Conforme sugerido no Twitter, executei strings.exe para o arquivo objects.data. Muitas das strings mais comuns contêm polmkr no nome, mas não sei o que isso significa.

Publiquei um relatório de bug no Twitter e, a princípio, causou algum movimento da equipe do WMI , mas depois parei de receber respostas, então não sei qual é a situação agora.

Gostaria de ver uma correção para o problema de desempenho e gostaria que nosso departamento de TI pudesse encontrar e corrigir o problema que torna nossos repositórios wbem tão grandes. Mas, por enquanto, o departamento de TI prometeu não executar o comando / Checkerrepository a cada hora a mais, o que deve nos ajudar a evitar os piores sintomas.

Referências

• Uma lista geral de tutoriais, investigações e documentação da ETW está disponível aqui: https://tinyurl.com/etwcentral
• O tutorial Uso da CPU (Amostrado) (para descobrir em que tempo da CPU é gasto) está aqui e a documentação está aqui.
• O tutorial Uso da CPU (Preciso) (para encontrar razões pelas quais os threads não podem ser executados) está aqui e a documentação está aqui.
• Os links para artigos individuais são fornecidos no corpo da postagem. Você também pode encontrá-los na minha categoria Investigar relatórios.
• Outras histórias sobre algoritmos de O (n ² ) podem ser lidas em Acidentalmente Quadrático

Uma discussão do artigo no Reddit está aqui , uma discussão sobre notícias de hackers está aqui , uma discussão no Twitter está aqui e , possivelmente, aqui