DCSIMG
February 2010 - Posts - Liran Chen's Blog

Liran Chen's Blog

.Net Internals, Debugging, Multithreading - and More!

February 2010 - Posts

Accurately Measuring GC Suspensions

כשבאים לנתח ביצועים של אפליקציית Managed, ורוצים להבין מה הם צווארי הבקבוק שעשויים להכשיל אותה בתרחישי עומס איתם היא אמורה להתמודד, אחד הפרמטרים החשובים שצריך לשים לב אליהם הוא מידת הזמן שהאפליקציה שלנו מבלה ב-GC. בשביל לדעת את זה, תמיד אפשר להריץ במקביל לאפליקציה את Perfmon ולקבל ניתוח כללי של התנהגות ה-GC באפליקציה שלנו, כשהמדד העיקרי שנסתכל עליו בדרך כלל הוא אחוז ה-Time in GC.
התבוננת בנתונים האלה יכולים אמנם לתת לנו "מבט כללי" על השפעת ה-GC על ביצועי האפליקציה, אבל הוא פשוט לא מספיק בשביל לקבל תובנות מעמיקות יותר ולקשר תקיעות שנצפות בפרוסס ל-Collection'ים שיתכן והופעלו באותו הזמן. למשל, גם אם נראה שב-90% מהזמן אנחנו מבלים רק 2% ב-GC, זה עדיין לא אומר שלא יתכן מצב בו ברגע קריטי במערכת פתאום הוחלט להריץ Gen2 שתקע לנו את כל הפרוסס למשך של כ-200 מילישניות. מה שעשוי לגרום לנזק לא מבוטל אצל אפליקציות הרגישות למדי לתקיעות בלתי צפויות שכאלה. כל הרעיון הוא שה-GC לא גורם לתהליכים לעבוד יותר לאט, אלא הוא פשוט יכול לתקוע את כל הפרוסס לחלוטין. לכן הסתכלות נאיבית על גרף ה-Time in GC לא באמת אומרת לנו בצורה מובהקת מה הנזק האמיתי של כל GC במקרה הפרטי שלנו. אם נסתכל על הגרף, יתכן שנראה איזשהיא קפיצה "באזור הזמן" של התקיעה, אבל מאחר והרזולוציה הגבוהה ביותר של Perfmon עומדת על שנייה אחת, ואנחנו לא באמת יודעים באמת כמה זמן כל GC באזור השניה ההיא לקח, אין לנו דרך לקשר בצורה ישירה וברורה בין התקיעה "הכללית" שנצפתה בפרוסס, לבין Collection מסויים שיתכן וקרה או לא קרה באותו הזמן. מה גם, שלא תמיד פשוט לדאוג שבכל מקום שמריצים את האפליקציה ידאגו גם להריץ Collector'ים של Perfmon שידאגו לאסוף את הנתונים האלה בכל רגע נתון.

לכן, אנחנו זקוקים לדרך אמינה שתאפשר לנו למדוד בצורה מדוייקת מתי ה-CLR מחליט לבצע Collection'ים, באיזה Generation'ים מדובר, וכמה זמן כל אחד מהם לוקח.
כיום מחלקת ה-GC לא חושפת לנו דרך לקבל את התונים האלה. אבל על ידי כתיבת CLR Host משלנו, נוכל להתממשק ל-CLR ולקבל ממנו את ההתראות המתאימות שיאמרו לנו מתי מתחיל ונגמר כל GC בפרוסס.
כדי לעשות זאת, נצטרך לממש את IHostGCManager ולהעזר בשניים מתוך שלושת Callback'ים שהוא מציע. הראשון הוא SuspensionStarting שלא מקבל פרמטרים כלשהם, והשני הוא SuspensionEnding שמקבל פרמטר DWORD בודד שמכיל את מספר ה-Genration של ה-Collection שהסתיים. כמו שאפשר לנחש, ה-CLR דואג להפעיל את SuspensionStarting לפני שהוא מפעיל את ה-Collection, ולאחריו, הוא דואג להפעיל את SuspensionEnding.
דבר אחד שצריך לשים לב אליו לגבי SuspensionEnding, הוא שהתיעוד ב-MSDN לא מדוייק ויכול להטעות משתמשים לגבי הטריגרים האפשריים להפעלה שלו. נכון להיום, זה מה שהתיעוד אומר:

"...Notifies the host that the common language runtime (CLR) is resuming execution of tasks on threads that had been suspended for a garbage collection.
[parameter: generation] The garbage collection generation that is just finishing, from which the thread is resuming."


כלומר, התיעוד מספר שה-Callback יופעל אך ורק כתוצאה מקפיאות הנובעות מ-GC. אולם בפועל, זוהי אינה הסיבה היחידה לכך שה-Callback הזה יופעל. למעשה, ה-CLR יפעיל אותה גם לאחר התעוררות מחודשות כתוצאה מהקפאות יזומות אחרות שהוא עשוי לבצע (למשל, טעינה ושחרור של AppDomain'ים). אם נבדוק במימוש של SSCLI היכן ומתי מפעילים את ה-Callback, נוכל להבחין בקטע הקוד הבא:

if (pGCThreadControl)

{

    // If we the suspension was for a GC, tell the host what generation GC.

    DWORD   Generation = (bFinishedGC

        ? GCHeap::GetGCHeap()->GetCondemnedGeneration()

        : ~0U);

 

    pGCThreadControl->SuspensionEnding(Generation);

}


כך שאפשר לראות שעבור כל קפיאה שנגרמה לאו דווקא כתוצאה מ-GC, פרמטר ה-generation שמועבר לפונקציה יכיל את הערך UINT_MAX, כך שיהיה לנו כדאי להתייחס בצורה מתאימה לערך הזה בזמן שאנחנו כותבים את ה-CLR Host שלנו.

באשר למימוש המדידה עצמה, נשתמש ב-QueryPerformanceCounter על מנת לקבל את הדיוק הגבוה ביותר למשך הזמן שלקח ה-GC. מאחר ובדרך כלל רוב ה-Collection'ים שננטר יעצרו את הפרוסס לפרקי זמן קצרים בלבד (מילישניות בודדות), סביר שלא נרצה להשקיע מאמץ בשמירת הנתונים האלה (המנעות מ-IO מיותר). לכן זה יהיה רעיון טוב להתממשק לתשתית Logging ועבור Collection'ים שלוקחים פחות מסף מסויים של זמן, להשתמש ברמת Debug עבור הכתיבות ללוג, בעוד שעבור Collection'ים שחרגו אותו סף זמן, להשתמש ברמת Warn.
עם צירוף של Appender שדואג לזרוק את כל הלוגים ל-Console, והרצת תוכנית שדואגת להקצות זכרון בלי סוף, אנחנו יכולים לקבל פלט בסגנון הזה:



לשם הנוחות, אני מצרף מימוש פשוט של Host לדוגמא שמנטר הקפאות יזומות של ה-CLR ומדפיס ל-Console את משך הזמן שנמדד בכל פעם:

#include <mscoree.h>

#include <windows.h>

#include <assert.h>

#include <iostream>

 

using namespace std;

 

#define APP_STARTUP_EXE L"TestApplication.exe"

#define APP_ENTRY_TYPE L"SomeNamespace.Program"

#define APP_ENTRY_METHOD L"Main"

 

class MyCLRHost : public IHostControl, public IHostGCManager

{

private:

    LONG m_refCount;

    LARGE_INTEGER m_lastGCStart;

    LARGE_INTEGER m_frequency;

 

public:

    MyCLRHost() { QueryPerformanceFrequency(&m_frequency); }

 

    // IHostControl

    HRESULT __stdcall GetHostManager(REFIID riid, void** ppObject)

    {

        if(riid == IID_IHostGCManager)

        {

            *ppObject = static_cast<IHostGCManager*>(this);

            return S_OK;

        }

 

        *ppObject = NULL;

        return E_NOINTERFACE;

    }

 

    // IUnknown

    HRESULT __stdcall QueryInterface(REFIID riid, void** ppvObject)

    {

        if (riid == IID_IHostGCManager)

        {

            *ppvObject = static_cast<IHostGCManager*>(this);

            return S_OK;

        }

 

        *ppvObject = NULL;

        return E_NOINTERFACE;

    }

 

    HRESULT __stdcall SetAppDomainManager(DWORD appDomain, IUnknown* domainManager)

    {

        return S_OK;

    }

 

    ULONG __stdcall AddRef() { return InterlockedIncrement(&m_refCount); }

    ULONG __stdcall Release() { return InterlockedDecrement(&m_refCount); }

 

    // IHostGCManager

    HRESULT __stdcall ThreadIsBlockingForSuspension() { return S_OK; }

 

    HRESULT __stdcall SuspensionStarting()

    {

        m_lastGCStart;

        QueryPerformanceCounter(&m_lastGCStart);

 

        return S_OK;

    }

 

    HRESULT __stdcall SuspensionEnding(DWORD gen)

    {

        LARGE_INTEGER gcEnd;

        QueryPerformanceCounter(&gcEnd);

        double duration = ((gcEnd.QuadPart - m_lastGCStart.QuadPart))

            * 1000.0 / (double)m_frequency.QuadPart;

 

        if(gen != UINT_MAX)

            cout<<"GC generation "<<gen<<" ended: "<<duration<<"ms"<<endl;

        else

            cout<<"CLR suspension ended: "<<duration<<" ms"<<endl;

 

        return S_OK;

    }

};

 

int _tmain(int argc, _TCHAR* argv[])

{

    ICLRRuntimeHost* pCLR;

    DWORD startupFlags = STARTUP_CONCURRENT_GC;

    HRESULT hr = CorBindToRuntimeEx(L"v2.0.50727", L"wks", startupFlags,

        CLSID_CLRRuntimeHost, IID_ICLRRuntimeHost, (LPVOID*)&pCLR);

    assert(SUCCEEDED(hr));

 

    MyCLRHost customHost;

    hr = pCLR->SetHostControl(&customHost);

    assert(SUCCEEDED(hr));

 

    hr = pCLR->Start();

    assert(SUCCEEDED(hr));

 

    DWORD retcode;

    hr = pCLR->ExecuteInDefaultAppDomain(APP_STARTUP_EXE,

        APP_ENTRY_TYPE, APP_ENTRY_METHOD, L"" , &retcode);

    assert(SUCCEEDED(hr));

 

    return 0;

};