Пример 15. Измерение времени DPC/ISR
Вы можете измерять время, которое драйвер тратит на отложенные вызовы процедур (DPCs) и подпрограммы службы прерываний (ISR), отслеживая эти события в ядре Windows. Эти сведения помогут свести к минимуму время, которое драйвер тратит на более высокие irQLs, что делает драйвер и систему более эффективной.
Корпорация Майкрософт рекомендует, чтобы ЦП не выполнялись дольше 100 микросекунд, и isR не должны выполняться дольше 25 микросекунд. Последние требования см. в комплекте аппаратных лабораторий.
Процедура, описанная в этом разделе, включает следующие действия.
Запустите трассировку ядра событий DPC/ISR.
Отслеживайте сеанс трассировки для потерянных событий и при необходимости увеличьте размер буферов трассировки.
Упражнение тестового драйвера.
Остановите сеанс трассировки.
Используйте Tracerpt для создания отчета, в котором приводится сводка действий DPC/ISR.
Анализ отчетов
Шаг 1. Запуск сеанса трассировки.
Следующая команда запускает сеанс трассировки средства ведения журнала ядра NT:
tracelog -start -f test01.etl -dpcisr -UsePerfCounter -b 64
Команда tracelog -start запускает сеанс трассировки. Так как "NT Kernel Logger" является именем сеанса по умолчанию, его не нужно указывать, и для указания файла поставщика нельзя использовать параметр -guid . Команда использует параметр -f для указания сеанса журнала и направления сообщений трассировки в файл журнала трассировки событий test01.etl .
Эта команда включает параметр -dpcisr для включения трассировки ЦП, ISR, коммутаторов контекста и загрузки изображений.
При трассировке ЦП и ISR всегда добавьте параметр -UsePerfCounter в команду. Разрешение системного таймера слишком низко, чтобы оценить время, затраченное на эти действия. Кроме того, Tracerpt, средство, которое форматирует события DPC/ISR, требует значений счетчика производительности для своих отчетов. (Tracerpt включен в Windows XP и более поздних версиях Windows.)
Наконец, команда использует параметр -b для увеличения размера буферов трассировки до 64 КБ. Так как трассировка DPC/ISR создает большой объем сообщений трассировки с быстрой скоростью, важно увеличить размер буферов трассировки, чтобы не потерять события.
В ответ на эту команду Tracelog запускает сеанс ведения журнала ядра NT и отображает его свойства.
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
Обратите внимание, что события DPC, ISR и переключения контекста не отображаются в поле трассировки включено. Так как эти события отслеживаются внутренним инструментированием, они не отображаются в этом списке, даже если они включены. Однако события загрузки изображения, которые также включены параметром -dpcisr , отображаются.
Шаг 2. Проверка потерянных событий.
Периодически используйте команду tracelog -q (query), чтобы проверка для потерянных событий. Если их найти, используйте команду tracelog -update для добавления дополнительных буферов в сеанс трассировки.
tracelog -q
Команда tracelog -q принимает имя сеанса, но в этом случае не требуется указать его, так как по умолчанию используется средство ведения журнала ядра NT.
В ответ на эту команду Tracelog отображает свойства сеанса.
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
В этом случае 544 события, созданные не были сохранены в буфере. Чтобы предотвратить повторение, используйте команду tracelog -update, чтобы увеличить размер каждого буфера (-b) или увеличить максимальное количество буферов (-max), например:
tracelog -update -b 128 -max 40
Шаг 3. Упражнение драйвера.
Используйте процедуры тестирования, чтобы драйвер выполнял свои функции. Рассмотрите возможность выполнения двух тестов, один для базовых функций и один для более сложных функций.
Шаг 4. Остановка сеанса трассировки.
Чтобы остановить сеанс трассировки, используйте следующую команду:
tracelog -stop
Для команды tracelog -stop обычно требуется имя сеанса, но так как "NT Kernel Logger" используется по умолчанию, имя сеанса не требуется.
Шаг 5. Создание отчета DPC/ISR.
Чтобы суммировать сообщения DPC/ISR в журнале трассировки событий, используйте версию Tracerpt, включенную в Windows XP с пакетом обновления 2 (SP2) и более поздними версиями Windows.
Следующая команда Tracerpt форматирует сообщения в файле Test01.etl и создает текстовый отчет о действии в Windows XP с пакетом обновления 2 (SP2).
tracerpt test01.etl -report dpcisr.txt -df
В этой команде параметр -report задает метод анализа и имя выходного файла. Параметр -df необходим для правильного форматирования сообщений только в Windows XP с пакетом обновления 2 (SP2).
При создании этого отчета в Windows Server 2003 с пакетом обновления 1 (SP1) и более поздних версий Windows можно создать html-форматированный отчет с помощью следующей команды.
tracerpt test01.etl -report dpcisr.html -f HTML
В этой команде параметр -report указывает имя выходного файла, а параметр -f указывает формат отчета.
Шаг 6. Анализ отчета.
Отчет о сеансе трассировки событий Windows содержит следующие разделы:
Статистика изображений. Отображает данные о процессах, выполняемых на компьютере во время трассировки.
Итоговые значения дисков. Отображает данные о дисках ввода-вывода для каждого процесса, выполняемого во время трассировки.
Использование процессора DPC для всей трассировки: отображает процент времени, затраченного на обслуживание подпрограмм DPC для каждого драйвера.
Распределение всех времени выполнения DPC для всей трассировки. Таблица диапазонов времени в микросекундах. В таблице отображается процент подпрограмм DPC, которые попадают в каждый диапазон времени.
Распределение driverName (DPCRoutineAddress) — время выполнения DPC для всей трассировки. Таблица диапазонов времени в микросекундах. В таблице отображается процент экземпляров этой подпрограммы DPC, которые попадают в каждый диапазон времени. Этот раздел отображается для каждой подпрограммы DPC в трассировке.
Использование процессора ISR для всей трассировки. Отображает процент времени, затраченного на обслуживание подпрограмм службы прерываний для каждого драйвера трассировки.
Распределение всех времени выполнения ISR для всей трассировки. Таблица диапазонов времени в микросекундах. В таблице отображается процент подпрограмм ISR, которые попадают в каждый диапазон времени.
Распределение DriverName (ISRAddress) — время выполнения ISR для всей трассировки. Таблица диапазонов времени в микросекундах. В таблице отображается процент экземпляров ISR, которые попадают в каждый диапазон времени. Этот раздел отображается для каждого isR в трассировке.
Распределение использования процессора DPC и ISR для трассировкиPeriodInMs двух микросекунд времени. Отображает объединенную загрузку процессора для ЦП и ISR во время трассировки.
Распределение isRName (ISRAddress) isR to DriverName (DPCRoutineAddress) задержки DPC для всей трассировки. Отображает распределение интервалов задержки между концем ISR и началом связанного DPC.
Следующий фрагмент из примера отчета показывает распределение времени выполнения DPC для Ipsec.sys. Как правило, подпрограммы DPC, продолжаемые более 100 микросекунд, не рекомендуется. В отчете показано, что более половины подпрограмм DPC для этого драйвера превышают пороговое значение.
+------------------------------------------------------------------------------+
| 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% |
+------------------------------------------------------------------------------+