“Explorer menghabiskan 700 ms untuk membuka menu konteks pada taskbar. 75% dari waktu ini, ia melakukan operasi baca 114.801 dari satu file, jumlah rata-rata data yang dibaca adalah 68 byte.
Haruskah saya menulis posting tentang ini, atau tweet yang agak sarkastik? "Saya bekerja dengan cepat di komputer, dan karena itu mengganggu saya ketika saya harus menunggu selesainya operasi yang harus dilakukan secara instan. Rintangan terus-menerus pada laptop tugas berat saya di rumah adalah penutupan windows yang lambat pada taskbar. Saya klik kanan pada ikon, tunggu menu untuk membuka, dan kemudian pilih "Tutup Jendela". Yang paling lambat dalam proses ini adalah gerakan mouse, tetapi ternyata komponen terpanjang adalah penundaan sebelum menu muncul.
Ini mengganggu saya untuk waktu yang lama, tetapi saya menunjukkan kontrol diri yang tidak seperti biasanya dan menjaga diri saya dari iritasi. Itu sampai hari ini, ketika saya akhirnya mematahkan dan meraih pelacak
ETW .
Posting ini ditulis sebagai cek untuk blogging cepat. Sekitar 90 menit berlalu dari saat masalah ditemukan dan tweet sarkastik tentang hal itu sampai posting diterbitkan.
Pelacak ETW memperbaiki cara saya mengklik kanan pada taskbar dan menutup dua jendela Explorer. Saya menggunakan
UIforETW Tracing untuk fungsi
file dengan opsi default, menghasilkan
log diagnostik 20,9 MB .
Terkadang bagian yang paling sulit dalam menganalisis jejak adalah menemukan lokasi masalahnya, tetapi dalam kasus ini bagian analisisnya sepele. Ada tiga tanda yang jelas yang menunjukkan tempat yang tepat, dan penyebab kejahatan yang sangat menyakitkan.
Sinyal pertama adalah peristiwa input. UIforETW berisi
input logger terintegrasi (cukup anonim sehingga saya tidak sengaja mencuri kata sandi atau informasi pribadi), jadi saya hanya perlu mempelajari peristiwa
MouseUp dan
Button Type secara terperinci dengan nilai 2 sesuai dengan tombol kanan mouse. Pada saat yang sama, tanda pada garis waktu
WPA muncul ketika peristiwa ini terjadi - lihat garis vertikal pada tangkapan layar:
Ini menjelaskan kepada saya bahwa ketika saya melepaskan tombol mouse kanan, maka setelah 600 ms perubahan jendela berubah, yang, menurut pendapat saya, sesuai dengan saat menu ditampilkan. Selain itu, RuntimeBroker.exe memiliki blok yang jelas dari aktivitas CPU antara peristiwa melepaskan tombol mouse dan mengubah fokus jendela.
Belum terbukti bahwa perubahan fokus jendela dan aktivitas CPU saling terkait, tetapi setelah melakukan pengukuran menggunakan aplikasi perekaman layar, saya melihat bahwa dibutuhkan sekitar 660 ms untuk menampilkan menu, jadi saya cenderung mempercayai ini.
Langkah selanjutnya adalah mempelajari apa yang dilakukan RuntimeBroker.exe. Meskipun
Penggunaan CPU (Tepat) membantu Anda untuk melihat berapa banyak waktu CPU menggunakan proses dan mengapa itu menganggur,
tabel Penggunaan CPU (Sampel) adalah alat yang baik untuk mengetahui berapa waktu CPU dihabiskan. Saya hati-hati mempelajarinya dan dengan cepat menemukan bahwa 264 sampel berasal dari
KernelBase.dll! ReadFile :
Setelah mencari sedikit lebih banyak, saya menemukan tumpukan panggilan lain yang juga mempengaruhi fungsi ini, jadi saya klik kanan dan pilih
View Callers-> By Function . Mode yang dihidupkan (dengan tumpukan terbalik) menunjukkan bahwa dari 899 sampel proses ini, 628 sampel, atau 70%, dari tumpukan panggilan berbeda melewati fungsi ini:
271 sampel dalam aliran ini tidak melewati fungsi, dan sampel yang tersisa (tidak ditampilkan) berada di aliran lain.
Perhatikan bahwa 899 sampel dalam aliran 10 252 mewakili dua klik mouse, yaitu sekitar 450 sampel atau 450 ms (pada frekuensi sampling standar 1 kHz) per klik mouse.
Terkadang file I / O adalah waktu CPU
Penggunaan CPU (Sampel) menunjukkan waktu
CPU , jadi disk I / O biasanya tidak ditampilkan di sini, karena pada saat ini aliran tertidur dan menunggu disk. Fakta bahwa operasi I / O ditampilkan sebagai waktu CPU berarti bahwa semua pembacaan jatuh pada cache sistem dan waktu CPU adalah sumber daya kernel tambahan (lihat
ntoskrnl.exe dalam tumpukan panggilan sampel pertama) yang dihabiskan untuk mendapatkan data dari cache.
Sekarang
file I / O telah dicurigai, kita harus pergi ke
Graph Explorer-> Storage-> File I / O. Setelah sedikit menyesuaikan tampilan kolom, kami mendapat hasil mengesankan berikut:
, 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