עקיבה שמסבירה התנהגות

הפעולה הסתיימה אחרי חצי שנייה, אבל הCPU היה עסוק רק בחלק קטן מהזמן. היכן נעלם השאר? יכול להיות שהעבודה חיכתה בתור, לדיסק, לשרת אחר או לthread שהיה צריך להשלים אותה. מדידת זמן אחת מסביב לפונקציה אומרת כמה חיכינו, אבל אינה מסבירה למה.

המנגנון ETW מאפשר לחבר אירועים של היישום לאירועי מערכת על ציר זמן. אנחנו נכתוב אירועים שמסמנים משמעות עסקית, והכלים יאפשרו להצליב אותם עם scheduling, CPU וI/O. כדי שהחיבור יהיה שימושי, צריך לתכנן את האירועים לפני שמתחילים להוסיף הדפסות לכל לולאה.

מי מפיק ומי אוסף

הprovider מגדיר את מקור האירועים. הsession של העקיבה בוחר אילו providers, רמות וkeywords לאסוף, ומעביר את המידע לbuffers ולצרכן. העובדה שהקוד קרא לפונקציית כתיבה אינה אומרת שהיה session פעיל או שהאירוע הגיע בשלמותו לקובץ.

הפורמט TraceLogging מאפשר לצרף metadata שמסביר את השדות בלי לכתוב manifest נפרד לכל אירוע. הוא עדיין דורש schema יציב מבחינת הקוד והניתוח: שם שדה שנשאר זהה אבל מחליף משמעות יכול לשבור דוח גם אם כל האירועים מפוענחים.

מזהה פעילות עובר עם העבודה

הthread הוא משאב ביצוע, ולא זהות העבודה. אותה עבודה יכולה להתחיל בUI, להיכנס לתור ולהסתיים בworker. לכן ניצור activity ID ונעביר אותו במפורש. כאשר נוצרת פעילות בת נוכל להוסיף related activity ID, במקום לקשור הכול לthread שהיה פעיל בזמן ההתחלה.

הקובץ הבא, trace_lab.cpp, הוא תוכנית מלאה לMSVC עם Windows SDK הכולל TraceLoggingProvider.h. הוא מבצע חישוב קצר והמתנה יזומה כדי שיהיה אפשר לראות שני סוגי זמן. האירועים אינם כוללים payload של משתמש.

#include <windows.h>
#include <evntrace.h>
#include <TraceLoggingProvider.h>
#include <objbase.h>
#include <cstdint>
#include <cstdio>
#include <thread>
#include <vector>
#include <stdexcept>

TRACELOGGING_DEFINE_PROVIDER(
    course_provider, "AmitTech.Course.Work",
    (0x65fb74ad, 0x4ac9, 0x4cf2, 0x86, 0xac, 0x42, 0x60, 0x9c, 0x31, 0x25, 0x01));

class ProviderScope {
public:
    ProviderScope() {
        const ULONG status = TraceLoggingRegister(course_provider);
        if (status != ERROR_SUCCESS) throw std::runtime_error("provider registration failed");
    }
    ~ProviderScope() { TraceLoggingUnregister(course_provider); }
    ProviderScope(const ProviderScope&) = delete;
    ProviderScope& operator=(const ProviderScope&) = delete;
};

void run_work(GUID activity) noexcept {
    TraceLoggingWriteActivity(course_provider, "WorkStart", &activity, nullptr,
        TraceLoggingLevel(TRACE_LEVEL_INFORMATION), TraceLoggingKeyword(0x1),
        TraceLoggingOpcode(EVENT_TRACE_TYPE_START));
    try {
        std::vector<std::uint64_t> values(1000000);
        std::uint64_t checksum = 0;
        for (std::size_t i = 0; i < values.size(); ++i) {
            values[i] = static_cast<std::uint64_t>(i) * 17 + 3;
            checksum ^= values[i];
        }
        TraceLoggingWriteActivity(course_provider, "ComputeDone", &activity, nullptr,
            TraceLoggingLevel(TRACE_LEVEL_INFORMATION), TraceLoggingKeyword(0x1),
            TraceLoggingUInt64(checksum, "Checksum"),
            TraceLoggingUInt64(values.size(), "Items"));
        TraceLoggingWriteActivity(course_provider, "WaitStart", &activity, nullptr,
            TraceLoggingLevel(TRACE_LEVEL_INFORMATION), TraceLoggingKeyword(0x1),
            TraceLoggingUInt32(60, "RequestedMilliseconds"));
        Sleep(60);
        TraceLoggingWriteActivity(course_provider, "WorkStop", &activity, nullptr,
            TraceLoggingLevel(TRACE_LEVEL_INFORMATION), TraceLoggingKeyword(0x1),
            TraceLoggingOpcode(EVENT_TRACE_TYPE_END), TraceLoggingInt32(0, "Result"));
    } catch (...) {
        TraceLoggingWriteActivity(course_provider, "WorkStop", &activity, nullptr,
            TraceLoggingLevel(TRACE_LEVEL_ERROR), TraceLoggingKeyword(0x1),
            TraceLoggingOpcode(EVENT_TRACE_TYPE_END), TraceLoggingInt32(1, "Result"));
    }
}

int main() {
    try {
        ProviderScope provider;
        GUID first{}, second{};
        if (FAILED(CoCreateGuid(&first)) || FAILED(CoCreateGuid(&second))) return 2;
        std::jthread a([first] { run_work(first); });
        std::jthread b([second] { run_work(second); });
        a.join();
        b.join();
        std::puts("workload finished");
    } catch (const std::exception& error) {
        std::fprintf(stderr, "%s\n", error.what());
        return 1;
    }
}

cl /std:c++20 /EHsc /Zi /O2 /W4 trace_lab.cpp advapi32.lib ole32.lib /link /DEBUG:FULL

הchecksum יוצא לאירוע ולכן החישוב נצפה על ידי התוכנית, אך הקומפיילר עדיין רשאי לשנות את אופן ביצועו. נבדוק את הקוד והtrace במקום להניח שכל איבר בvector נכתב בדיוק כפי שהמקור נראה. מטרת הניסוי היא להבחין בין קטע חישוב לקטע המתנה, ולא להעריך ביצועי אלגוריתם מסוים.

הprovider נשאר רשום עד ששני הthreadים הצטרפו. שחרור מוקדם שלו היה יוצר גבול חיים שגוי גם אם רוב הריצות קצרות מספיק. את מאקרואי הכתיבה ואת הקישור לפעילות אפשר לבדוק בתיעוד TraceLogging.

מגדירים מה לאסוף

נשמור את הפרופיל הבא בקובץ course.wprp. הוא אוסף את הprovider שלנו ברמה verbose עבור keyword אחד. גודל הbuffer והכמות הם נקודת פתיחה למעבדה, ולא הבטחה שלא נאבד אירועים בכל עומס.

<?xml version="1.0" encoding="utf-8"?>
<WindowsPerformanceRecorder Version="1.0" Author="AmitTech">
  <Profiles>
    <EventCollector Id="CourseCollector" Name="AmitTech Course Collector">
      <BufferSize Value="64" />
      <Buffers Value="64" />
    </EventCollector>
    <EventProvider Id="CourseProvider"
      Name="{65FB74AD-4AC9-4CF2-86AC-42609C312501}" Level="5">
      <Keywords><Keyword Value="0x1" /></Keywords>
    </EventProvider>
    <Profile Id="Course.Verbose.File" Name="Course"
      Description="AmitTech application activity" LoggingMode="File" DetailLevel="Verbose">
      <Collectors>
        <EventCollectorId Value="CourseCollector">
          <EventProviders><EventProviderId Value="CourseProvider" /></EventProviders>
        </EventCollectorId>
      </Collectors>
    </Profile>
  </Profiles>
</WindowsPerformanceRecorder>

נבדוק תחילה בwpr -status שאין איסוף אחר שאנחנו עלולים לקטוע, ונפעיל הקלטה קצרה בסביבת המעבדה עם ההרשאות שהפרופיל דורש. הפרופיל המובנה מוסיף נתוני מערכת; הפרופיל שלנו מוסיף את משמעות העבודה.

wpr -status
wpr -start course.wprp!Course -start GeneralProfile -filemode
trace_lab.exe
wpr -stop course.etl

המצב filemode יכול לייצר קובץ שגדל לאורך האיסוף, ולכן נסיים את ההקלטה מיד אחרי התרחיש. נוסח הפרופיל והפקודות צריך להיבדק מול גרסת WPR של המעבדה. את בחירת הפרופילים ומצבי האיסוף מתאר ממשק הפקודות של WPR.

קוראים ציר זמן במקום לנחש

בWPA נסנן את Generic Events לפי provider וactivity ID. נבדוק את המרחק בין WorkStart, ComputeDone, WaitStart וWorkStop, ונשווה את אותם תחומים לגרף CPU.

הגרף CPU Usage Sampled עוזר להבין איפה נצרך זמן CPU לפי דגימות. הגרף CPU Usage Precise עוזר להבין scheduling והמתנות כאשר האירועים הנדרשים נאספו. פעילות שלא מופיעה בדגימות אינה בהכרח פעולה שלא רצה; ייתכן שהייתה קצרה ביחס לקצב הדגימה.

בקטע ההמתנה הthread אינו אמור לצרוך CPU כפי שצרך בזמן החישוב. אם סיום ההמתנה מתעכב מעבר לזמן המבוקש, נבדוק גם ready delay: ייתכן שהtimer הסתיים אבל הthread עדיין חיכה לתזמון. את הקשר בין שאלת האבחון לפרופיל ולגרף אפשר לראות במדריך WPR וWPA.

אירוע חסר אינו הוכחה לפעולה חסרה

יכול להיות שהprovider לא הופעל, שהkeyword לא נבחר, שהאירוע היה גדול מדי או שהsession איבד אירועים בגלל עומס. לפני שחושבים שיש Start בלי Stop כתוצאה מבאג ביישום, נבדוק את גבולות ההקלטה ואת נתוני האובדן.

נשמור אירועים קטנים עם שדות בעלי משמעות. לא נכניס body של בקשת רשת רק כדי שיהיה "יותר מידע". כשצריך לבנות מידע יקר לצורך event, אפשר לבדוק אם הprovider מופעל, אבל הבדיקה אינה מנגנון סנכרון או הבטחת מסירה. התיעוד של כתיבת TraceLogging מפרט גם מגבלות גודל ותיאור האירוע.

נמדוד את עומס העקיבה עצמה. אם הוספנו event לכל איטרציה, ייתכן ששינינו את התוכנית עד כדי כך שהבעיה המקורית נעלמה או הוחמרה. נתחיל מגבולות משמעותיים ונוסיף פירוט רק כאשר הוא מבדיל בין השערות.