Exemplo 15: Medindo o tempo DPC/ISR
Você pode medir a quantidade de tempo que um driver gasta em chamadas de procedimento adiadas (DPCs) e rotinas de serviço de interrupção (ISRs) rastreando esses eventos no kernel do Windows. Essas informações ajudarão você a minimizar o tempo que o driver gasta em IRQLs mais altos, tornando o driver e o sistema mais eficientes.
A Microsoft recomenda que os DPCs não sejam executados por mais de 100 microssegundos, e os ISRs não devem ser executados por mais de 25 microssegundos. Para obter os requisitos mais recentes, consulte o Kit de Laboratório de Hardware.
O procedimento descrito nesta seção inclui as seguintes etapas:
Inicie o rastreamento do kernel de eventos DPC/ISR.
Monitore a sessão de rastreamento em busca de eventos perdidos e, se necessário, aumente o tamanho dos buffers de rastreamento.
Execute o driver de teste.
Interrompa a sessão de rastreamento.
Use o Tracerpt para gerar um relatório que resuma a atividade do DPC/ISR.
Analisar os relatórios
Etapa 1: Inicie uma sessão de rastreamento.
O comando a seguir inicia uma sessão de rastreamento do NT Kernel Logger:
tracelog -start -f test01.etl -dpcisr -UsePerfCounter -b 64
O comando tracelog -start inicia a sessão de rastreamento. Como "NT Kernel Logger" é o nome de sessão padrão, não é necessário especificá-lo e usar o parâmetro -guid para especificar um arquivo de provedor. O comando usa o parâmetro -f para indicar uma sessão de log e direcionar as mensagens de rastreamento para o arquivo de log de rastreamento de evento test01.etl.
O comando inclui o parâmetro -dpcisr para ativar o rastreamento de DPCs, ISRs, alternâncias de contexto e carregamento de imagens.
Ao rastrear DPCs e ISRs, sempre adicione o parâmetro -UsePerfCounter ao comando. A resolução do temporizador do sistema é muito baixa para medir o tempo gasto nessas atividades. Além disso, o Tracerpt, a ferramenta que formata eventos DPC/ISR, requer os valores de clock do contador de desempenho para seus relatórios. (O Tracerpt está incluído no Windows XP e em versões posteriores do Windows.)
Por fim, o comando usa o parâmetro -b para aumentar o tamanho dos buffers de rastreamento para 64 KB. Como o rastreamento de DPC/ISR gera um alto volume de mensagens de rastreamento em uma taxa rápida, é importante aumentar o tamanho dos buffers de rastreamento para que você não perca eventos.
Em resposta a esse comando, o Tracelog inicia a sessão do NT Kernel Logger e exibe suas propriedades.
Logger Started...
Operation Status: 0L The operation completed successfully.
Logger Name: NT Kernel Logger
Logger Id: ffff
Logger Thread Id: 00000C18
Buffer Size: 64 Kb
Maximum Buffers: 25
Minimum Buffers: 3
Number of Buffers: 5
Free Buffers: 4
Buffers Written: 14
Events Lost: 0
Log Buffers Lost: 0
Real Time Buffers Lost: 0
AgeLimit: 15
Log File Mode: Sequential
Enabled tracing: Process Thread Disk File ImageLoad
Log Filename: c:\Tracelog\test01.etl
Observe que os eventos de DPC, ISR e alternância de contexto não são exibidos no campo Rastreamento ativado da tela. Como esses eventos são monitorados por instrumentação interna, eles não são exibidos na lista mesmo quando estão habilitados. No entanto, os eventos de carregamento de imagem, que também são habilitados pelo parâmetro -dpcisr, são exibidos.
Etapa 2: Verifique se há eventos perdidos.
Use um comando tracelog -q (consulta) periodicamente para verificar se há eventos perdidos. Se forem encontrados, use um comando tracelog -update para adicionar mais buffers à sessão de rastreamento.
tracelog -q
O comando tracelog -q pega um nome de sessão, mas não é necessário fornecer um nesse caso, pois "NT Kernel Logger" é o padrão.
Em resposta a esse comando, o Tracelog exibe as propriedades da sessão.
Operation Status: 0L The operation completed successfully.
Logger Name: NT Kernel Logger
Logger Id: ffff
Logger Thread Id: 00000BC4
Buffer Size: 64 Kb
Maximum Buffers: 25
Minimum Buffers: 3
Number of Buffers: 25
Free Buffers: 23
Buffers Written: 571
Events Lost: 544
Log Buffers Lost: 0
Real Time Buffers Lost: 0
AgeLimit: 15
Log File Mode: Sequential
Enabled tracing: Process Thread Disk File ImageLoad
Log Filename: c:\Tracelog\test.etl
Nesse caso, 544 eventos gerados não foram salvos em um buffer. Para evitar a recorrência, use um comando tracelog -update para aumentar o tamanho de cada buffer (-b) ou para aumentar o número máximo de buffers (-max), por exemplo:
tracelog -update -b 128 -max 40
Etapa 3: Execute o driver.
Use suas rotinas de teste para fazer o driver executar suas funções. Considere executar dois testes, um para funções básicas e outro para funções mais avançadas.
Etapa 4: Interrompa a sessão de rastreamento.
Use o seguinte comando para interromper a sessão de rastreamento:
tracelog -stop
Um comando tracelog -stop geralmente requer um nome de sessão, mas como "NT Kernel Logger" é o padrão, o nome de sessão não será necessário.
Etapa 5: Crie um relatório DPC/ISR.
Para resumir as mensagens DPC/ISR no log de rastreamento de eventos, use a versão do Tracerpt incluída no Windows XP com SP2 e versões posteriores do Windows.
O comando Tracerpt formata as mensagens no arquivo Test01.etl e cria um relatório formatado por texto da atividade no Windows XP com SP2.
tracerpt test01.etl -report dpcisr.txt -df
No comando, o parâmetro -report especifica o método de análise e o nome do arquivo de saída. O parâmetro -df é necessário para formatar as mensagens corretamente somente no Windows XP com SP2.
Ao criar esse relatório no Windows Server 2003 com SP1 e versões posteriores do Windows, você poderá criar um relatório formatado em HTML usando o comando a seguir.
tracerpt test01.etl -report dpcisr.html -f HTML
No comando, o parâmetro -report especifica o nome do arquivo de saída, e o parâmetro -f, o formato do relatório.
Etapa 6: Analise o relatório.
O "Relatório de sessão de rastreamento de eventos do Windows" tem as seguintes seções:
Estatísticas de Imagem. Exibe dados sobre os processos em execução no computador durante o rastreamento.
Totais de Disco. Exibe dados sobre E/S de disco para cada processo em execução durante o rastreamento.
Utilização do processador de DPC para todo o rastreamento: Exibe a porcentagem de tempo de processador na manutenção das rotinas de DPC de cada driver.
Distribuição de todos os tempos de execução do DPC para todo o rastreamento. Uma tabela de intervalos de tempo em unidades de microssegundos. A tabela exibe a porcentagem de rotinas DPC que se enquadram em cada intervalo de tempo.
Distribuição de tempos de execução de DPC (DPCRoutineAddress) do DriverName para todo o rastreamento. Uma tabela de intervalos de tempo em unidades de microssegundos. A tabela exibe a porcentagem de instâncias dessa rotina de DPC que se enquadram em cada intervalo de tempo. Uma seção como esta aparece para cada rotina de DPC no rastreamento.
Utilização do processador de ISR para todo o rastreamento. Exibe a porcentagem de tempo do processador gasto na manutenção das rotinas de serviço de interrupção para cada driver no rastreamento.
Distribuição de todos os tempos de execução do ISR para todo o rastreamento. Uma tabela de intervalos de tempo em unidades de microssegundos. A tabela exibe a porcentagem de rotinas ISR que se enquadram em cada intervalo de tempo.
Distribuição de tempos de execução de ISR (ISRAddress) do DriverName para todo o rastreamento. Uma tabela de intervalos de tempo em unidades de microssegundos. A tabela exibe a porcentagem de instâncias de ISR que se enquadram em cada intervalo de tempo. Uma seção como esta aparece para cada ISR no rastreamento.
Distribuição da utilização do processador DPC e ISR para janelas de tempo de dois microssegundos de TracingPeriodInMs. Exibe a utilização combinada do processador por DPCs e ISRs durante o rastreamento.
Distribuição de latência de DriverName (ISRAddress) ISR para DriverName (DPCRoutineAddress) DPC para todo o rastreamento. Exibe a distribuição dos intervalos de atraso entre o final de um ISR e o início do DPC associado.
O trecho a seguir de um relatório de exemplo mostra a distribuição dos tempos de execução do DPC para Ipsec.sys. Em geral, as rotinas de DPC com duração superior a 100 microssegundos são desencorajadas. O relatório mostra que mais da metade das rotinas de DPC para esse driver excedem o limite.
+------------------------------------------------------------------------------+
| Distribution of ipsec.sys (F7AA7449) DPC execution times for the whole trace |
+------------------------------------------------------------------------------+
| Lower Bound Upper Bound Count Percent |
+------------------------------------------------------------------------------+
| 0 1 0 0.00% |
| 1 2 0 0.00% |
| 2 3 8 42.11% |
| 3 4 1 5.26% |
| 4 5 0 0.00% |
| 5 10 0 0.00% |
| 10 25 0 0.00% |
| 25 50 0 0.00% |
| 50 100 0 0.00% |
| 100 250 10 52.63% |
+------------------------------------------------------------------------------+
| 19 100.00% |
+------------------------------------------------------------------------------+
Comentários
Brevemente: Ao longo de 2024, vamos descontinuar progressivamente o GitHub Issues como mecanismo de feedback para conteúdos e substituí-lo por um novo sistema de feedback. Para obter mais informações, veja: https://aka.ms/ContentUserFeedback.
Submeter e ver comentários