كيف يتحول الوقت الخطي إلى Windows في O (n²)

لقد واجهت مؤخرًا عدة دقائق من التأخير في محطة العمل الخاصة بي. بعد التحقيق ، تبين أن سبب المشكلة هو القفل ، والذي يمكن أن يستمر لمدة خمس دقائق ، وخلاله تدور مصدر القفل بشكل أساسي في دورة من تسعة تعليمات.

من المهم جدًا بالنسبة لي اختيار عناوين جيدة لمشاركاتي ، لكنني تذكرت على الفور أن الاسم المناسب "48 حلقة محجوبة بتسع تعليمات" تم أخذه بالفعل [ ترجمة في حبري] بواسطة منشور كتب قبل أقل من شهر. يختلف عدد المعالجات المحظورة ، والدورة أطول قليلاً ، ولكن في الحقيقة ، كل هذا يجعلك تواجه deja vu. لذلك ، بينما أشرح المشكلة الجديدة التي تم العثور عليها ، أردت أن أفكر في سبب حدوث ذلك طوال الوقت .

لماذا يحدث هذا؟

بمعنى تقريبي ، تنشأ مثل هذه المشكلات كنتيجة لملاحظة سأدعوها "قانون داوسون الأول حول الحوسبة: O (n ² ) هو نقطة جذب للخوارزميات التي لا تتطور بشكل جيد : إنها سريعة بما يكفي للدخول في الإنتاج ، ولكنها بطيئة بدرجة كافية لإفساد كل شيء ، عندما يصلون إلى هناك.


O (ن ² ) في العمل - البيانات مأخوذة من حالتي

ما الذي يحدث؟ المطور يكتب الكود ويستخدم خوارزمية O (n ² ). ربما لم يدرك ذلك ، أو أن الخوارزمية تصبح O (n ² ) بسبب خطأ ، أو أن المطور يعلم أنه O (n ² ) ، لكنه يعتقد أنه لن يكون مهمًا أبدًا. في الظروف المختبرية ، تكون سرعة الشفرة مقبولة ومقبولة بالنسبة لمعظم المستخدمين في العالم الحقيقي ، ولكن بعد ذلك يقوم شخص ما بإنشاء 7000 عملية مع تشغيل App Verifier أو إنشاء ملف ثنائي يحتوي على 180،000 عنصر من عناصر CFG ، أو يجمع DLL كبيرًا بحيث يكون باستمرار يتم فحص قائمة مرتبطة واحدة ، والتي تأخذ المعالج بأكمله. عند العمل في وقت إطلاق محرك Valve Source 2 ، وجدت العديد من خوارزميات O (n ² ) ، كل منها أضيفت حوالي 30 ثانية إلى وقت إطلاق المحرك ، أي أن هذه المشكلة تحدث مع مطورين مختلفين للغاية.

O (n ² ) هو مغناطيس للخوارزميات التي لا تتطور بشكل جيد: فهي سريعة بما يكفي للدخول في الإنتاج ، ولكنها بطيئة بدرجة كافية لتفسد كل شيء عندما تصل إلى هناك.

بالضبط.

على سبيل المثال ، يتم إنشاء أسماء ملفات سجل App Verifier في الوقت الخطي لكل عملية قيد التشغيل ، وهذا أمر طبيعي حتى تدرك أن هذا يؤدي إلى O (n ² ) في حالة تشغيل العديد من العمليات. في بعض الأحيان ، ليس من الواضح أن هناك حلقات متداخلة ، أو أنه ليس رسميًا O (n ² ) ، أو ليس من الواضح أن هذه الحلقات يمكن أن تعمل لفترة طويلة بحيث يمكن أن تؤثر بشكل كبير على السرعة ...

لذا فكر في هذه الفرصة ، فكر في الأمر عند كتابة التعليمات البرمجية ، ومراقبة كيفية قياس الأداء تحت الأحمال الثقيلة ، وفحص الأقسام المشبوهة من التعليمات البرمجية عند تحديد هذه الأحمال الثقيلة. أو اتركه لي حتى أتمكن من البحث عنهم وكتابة مقالات على مدونتي.

دعنا نعود إلى شكاوىنا المعتادة

كالمعتاد ، عملت في عملي على محطة العمل التي عفا عليها الزمن ولكن لا تزال قوية مع 48 المعالجات المنطقية و 96 جيجابايت من ذاكرة الوصول العشوائي. قدمت كروم النينجا لبناء Chromium ، لكن ... لم يحدث شيء. نظرت وانتظرت عشرين ثانية ، لكن الجمعية لم تبدأ. لذلك ، بالطبع ، تحولت إلى UIforETW لتسجيل تتبع ETW . بتعبير أدق ، حاولت أن أفعل ذلك. في محاولة لبدء تسجيل التتبع ، يتجمد UIforETW . لأول مرة في ممارستي ، استخدم الخلل تدابير وقائية لمنعني من استكشاف ذلك!

بعد دقيقة أو دقيقتين ، بدأ تجميع Chromium ، وبدأت UIforETW عملية التتبع ، لكنها بدأت بعد فوات الأوان ولم يكن لدي أدنى معلومات حول ما حدث.


خيارات UIforETW مع تحديد التعيين المؤقت للمخزن المؤقت

عندما حدث نفس الشيء بعد يومين ، لم تتمكن UIforETW مرة أخرى من فعل أي شيء. هذه المرة ، تركت التتبع للعمل في المخازن المؤقتة للذاكرة الدائرية ، لتكون مستعدًا لحقيقة حدوث تعليق للمرة الثالثة. ومع ذلك ، قلل هذا إلى حد كبير من سرعة أدوات البناء الخاصة بي ، لذلك بعد بضع ساعات استسلمت.

ثم كرر هذا الموقف مرة أخرى . هذه المرة قمت بتشغيل أداة تسجيل التتبع ETW التي أنشأتها Microsoft - wprui ، وتمكنت من بدء التسجيل. بعد حوالي 40 ثانية ، بدأ التجميع في العمل وحصلت على أثر!

هل يمكنني البدء في التحقيق الآن؟

في وقت سابق ، لاحظت في "إدارة المهام" أن WinMgmt.exe كان يعمل أثناء هذه التجميد . بالنظر إلى بيانات استخدام CPU (دقيق) في WPA ، كنت مقتنعًا أنه بعد أكثر من أربعين ثانية ، كانت خلالها WinMgmt.exe عملية العمل الوحيدة تقريبًا ، ظهرت أجهزتي الحيوية بعد إيقاف تشغيل WinMgmt.exe :


نحن ننتظر الصحوة من العمليات بعد اكتمال WinMgmt.exe

كل هذا مشكوك فيه إلى حد ما ، لكن قراءي الحكيمين يعرفون أن كلمة "بعد" لا تعني "بسبب" ، وسوف تتطلب إثباتًا.

مثل آخر مرة ، تقريبًا لحظات فتح القفل على الرسم البياني ، وفرز رموز تبديل السياق حسب وقت التبديل وتبحث عن المفتاح الأول بقيمة طويلة منذ وقت آخر (تشير إلى طول الفترة الزمنية التي لم يتم خلالها تنفيذ مؤشر الترابط). بعد أن غاب عن عشرات المواضيع التي كانت مجرد فترات توقف قصيرة ، وجدت أول واحد من تلك التي انتظرت 41.57 ثانية. لم يستيقظ خيط النوم WinMgmt.exe ، لكنني سرعان ما اكتشفت أنه استيقظ مع الخيط الذي استيقظ WinMgmt.exe جزء من ميلي ثانية واحدة من قبل.

للحصول على شرح للرسوم البيانية لاستخدام وحدة المعالجة المركزية (دقيقة) ومفاهيم مؤشر ترابط الاستعداد / سلسلة الرسائل الجديدة ، راجع هذا البرنامج التعليمي أو هذه الوثائق .

في لقطة الشاشة التي تحتوي على بيانات تبديل المحتوى ، يحتوي السطر 17 على الدفق 72.748 (WinMgmt.exe) ، الذي ينشط الدفق 74156 (ملف Svchost.exe). بعد ذلك ، على السطر 19 ، يقوم مؤشر الترابط 74،156 (svchost.exe) بتنشيط مؤشر الترابط 58،704 (svchost.exe) ، الذي كان ينتظر 41.57 ثانية. هذا هو الخيط الأول الذي يستيقظ بعد نوم طويل ويستمر من خلاله سلسلة تنشيط التدفقات. يمكن رؤية سلاسل الرسائل التي تم تنشيطها للتو في عمود معرف سلسلة الرسائل الجديدة ، ثم تنزل بضعة أسطر ورؤيتها في عمود مؤشر قراءة سلسلة القراءة ، وتفعيل سلسلة رسائل أخرى. تساعدك الأسماء ومعرفات العمليات في فهم السياق. يرتبط الخط 17 بالخطين 18 و 19 ، بينما يرتبط السطر 19 بالخط 20 ، ويرتبط بالخط 23 ، المرتبط بالخط 27 وما إلى ذلك ؛ يتم تنشيط كل خيط من الخيط السابق في السلسلة:


يوقظ الوحش - الخيوط الطويلة الخاملة تنبض بالحياة

41.57 هو وقت طويل لحظر سلسلة ، ولكن في الواقع تم حظر مئات الخيوط ، وتم حظرها لفترة أطول من ذلك بكثير . السبب الوحيد لقيمة وقتهم منذ حوالي 41.5 ثانية هو أن طول التتبع قبل حل المشكلة.

يبدو أن النتائج تتفق مع نظرية أن المشكلة في WinMgmt.exe ، لكنها لا تثبت ذلك. زادت ثقتي عندما نظرت إلى ملف Svchost.exe (3024) في التتبع> تكوين النظام> الخدمات واكتشف أنها خدمة Winmgmt ، لكنني ما زلت بحاجة إلى مزيد من اليقين.

بعد أن قمت بالتفتيش أكثر قليلاً (تجول للأمام والخلف في الوقت المناسب) ، قررت أن التفاعلات معقدة للغاية بحيث لا يمكن تحليلها بالتفصيل ، خاصة دون أسماء الدفق التي يمكن أن تشير إلينا إلى ما يفعله 25 مؤشر ترابط مختلف في ملف Svchost.exe (3024) .

! والدليل

ثم قررت الاقتراب من دليل WinMgmt.exe على أنه مذنب بشكل مختلف. ربما كان الأمر يستحق البدء بهذا ، لكنه سيكون بسيطًا جدًا. أخذت سطر الأوامر WinMgmt.exe من جدول العمليات في WPA وبدأت تشغيله يدويًا. الأمر لديه النموذج:

winmgmt.exe / التحقق من المستودع

واستغرق حوالي خمس دقائق لإكمال. بينما كان يعمل (وكان لدي الكثير من الوقت) ، اكتشفت أنه لا يمكنني بدء تتبع ETW من UIforETW . كان هذا الدليل أفضل من أي تحليل معقد يمكنني القيام به.


التكوين لعرض فقط المواضيع الخاملة طويلة

ثم ركضت Rep مرة أخرى مع التتبع قيد التشغيل بالفعل ؛ بعد تحليل التتبع ، اكتشفت أكثر من مائة عملية تم حظر مؤشرات الترابط الخاصة بها لأكثر من خمس دقائق!

ومرة أخرى إلى نقطة ...

خارج العادة ، لقد بحثت مرة أخرى في بيانات استخدام وحدة المعالجة المركزية (أخذ العينات) لمعرفة ما WinMgmt.exe كان يضيع الوقت في. اكتشفت بسرعة أن 96.5٪ من العينات كانت في repdrvfs.dll! CPageCache :: Read () ، ودعا على أربعة مكدسات مختلفة:


أربعة مسارات التي أدت بي إلى CPageCache :: قراءة

تظهر هنا مجموعة من العناصر الكاملة لهذه الوظيفة ، خاصة للأشخاص من Microsoft الذين يريدون البحث في هذه المشكلة:


مكدسات كاملة تؤدي إلى CPageCache :: قراءة بثلاث طرق

أضفت عمود عنوان واكتشفت أن 95.3 ٪ من العينات كانت في دورة واحدة من تسعة تعليمات (سقطت العينات دائما في سبعة فقط من أصل تسعة تعليمات (إذا كنت تريد معرفة السبب ، انظر هنا ) ، ولكن مصحح الأخطاء أظهر الحجم الكامل للدورة) :


عينات حسب العنوان - سبعة عناوين "ساخنة للغاية"

ثم بدأت تشغيل winmgmt.exe / verrepository يدويًا ، وفي نفس الوقت قمت بجمع بيانات عداد وحدة المعالجة المركزية حول تعليمات الفرع التي يتم تنفيذها . من هذا ، استطعت تقريبًا معرفة عدد مرات تشغيل الحلقة. ربما لم يكن هذا ضروريًا ، لكنني أردت التأكد من تنفيذ الحلقة عدة مرات ، ولم يتم تنفيذها ببطء (لسبب ما). اعتقدت أنه من الرائع أن أتمكن من القيام بذلك ببساطة ، فقط قم بإجراء تغيير بسيط على الملف الدفعي. اكتشفت أن WinMgmt.exe نفّذ ما يقرب من تعليمة فرعية واحدة لكل دورة ، أي أن الدورة (التي ، كما كنت أعرف بالفعل ، استهلكت معظم وقت وحدة المعالجة المركزية) كانت سريعة للغاية ، وكان التباطؤ يرجع إلى حقيقة أنها ركضت مئات الملايين الوقت.

Xperf تأخير

فقط من أجل الدقة ، قررت أن أرى لماذا لم تتمكن UIforETW من بدء التتبع خلال هذا الحادث. اتضح أن UIforETW كان يعمل xperf ، لكن xperf كان خاملاً لمدة 41.5 ثانية (أطول فعليًا) في مكدس الاستدعاءات هذا:

xperf.exe!
xperf.exe! CStopTrace :: Execute
تسجيل الدخول :: EnumLoggers
perfctrl.dll! LoggingSession :: LoggingSession
تسجيل الدخول :: CreateProviderList!
perfctrl.dll! GetProviderInfoCache
perfctrl.dll! CProviderInfoCache :: CProviderInfoCache
tdh.dll! TdhfEnumerateProviders
tdh.dll! TdhpWbemConnect
wbemprox.dll! CLocator :: ConnectServer
wbemprox.dll! CDCOMTrans :: DoActualConnection

باختصار ، يتم استدعاء xperf بواسطة Wbem ، وبالتالي يتم حظره بواسطة هذه المشكلة. يحاول xperf إيقاف التتبع قبل بدء تشغيله ، لأنني أضفت هذا السلوك لجعل بداية التتبع أكثر تحملاً للأخطاء . أظن أن تعليقًا ما زال سيحدث ، لكنني لا أعرف بالتأكيد.

إنشاء الرسوم البيانية التعقيد الحسابي

لقد لاحظت أن WinMgmt.exe يقوم بمسح الدليل c: \ windows \ System32 \ wbem \ Repository ، الذي يبلغ 1.9 غيغابايت على الجهاز الخاص بي ، لذلك طلبت في العمل وعلى Twitter لمعرفة مقدار ما يستغرقه هذا الدليل للحصول على نقاط البيانات. طلبت أيضًا من الأشخاص إصلاح وقت تشغيل ملف winmgmt.exe / verrepository وبدأت بجدولة. على الرغم من أن هذه الاختبارات قد أجريت على أجهزة مختلفة تمامًا بسرعات مختلفة لوحدة المعالجة المركزية ، فقد اتضح أن الرسم البياني واضح جدًا:


العلاقة بين الجذر التربيعي للوقت وحجم المستودع

يعد هذا الرسم البياني لنسبة sqrt (الوقت) إلى حجم المستودع مثاليًا بشكل لا يصدق للبيانات الواردة من ستة أجهزة مختلفة ، ومع ذلك ، فهو حقيقي. من الواضح أن وظيفة VerifyRepository لها أداء O (n ² ). إذا كان n هو حجم دليل السجل في جيجابايت ، فإن VerifyRepository يستغرق حوالي 1.6 * n دقيقتين. هذا تقدير تقريبي جيد لجميع القيم - من الانقسام الثاني إلى عشر دقائق.

أهمية

إما أني محظوظ ، أو أنا مجرد ملاحظ ، لأنه لم يعد أحد يواجه هذه المشكلة لمدة أسبوعين - أعتقد أن أشياء غريبة تحدث في سيارتي. لكن فجأة بدأت أسمع شكاوى مماثلة بشكل مثير للريبة من زملائي. واحد منهم لديه مستودع 2.6 غيغابايت ، والتي استغرقت عشر دقائق للتحقق. أثرت المشكلة على بعض مطوري CI ، وبدرجات مختلفة ، أشخاص مختلفين. عادة ما يعرف زملائي أنه في حالة حدوث مشكلات في أداء أجهزة Windows ، أحتاج أن أقول هذا لي ، ومع ذلك ، ربما يكون هناك العديد من موظفي Google الآخرين الذين يعملون تحت Windows والذين تم منعهم من هذا الخطأ ، لكنهم لا يدركون ذلك.

لحسن الحظ ، لقد بدأت بالفعل العمل مع قسم تكنولوجيا المعلومات لدينا. لقد وجدت البرنامج النصي الذي أطلق WinMgmt واكتشف أنه يعمل كل ساعة. هذا يعني أن جهازي كان يعمل على WinMgmt.exe / verrepository 10٪ من الوقت ، وكان لدى بعض زملائي أكثر من 16٪ من الوقت. هناك احتمال كبير إلى حد ما للحصول على تأخير لمدة عشر دقائق قبل التجميع.

بحلول الوقت الذي بدأت فيه التقارير في الوصول ، كان الإصلاح بالفعل في طريقه إلى الإنتاج. كان البرنامج النصي اختياريًا ، وبالتأكيد لا يستحق المشاكل التي تسبب بها ، لذلك كان الإصلاح هو إيقاف مكالمته.

النتائج

يحتوي winmgmt.exe / verrepository على دورة من تسعة إرشادات ، يتناسب عدد تكرارات التنفيذ مع مربع حجم مستودع wbem . لهذا السبب ، قد يستغرق تنفيذ الأمر ما يصل إلى عشر دقائق ، على الرغم من أنه في الواقع يجب تنفيذه في بضع ثوانٍ فقط. هذا سيء في حد ذاته.

ولكن الأسوأ من ذلك ، أن الفريق ينفذ قفل WMI ( Windows Management Instrumentation ) أثناء تشغيله ، وبالتالي فإن أي عملية تؤدي عمليات WMI ستتجمد.

الألغاز مذهلة

قام البرنامج النصي الذي قام بتشغيل winmgmt.exe / checkrepository كل ساعة بهذا منذ سنوات عديدة ، لكن السلوك الإشكالي بدأ يظهر من شهر إلى شهرين فقط. من المفترض أن هذا يعني أن مستودع wbem أصبح مؤخرًا أكبر بكثير. يمكن التغاضي بسهولة عن التأخيرات عند 0.5 جيجا بايت ، ولكن من 1.0 جيجا بايت وما فوق يمكن أن تتوتر بالفعل. كما هو مقترح على Twitter ، قمت بتشغيل strings.exe لملف object.data. تحتوي العديد من السلاسل الأكثر شيوعًا على polmkr في الاسم ، لكنني لا أعرف ماذا يعني ذلك.

لقد نشرت تقريرًا عن الأخطاء على Twitter ، وفي البداية تسببت في بعض الحركة من فريق WMI ، ولكن بعد ذلك توقفت عن تلقي الإجابات ، لذلك لا أعرف ما هو الوضع الآن.

أرغب في رؤية حل لمشكلة الأداء ، وأريد أن يتمكن قسم تكنولوجيا المعلومات لدينا من العثور على المشكلة التي تجعل مستودعات wbem لدينا كبيرة للغاية وحلها. لكن في الوقت الحالي ، وعد قسم تقنية المعلومات بعدم تشغيل الأمر / validrepository كل ساعة ، مما سيساعدنا في تجنب أسوأ الأعراض.

مراجع

• قائمة عامة من البرامج التعليمية ETW والتحقيقات والوثائق المتاحة هنا: https://tinyurl.com/etwcentral
• البرنامج التعليمي لاستخدام وحدة المعالجة المركزية (أخذ العينات) (لمعرفة الوقت الذي تستغرقه وحدة المعالجة المركزية) موجود هنا ، والوثائق هنا.
• البرنامج التعليمي لاستخدام وحدة المعالجة المركزية (الدقيق) (للعثور على أسباب عدم تشغيل مؤشرات الترابط) هنا ، والوثائق هنا.
• وترد روابط لمقالات فردية في نص المنشور ، ويمكنك أيضا العثور عليها في فئة التحقيق في التقارير
• يمكن قراءة قصص أخرى حول خوارزميات O (n ² ) على التربيعي العرضي

مناقشة مقالة حول رديت هنا ، ومناقشة حول أخبار القراصنة هنا ، وخيط على تويتر هنا ، وربما هنا