Bagaimana waktu linear berubah menjadi Windows dalam O (n²)

Saya baru-baru ini mengalami penundaan multi-menit di workstation saya. Setelah penyelidikan, ternyata penyebab masalahnya adalah kunci, yang bisa bertahan selama lima menit, di mana sumber kunci pada dasarnya berputar dalam siklus sembilan instruksi.

Sangat penting bagi saya untuk memilih judul yang baik untuk posting saya, tetapi saya segera ingat bahwa nama yang tepat "48 core diblokir oleh sembilan instruksi" sudah diambil [ terjemahan di Habré] oleh sebuah pos yang ditulis kurang dari sebulan yang lalu. Jumlah prosesor yang diblokir berbeda, dan siklusnya sedikit lebih lama, tetapi pada kenyataannya, semua ini membuat Anda mengalami deja vu. Karena itu, ketika saya menjelaskan masalah baru yang ditemukan, saya ingin merenungkan mengapa ini terjadi setiap saat .

Mengapa ini terjadi?

Secara kasar, masalah seperti itu muncul sebagai hasil dari pengamatan yang saya sebut Hukum Pertama Dawson tentang Komputasi: O (n ² ) adalah magnet bagi algoritma yang tidak skala dengan baik : mereka cukup cepat untuk masuk ke produksi, tetapi cukup lambat untuk merusak semuanya, ketika mereka sampai di sana.


O (n ² ) dalam aksi - data diambil dari kasus saya

Apa yang sedang terjadi Pengembang menulis kode dan menggunakan algoritma O (n ² ). Mungkin dia tidak menyadari hal ini, atau algoritme menjadi O (n ² ) karena bug , atau pengembang tahu bahwa dia adalah O (n ² ), tetapi dia berpikir bahwa itu tidak akan pernah penting. Dalam kondisi laboratorium, kecepatan kode dapat diterima, dan itu dapat diterima untuk sebagian besar pengguna di dunia nyata, tetapi kemudian seseorang membuat 7.000 proses dengan App Verifier dihidupkan atau membuat file biner dengan 180.000 elemen CFG , atau mengumpulkan DLL besar sehingga terus - menerus daftar tautan tunggal dipindai , yang mengambil seluruh prosesor. Ketika bekerja pada waktu peluncuran mesin Valve Source 2, saya menemukan banyak algoritma O (n ² ), yang masing-masing menambahkan sekitar 30 detik pada waktu peluncuran mesin, yaitu masalah ini terjadi pada pengembang yang sangat berbeda.

O (n ² ) adalah magnet untuk algoritma yang tidak skala dengan baik: mereka cukup cepat untuk masuk ke produksi, tetapi cukup lambat untuk merusak semuanya ketika mereka sampai di sana.

Tepat

Misalnya, pembuatan nama file log Verifier Aplikasi dilakukan dalam waktu linier untuk setiap proses yang berjalan, dan ini normal sampai Anda menyadari bahwa ini mengarah ke O (n ² ) jika banyak proses sedang berjalan. Kadang-kadang bahkan tidak jelas bahwa ada loop bersarang, atau yang secara resmi bukan O (n ² ), atau tidak jelas bahwa loop dapat berjalan begitu lama sehingga secara signifikan dapat mempengaruhi kecepatan ...

Jadi pertimbangkan fitur ini, pikirkan ketika menulis kode, pantau bagaimana skala kinerja di bawah beban berat, dan periksa bagian kode yang mencurigakan saat membuat profil beban berat seperti itu. Atau serahkan pada saya sehingga saya bisa mencari mereka dan menulis artikel di blog saya.

Mari kita kembali ke keluhan kita yang biasa

Seperti biasa, saya menjalankan bisnis saya dengan komputer saya yang sudah usang tetapi masih kuat dengan 48 prosesor logis dan RAM 96 GB. Saya memperkenalkan ninja chrome untuk membangun Chromium, tapi ... tidak ada yang terjadi. Saya melihat dan menunggu dua puluh detik, tetapi pertemuan itu tidak pernah dimulai. Jadi saya, tentu saja, beralih ke UIforETW untuk merekam jejak ETW . Lebih tepatnya, saya mencoba melakukannya. Mencoba memulai pelacakan rekaman, UIforETW membeku . Untuk pertama kalinya dalam latihan saya, bug menggunakan langkah-langkah perlindungan untuk mencegah saya menjelajahinya!

Setelah satu atau dua menit, perakitan Chromium dimulai, dan UIforETW memulai pelacakan, tetapi sudah mulai terlambat dan saya tidak memiliki sedikit pun informasi tentang apa yang terjadi.


Opsi UIforETW dengan Pelacakan Penyangga Sirkular terpilih

Ketika hal yang sama terjadi beberapa hari kemudian, UIforETW kembali tidak dapat melakukan apapun. Kali ini, saya meninggalkan jejak untuk bekerja di buffer memori melingkar, untuk bersiap-siap karena fakta bahwa hang akan terjadi untuk ketiga kalinya. Namun, ini sangat mengurangi kecepatan alat bangun saya, jadi setelah beberapa jam saya menyerah.

Kemudian situasi ini terulang lagi . Kali ini saya menjalankan alat pencatat jejak ETW yang dibuat oleh Microsoft - wprui , dan saya dapat mulai merekam. Sekitar 40 detik kemudian, perakitan mulai bekerja dan saya mendapat jejak!

Bisakah saya memulai penyelidikan sekarang?

Sebelumnya, saya perhatikan di "Task Manager" bahwa WinMgmt.exe dijalankan selama pembekuan ini. Melihat data Penggunaan CPU (Precise) di WPA, saya yakin bahwa setelah lebih dari empat puluh detik, selama WinMgmt.exe adalah satu-satunya proses yang bekerja, mesin saya menjadi hidup setelah WinMgmt.exe dimatikan :


Kami menunggu kebangkitan proses setelah WinMgmt.exe selesai

Semua ini agak mencurigakan, tetapi pembaca bijak saya tahu bahwa "setelah" tidak berarti "karena", dan akan membutuhkan bukti.

Seperti yang terakhir kali , saya memperkirakan saat membuka kunci pada grafik, menyortir sakelar konteks oleh Switch-In Time dan mencari sakelar pertama dengan nilai Time Sejak Terakhir yang lama (menunjukkan lamanya waktu selama thread tidak dieksekusi). Setelah melewatkan selusin utas yang hanya downtime pendek, saya menemukan yang pertama dari banyak yang menunggu 41,57 detik. Thread yang tertidur tidak membangunkan WinMgmt.exe , tetapi saya segera mengetahui bahwa itu terbangun dengan thread yang membangunkan WinMgmt.exe sepersekian milidetik sebelumnya.

Untuk penjelasan tentang grafik Penggunaan CPU (Precise) dan konsep ready-thread / new-thread, lihat tutorial ini atau dokumentasi ini .

Di tangkapan layar dengan data pemindahan konten, baris 17 berisi stream 72.748 (WinMgmt.exe) , yang mengaktifkan streaming 74.156 (svchost.exe). Selanjutnya, pada baris 19, utas 74.156 (svchost.exe) mengaktifkan utas 58.704 (svchost.exe) , yang sedang menunggu 41,57 detik. Ini adalah utas pertama yang bangun setelah tidur panjang dan dari sini terus rantai aktivasi arus. Utas yang baru saja diaktifkan dapat dilihat di kolom Id Utas Baru , lalu turun beberapa baris dan melihatnya di kolom Readying Thread Id , mengaktifkan utas lainnya. Nama dan ID proses membantu Anda memahami konteksnya. Jalur 17 dikaitkan dengan jalur 18 dan 19, jalur 19 dikaitkan dengan 20, yang dikaitkan dengan jalur 23, yang dikaitkan dengan jalur 27, dan seterusnya; setiap utas diaktifkan oleh utas sebelumnya di rantai:


Monster itu terbangun - utas panjang yang menganggur hidup kembali

41.57 adalah waktu yang lama untuk memblokir utas, tetapi dalam kenyataannya ratusan utas diblokir, dan mereka diblokir lebih lama. Satu-satunya alasan nilai Time Sejak Terakhir adalah sekitar 41,5 detik adalah karena lamanya jejak sebelum hang diselesaikan.

Tampaknya hasilnya konsisten dengan teori bahwa masalahnya ada di WinMgmt.exe , tetapi mereka tidak membuktikannya. Keyakinan saya meningkat ketika saya melihat svchost.exe (3024) di Trace-> System Configuration-> Services dan menemukan bahwa itu adalah layanan Winmgmt , tetapi saya masih membutuhkan lebih banyak kepastian.

Setelah mencari-cari lebih banyak (berkeliaran maju dan mundur dalam waktu), saya memutuskan bahwa interaksi terlalu rumit untuk menganalisis mereka secara rinci, terutama tanpa nama aliran yang bisa memberi petunjuk kepada kami apa yang dilakukan 25 thread berbeda di svchost.exe (3024) .

Bukti!

Kemudian saya memutuskan untuk mendekati WinMgmt.exe bukti bersalah secara berbeda. Mungkin itu layak dimulai dengan ini, tetapi itu akan terlalu sederhana. Saya mengambil baris perintah WinMgmt.exe dari tabel Processes di WPA dan memulainya secara manual. Perintah memiliki bentuk:

winmgmt.exe / verifikasi repositori

dan butuh sekitar lima menit untuk menyelesaikannya. Sementara itu berhasil (dan saya punya banyak waktu), saya menemukan bahwa saya tidak dapat memulai jejak ETW dari UIforETW . Bukti seperti itu lebih baik daripada analisis rumit yang bisa saya lakukan.


Konfigurasi untuk menampilkan hanya utas yang lama tidak aktif

Lalu aku berlari repro lagi dengan jejak sudah berjalan; Setelah menganalisis jejak, saya menemukan lebih dari seratus proses yang utasnya diblokir selama lebih dari lima menit!

Dan lagi ke titik ...

Karena kebiasaan, saya melihat kembali data Penggunaan CPU (Sampel) untuk melihat apa yang membuang waktu WinMgmt.exe . Saya segera mengetahui bahwa 96,5% sampel berada di repdrvfs.dll! CPageCache :: Read () , meminta empat tumpukan berbeda:


Empat jalur yang mengarahkan saya ke CPageCache :: Read

Pohon tumpukan penuh untuk fungsi ini ditampilkan di sini, terutama untuk orang-orang dari Microsoft yang ingin meneliti masalah ini:


Tumpukan penuh yang mengarah ke CPageCache :: Baca dalam tiga cara

Saya menambahkan kolom alamat dan menemukan bahwa 95,3% dari sampel berada dalam satu siklus dari sembilan instruksi (sampel selalu jatuh hanya tujuh dari sembilan instruksi (jika Anda ingin tahu mengapa, lihat di sini ), tetapi debugger menunjukkan ukuran penuh siklus) :


Sampel berdasarkan alamat - tujuh alamat yang sangat "panas"

Kemudian saya mulai winmgmt.exe / verifikasi repositori secara manual, dan pada saat yang sama saya mengumpulkan data penghitung CPU tentang instruksi cabang yang sedang dieksekusi . Dari ini, saya kira-kira bisa mengetahui berapa kali loop berjalan. Ini mungkin tidak perlu, tetapi saya ingin memastikan bahwa loop dijalankan berkali-kali, dan tidak dieksekusi lambat (untuk beberapa alasan). Saya pikir itu sangat keren sehingga saya bisa melakukannya secara sederhana, cukup buat perubahan kecil pada file batch. Saya menemukan bahwa WinMgmt.exe dijalankan kira-kira satu instruksi percabangan per siklus, yaitu siklus (yang, seperti yang saya sudah tahu, menghabiskan sebagian besar waktu CPU) sangat cepat, dan perlambatan disebabkan oleh kenyataan bahwa ia menjalankan ratusan juta kali.

Keterlambatan Xperf

Hanya demi ketelitian, saya memutuskan untuk melihat mengapa UIforETW tidak dapat mulai melacak selama insiden ini. Ternyata UIforETW menjalankan xperf , tetapi xperf idle selama 41,5 detik (sebenarnya lebih lama) di tumpukan panggilan ini:

xperf.exe! wmain
xperf.exe! CStopTrace :: Execute
perfctrl.dll! LoggingSession :: EnumLoggers
perfctrl.dll! LoggingSession :: LoggingSession
perfctrl.dll! LoggingSession :: CreateProviderList
perfctrl.dll! GetProviderInfoCache
perfctrl.dll! CProviderInfoCache :: CProviderInfoCache
tdh.dll! TdhfEnumerateProviders
tdh.dll! TdhpWbemConnect
wbemprox.dll! CLocator :: ConnectServer
wbemprox.dll! CDCOMTrans :: DoActualConnection

Singkatnya, xperf dipanggil oleh Wbem , dan karenanya diblokir oleh masalah ini. xperf mencoba menghentikan jejak sebelum memulainya, karena saya menambahkan perilaku ini untuk membuat awal jejak lebih toleran terhadap kesalahan . Saya menduga bahwa hang masih akan terjadi, tetapi saya tidak tahu pasti.

Kami membuat grafik kompleksitas komputasi

Saya perhatikan bahwa WinMgmt.exe memindai direktori c: \ windows \ System32 \ wbem \ Repository , yang berukuran 1,9 GB di komputer saya, jadi saya bertanya di tempat kerja dan di Twitter untuk mengetahui berapa banyak direktori ini yang diperlukan untuk mendapatkan poin data. Saya juga meminta orang-orang untuk memperbaiki runtime winmgmt.exe / verifikasi repositori dan mulai menjadwalkan. Meskipun pengujian ini dilakukan pada mesin yang sama sekali berbeda dengan kecepatan CPU yang berbeda, grafik ternyata cukup jelas:


Hubungan antara akar kuadrat waktu dan ukuran repositori

Grafik rasio sqrt (waktu) ini dengan ukuran repositori sangat ideal untuk data yang diterima dari enam mesin yang berbeda, dan bagaimanapun, itu nyata. Jelas, fungsi VerifyRepository memiliki kinerja O (n ² ). Jika n adalah ukuran direktori Repositori dalam GB , maka VerifyRepository membutuhkan waktu sekitar 1,6 * n ² menit. Ini adalah perkiraan kasar yang baik untuk semua nilai - dari sepersekian detik hingga sepuluh menit.

Relevansi

Entah saya beruntung, atau saya hanya jeli, karena selama beberapa minggu tidak ada yang pernah mengalami masalah ini lagi - saya pikir hal-hal aneh terjadi pada mobil saya. Tapi tiba-tiba saya mulai mendengar keluhan serupa yang mencurigakan dari rekan kerja. Salah satu dari mereka memiliki repositori 2,6 GB, yang membutuhkan waktu sepuluh menit untuk memverifikasi. Masalahnya memengaruhi beberapa pengembang CI kami, dan pada tingkat yang berbeda, orang lain berbeda. Rekan-rekan saya biasanya tahu bahwa jika terjadi masalah dengan kinerja mesin Windows, saya harus mengatakan ini kepada saya, namun, mungkin ada banyak karyawan Google lain yang bekerja di bawah Windows yang dicegah oleh bug ini, tetapi mereka tidak menyadarinya.

Untungnya, saya sudah mulai bekerja dengan departemen TI kami. Saya menemukan skrip yang meluncurkan WinMgmt dan menemukan bahwa itu berjalan setiap jam. Ini berarti bahwa mesin saya menjalankan WinMgmt.exe / memverifikasi repositori 10% dari waktu, dan beberapa rekan saya memiliki lebih dari 16% dari waktu. Ada kemungkinan yang cukup tinggi untuk mendapatkan penundaan sepuluh menit sebelum perakitan.

Pada saat laporan mulai tiba, perbaikan sudah dalam perjalanan ke produksi. Script adalah opsional, dan tentu saja tidak sepadan dengan masalah yang ditimbulkannya, jadi perbaikannya adalah mematikan panggilannya.

Ringkasan

winmgmt.exe / verifikasi repositori berisi siklus sembilan instruksi, jumlah iterasi eksekusi yang sebanding dengan kuadrat ukuran repositori wbem . Karena itu, pelaksanaan perintah dapat memakan waktu hingga sepuluh menit, meskipun dalam kenyataannya harus dijalankan hanya dalam beberapa detik. Ini buruk dalam dirinya sendiri.

Tetapi lebih buruk lagi, tim melakukan kunci WMI ( Windows Management Instrumentation ) selama operasinya, sehingga setiap proses yang melakukan operasi WMI akan membeku.

Teka-teki menakjubkan

Script yang menjalankan winmgmt.exe / verifikasi repositori setiap jam melakukan ini selama bertahun-tahun, tetapi perilaku bermasalah mulai muncul hanya satu hingga dua bulan lalu. Agaknya, ini berarti bahwa repositori wbem baru-baru ini menjadi jauh lebih besar. Penundaan pada 0,5 GB mudah diabaikan, tetapi dari 1,0 GB dan di atas mereka sudah bisa tegang. Seperti yang disarankan di Twitter, saya menjalankan strings.exe untuk file objects.data. Banyak string yang paling umum mengandung polmkr dalam namanya, tetapi saya tidak tahu apa artinya itu.

Saya menerbitkan laporan bug di Twitter , dan pada awalnya menyebabkan beberapa gerakan dari tim WMI , tetapi kemudian saya berhenti menerima jawaban, jadi saya tidak tahu apa situasinya sekarang.

Saya ingin melihat perbaikan untuk masalah kinerja, dan saya ingin departemen TI kami dapat menemukan dan memperbaiki masalah yang membuat repositori wbem kami begitu besar. Tetapi untuk saat ini, departemen TI telah berjanji untuk tidak menjalankan perintah repositori / verifikasi setiap jam lebih, yang seharusnya membantu kita menghindari gejala terburuk.

Referensi

• Daftar umum tutorial, investigasi, dan dokumentasi ETW tersedia di sini: https://tinyurl.com/etwcentral
• Tutorial Penggunaan CPU (Sampel) (untuk mengetahui berapa waktu CPU dihabiskan) ada di sini , dan dokumentasinya ada di sini.
• Tutorial Penggunaan CPU (Tepat) (untuk menemukan alasan mengapa utas tidak dapat berjalan) ada di sini , dan dokumentasinya ada di sini.
• Tautan ke masing-masing artikel diberikan di badan pos, Anda juga dapat menemukannya di kategori Pelaporan Investigasi saya
• Cerita lain tentang algoritma O (n ² ) dapat dibaca di Accidentally Quadratic

Diskusi tentang artikel tentang Reddit ada di sini , diskusi tentang berita hacker ada di sini , utas di Twitter ada di sini, dan mungkin di sini