Contoh 15: Mengukur Waktu DPC/ISR
Anda dapat mengukur jumlah waktu yang dihabiskan driver dalam panggilan prosedur yang ditangguhkan (DPC) dan mengganggu rutinitas layanan (ISR) dengan melacak peristiwa ini di kernel Windows. Informasi ini akan membantu Anda meminimalkan waktu yang dihabiskan driver pada IRQL yang lebih tinggi, membuat driver dan sistem lebih efisien.
Microsoft menyarankan agar DPC tidak boleh berjalan lebih lama dari 100 mikrosetik dan ISR tidak boleh berjalan lebih dari 25 mikro detik. Untuk persyaratan terbaru, lihat Kit Lab Perangkat Keras.
Prosedur yang dijelaskan di bagian ini mencakup langkah-langkah berikut:
Mulai pelacakan kernel peristiwa DPC/ISR.
Pantau sesi pelacakan untuk peristiwa yang hilang dan, jika perlu, tingkatkan ukuran buffer jejak.
Latihan driver uji.
Hentikan sesi pelacakan.
Gunakan Tracerpt untuk membuat laporan yang meringkas aktivitas DPC/ISR.
Menganalisis laporan
Langkah 1: Mulai sesi pelacakan.
Perintah berikut memulai sesi pelacakan NT Kernel Logger:
tracelog -start -f test01.etl -dpcisr -UsePerfCounter -b 64
Perintah tracelog -start memulai sesi pelacakan. Karena "NT Kernel Logger" adalah nama sesi default, Anda tidak perlu menentukannya, dan Anda tidak dapat menggunakan parameter -guid untuk menentukan file penyedia. Perintah menggunakan parameter -f untuk menunjukkan sesi log dan untuk mengarahkan pesan pelacakan ke file log jejak peristiwa test01.etl .
Perintah ini mencakup parameter -dpcisr untuk mengaktifkan pelacakan DPC, ISR, sakelar konteks, dan pemuatan gambar.
Saat melacak DPC dan ISR, selalu tambahkan parameter -UsePerfCounter ke perintah . Resolusi timer sistem terlalu rendah untuk mengukur waktu yang dihabiskan dalam aktivitas ini. Selain itu, Tracerpt, alat yang memformat peristiwa DPC/ISR, memerlukan nilai jam penghitung kinerja untuk laporannya. (Tracerpt disertakan dalam Windows XP dan versi Windows yang lebih baru.)
Terakhir, perintah menggunakan parameter -b untuk meningkatkan ukuran buffer pelacakan menjadi 64 KB. Karena pelacakan DPC/ISR menghasilkan volume pesan pelacakan yang tinggi pada laju yang cepat, penting untuk meningkatkan ukuran buffer jejak sehingga Anda tidak kehilangan peristiwa.
Menanggapi perintah ini, Tracelog memulai sesi NT Kernel Logger dan menampilkan propertinya.
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
Perhatikan bahwa peristiwa DPC, ISR, dan pengalihan konteks tidak muncul di bidang Pelacakan yang diaktifkan dari tampilan. Karena peristiwa ini dipantau oleh instrumentasi internal, peristiwa tersebut tidak muncul dalam daftar ini bahkan ketika diaktifkan. Namun, peristiwa beban gambar, yang juga diaktifkan oleh parameter -dpcisr , memang muncul.
Langkah 2: Periksa peristiwa yang hilang.
Gunakan perintah tracelog -q (kueri) secara berkala untuk memeriksa peristiwa yang hilang. Jika Anda menemukannya, gunakan perintah tracelog -update untuk menambahkan lebih banyak buffer ke sesi pelacakan.
tracelog -q
Perintah tracelog -q mengambil nama sesi, tetapi tidak perlu menyediakannya dalam kasus ini karena "NT Kernel Logger" adalah default.
Sebagai respons terhadap perintah ini, Tracelog menampilkan properti sesi.
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
Dalam hal ini, 544 peristiwa yang dihasilkan tidak disimpan dalam buffer. Untuk mencegah hal ini berulang, gunakan perintah tracelog -update untuk meningkatkan ukuran setiap buffer (-b) atau untuk meningkatkan jumlah maksimum buffer (-maks), misalnya:
tracelog -update -b 128 -max 40
Langkah 3: Latihan driver.
Gunakan rutinitas pengujian Anda untuk membuat driver menjalankan fungsinya. Pertimbangkan untuk menjalankan dua pengujian, satu untuk fungsi dasar dan satu untuk fungsi yang lebih canggih.
Langkah 4: Hentikan sesi pelacakan.
Gunakan perintah berikut untuk menghentikan sesi pelacakan:
tracelog -stop
Perintah tracelog -stop biasanya memerlukan nama sesi, tetapi karena "NT Kernel Logger" adalah default, nama sesi tidak diperlukan.
Langkah 5: Buat laporan DPC/ISR.
Untuk meringkas pesan DPC/ISR dalam log pelacakan peristiwa, gunakan versi Tracerpt yang disertakan dalam Windows XP dengan SP2 dan versi Windows yang lebih baru.
Perintah Tracerpt berikut memformat pesan dalam file Test01.etl dan membuat laporan aktivitas berformat teks di Windows XP dengan SP2.
tracerpt test01.etl -report dpcisr.txt -df
Dalam perintah ini, parameter -report menentukan metode analisis dan nama file output. Parameter -df diperlukan untuk memformat pesan dengan benar hanya di Windows XP dengan SP2.
Saat membuat laporan ini di Windows Server 2003 dengan SP1 dan versi Windows yang lebih baru, Anda bisa membuat laporan berformat HTML dengan menggunakan perintah berikut.
tracerpt test01.etl -report dpcisr.html -f HTML
Dalam perintah ini, parameter -report menentukan nama file output dan parameter -f menentukan format laporan.
Langkah 6: Analisis laporan.
"Laporan Sesi Pelacakan Peristiwa Windows" memiliki bagian berikut:
Statistik Gambar. Menampilkan data tentang proses yang berjalan pada komputer selama pelacakan.
Total Disk. Menampilkan data tentang I/O disk untuk setiap proses yang berjalan selama pelacakan.
Pemanfaatan prosesor DPC untuk seluruh jejak: Menampilkan persentase waktu prosesor yang dihabiskan untuk melayani rutinitas DPC untuk setiap driver.
Distribusi semua waktu eksekusi DPC untuk seluruh jejak. Tabel rentang waktu dalam unit mikrodir. Tabel menampilkan persentase rutinitas DPC yang termasuk dalam setiap rentang waktu.
Distribusi DriverName ( DPCRoutineAddress ) Waktu eksekusi DPC untuk seluruh jejak. Tabel rentang waktu dalam unit mikrodir. Tabel menampilkan persentase instans rutin DPC ini yang termasuk dalam setiap rentang waktu. Bagian seperti ini muncul untuk setiap rutinitas DPC dalam jejak.
Pemanfaatan prosesor ISR untuk seluruh jejak. Menampilkan persentase waktu prosesor yang dihabiskan untuk melayani rutinitas layanan interupsi untuk setiap driver dalam pelacakan.
Distribusi semua waktu eksekusi ISR untuk seluruh jejak. Tabel rentang waktu dalam unit mikrodir. Tabel menampilkan persentase rutinitas ISR yang termasuk dalam setiap rentang waktu.
Distribusi Waktu eksekusi ISR DriverName ( ISRAddress ) untuk seluruh jejak. Tabel rentang waktu dalam unit mikrodir. Tabel menampilkan persentase instans ISR yang termasuk dalam setiap rentang waktu. Bagian seperti ini muncul untuk setiap ISR dalam pelacakan.
Distribusi pemanfaatan prosesor DPC dan ISR untuk TracingPeriodInMs dua jendela waktu microsecond. Menampilkan pemanfaatan prosesor gabungan oleh DPC dan ISR selama pelacakan.
Distribusi DriverName ( ISRAddress ) ISR ke DriverName ( DPCRoutineAddress ) Latensi DPC untuk seluruh jejak. Menampilkan distribusi interval penundaan antara akhir ISR dan awal DPC terkait.
Kutipan berikut dari laporan sampel menunjukkan distribusi waktu eksekusi DPC untuk Ipsec.sys. Secara umum, rutinitas DPC yang berlangsung lebih dari 100 mikro detik tidak disarankan. Laporan menunjukkan bahwa lebih dari setengah rutinitas DPC untuk driver ini melebihi ambang batas.
+------------------------------------------------------------------------------+
| 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% |
+------------------------------------------------------------------------------+