“O Explorer gasta 700 ms para abrir o menu de contexto da barra de tarefas. 75% desse tempo, ele realiza 114.801 operações de leitura de um arquivo, a quantidade média de dados de leitura é de 68 bytes.
Devo escrever um post sobre isso ou um tweet bastante sarcástico? ”Trabalho rapidamente em um computador e, portanto, me incomoda quando tenho que esperar pela conclusão de uma operação que deve ser executada instantaneamente. Um obstáculo constante no meu laptop doméstico pesado foi o lento fechamento das janelas na barra de tarefas. Clique com o botão direito do mouse no ícone, aguarde o menu abrir e, em seguida, selecione "Fechar janela". O mais lento nesse processo deve ser o movimento do mouse, mas o componente mais longo é o atraso antes que o menu seja exibido.
Isso me incomodou por um longo tempo, mas eu demonstrei autocontrole incomum e me mantive irritada. Isso foi até hoje, quando eu finalmente quebrei e agarrei o marcador
ETW .
Este post foi escrito como uma verificação de velocidade dos blogs. Cerca de 90 minutos se passaram desde o momento em que o problema foi encontrado e o tweet sarcástico até a publicação do post.
O rastreador ETW corrigiu como eu clico com o botão direito na barra de tarefas e fecho as duas janelas do Explorer. Usei o
rastreamento de UIforETW para arquivar a função com opções padrão, resultando em um
log de diagnóstico de 20,9 MB .
Às vezes, a parte mais difícil na análise de um rastreamento é encontrar a localização do problema, mas, nesse caso, essa parte da análise é trivial. Havia três sinais inequívocos indicando o lugar certo e o culpado dolorosamente óbvio do crime.
O primeiro sinal foram os eventos de entrada. O UIforETW contém um
logger de entrada integrado (suficientemente anonimizado para que eu não roube senhas ou informações pessoais acidentalmente), então eu apenas tive que estudar os eventos
MouseUp e
Button Type em detalhes com um valor 2 correspondente ao botão direito do mouse. Ao mesmo tempo, as marcas na linha do tempo
WPA aparecem quando esses eventos ocorrem - veja as linhas verticais na captura de tela:
Isso deixou claro para mim que, quando solto o botão direito do mouse, após 600 ms, o foco da janela muda, o que, na minha opinião, corresponde ao momento em que o menu é exibido. Além disso, o RuntimeBroker.exe possui um bloco claro de atividade da CPU entre os eventos de liberação do botão do mouse e alteração do foco da janela.
Não foi provado que a alteração no foco da janela e na atividade da CPU esteja relacionada, mas depois de fazer medições usando o aplicativo de gravação de tela, vi que são necessários cerca de 660 ms para exibir o menu, por isso, confio nisso.
O próximo passo é aprender o que o RuntimeBroker.exe está fazendo. Embora
o Uso da CPU (Preciso) ajude você a ver quanto tempo de CPU o processo usa e por que ele está ocioso, a
tabela Uso da
CPU (Amostrada) é uma boa ferramenta para descobrir em que tempo de CPU é gasto. Estudei-o cuidadosamente e descobri rapidamente que 264 amostras eram do
KernelBase.dll!Depois de pesquisar um pouco mais, encontrei outras pilhas de chamadas que também afetavam essa função.
Cliquei com o botão direito do mouse e selecionei
Ver chamadores-> Por função . O modo ativado (com pilhas invertidas) mostrou que de 899 amostras desse processo, 628 amostras ou 70% de pilhas de chamadas diferentes passaram por esta função:
271 amostras neste fluxo não passaram pela função e as amostras restantes (não mostradas) estavam em outros fluxos.
Observe que 899 amostras em um fluxo de 10252 representam dois cliques do mouse, isto é, aproximadamente 450 amostras ou 450 ms (com uma frequência de amostragem padrão de 1 kHz) por clique do mouse.
Às vezes, a E / S do arquivo é o tempo da CPU
O uso da CPU (amostrado) mostra o tempo da
CPU ; portanto, a E / S do disco geralmente não é exibida aqui, porque nesses momentos o fluxo adormece e aguarda o disco. O fato de as operações de E / S serem exibidas como tempo da CPU significa que todas as leituras caíram no cache do sistema e o tempo da CPU foi um recurso extra do kernel (consulte
ntoskrnl.exe na primeira pilha de chamadas de amostra) gasto na obtenção de dados do cache.
Agora que a
E / S de arquivo ficou sob suspeita, precisamos ir para o
Graph Explorer-> Armazenamento-> Arquivo de E / S. Depois de ajustar ligeiramente a aparência das colunas, obtivemos o seguinte resultado impressionante:
, 10 252
RuntimeBroker.exe 229 604
ReadFile, 15 686 586 . 68 .
.
, — . ,
RuntimeBroker.exe . 4 027 904 , , , 1,9 .
, . , ( ):
%appdata%\Microsoft\Windows\Recent\AutomaticDestinations\f01b4d95cf55d32a.automaticDestinations-msWPA. — , . :
« „“, ( ) ( ) „“/ . , ».
, !
, . , , , .
- ReadFile, 68 . , , . , 4 , .
- , - , — .
- , - , . , ETW !
- https://aka.ms/AA60dfg
- , UIforETW ,
- , ( , ), shift+ . , .
- Hacker news
- Reddit
- Twitter