Support for ETW events

Added support for ETW events to distinguish between various phases and to trace individual I/Os.
microsoft · Sep 27, 2018 · 6a28c0d · 6a28c0d
1 parent c59ffa7
commit 6a28c0d
Show file tree

Hide file tree

Showing 5 changed files with 189 additions and 7 deletions.
diff --git a/CmdRequestCreator/CmdRequestCreator.cpp b/CmdRequestCreator/CmdRequestCreator.cpp
@@ -152,6 +152,8 @@ int __cdecl main(int argc, const char* argv[])
         return 1;
     }
 
+    TraceLoggingRegister(g_hEtwProvider);
+
     //
     // call IO request generator
     //
@@ -179,6 +181,8 @@ int __cdecl main(int argc, const char* argv[])
         return 1;
     }
 
+    TraceLoggingUnregister(g_hEtwProvider);
+
     if( NULL != synch.hStartEvent )
     {
         CloseHandle(synch.hStartEvent);

diff --git a/Common/Common.cpp b/Common/Common.cpp
@@ -29,6 +29,10 @@ SOFTWARE.
 
 #include "Common.h"
 
+TRACELOGGING_DEFINE_PROVIDER(g_hEtwProvider,
+                             "Microsoft-Windows-DiskSpd", // {CA13DB84-D0A9-5145-FCA4-468DA92FDC2D}
+                             (0xca13db84, 0xd0a9, 0x5145, 0xfc, 0xa4, 0x46, 0x8d, 0xa9, 0x2f, 0xdc, 0x2d));
+
 SystemInformation g_SystemInformation;
 
 UINT64 PerfTimer::GetTime()
@@ -1058,3 +1062,47 @@ DWORD ThreadParameters::GetTotalRequestCount() const
 
     return cRequests;
 }
+
+void EtwResultParser::ParseResults(vector<Results> vResults)
+{
+    if (TraceLoggingProviderEnabled(g_hEtwProvider,
+                                    TRACE_LEVEL_NONE,
+                                    DISKSPD_TRACE_INFO))
+    {
+        for (size_t ullResults = 0; ullResults < vResults.size(); ullResults++)
+        {
+            const Results& results = vResults[ullResults];
+            for (size_t ullThread = 0; ullThread < results.vThreadResults.size(); ullThread++)
+            {
+                const ThreadResults& threadResults = results.vThreadResults[ullThread];
+                for (const auto& targetResults : threadResults.vTargetResults)
+                {
+                    if (targetResults.ullReadIOCount)
+                    {
+                        _WriteResults(IOOperation::ReadIO, targetResults, ullThread);
+                    }
+                    if (targetResults.ullWriteIOCount)
+                    {
+                        _WriteResults(IOOperation::WriteIO, targetResults, ullThread);
+                    }
+                }
+            }
+        }
+    }
+}
+
+void EtwResultParser::_WriteResults(IOOperation type, const TargetResults& targetResults, size_t ullThread)
+{
+    UINT64 ullIOCount = (type == IOOperation::ReadIO) ? targetResults.ullReadIOCount : targetResults.ullWriteIOCount;
+    UINT64 ullBytesCount = (type == IOOperation::ReadIO) ? targetResults.ullReadBytesCount : targetResults.ullWriteBytesCount;
+
+    TraceLoggingWrite(g_hEtwProvider,
+                      "Statistics",
+                      TraceLoggingLevel((TRACE_LEVEL_NONE)),
+                      TraceLoggingString((type == IOOperation::ReadIO) ? "Read" : "Write", "IO Type"),
+                      TraceLoggingUInt64(ullThread, "Thread"),
+                      TraceLoggingUInt64(ullBytesCount, "Bytes"),
+                      TraceLoggingUInt64(ullIOCount, "IO Count"),
+                      TraceLoggingString(targetResults.sPath.c_str(), "Path"),
+                      TraceLoggingUInt64(targetResults.ullFileSize, "File Size"));
+}
diff --git a/Common/Common.h b/Common/Common.h
@@ -30,6 +30,9 @@ SOFTWARE.
 #pragma once
 
 #include <windows.h>
+#include <TraceLoggingProvider.h>
+#include <TraceLoggingActivity.h>
+#include <evntrace.h>
 #include <ctime>
 #include <vector>
 #include <Winternl.h>   //ntdll.dll
@@ -40,6 +43,8 @@ SOFTWARE.
 
 using namespace std;
 
+TRACELOGGING_DECLARE_PROVIDER(g_hEtwProvider);
+
 // versioning material. for simplicity in consumption, please ensure that the date string
 // parses via the System.Datetime constructor as follows (in Powershell):
 //
@@ -64,6 +69,10 @@ using namespace std;
 #define DISKSPD_NUMERIC_VERSION_STRING DISKSPD_MAJORMINOR_VERSION_STR DISKSPD_REVISION DISKSPD_RELEASE_TAG
 #define DISKSPD_DATE_VERSION_STRING "2018/9/21"
 
+#define DISKSPD_TRACE_INFO      0x00000000
+#define DISKSPD_TRACE_RESERVED  0x00000001
+#define DISKSPD_TRACE_IO        0x00000100
+
 typedef void (WINAPI *PRINTF)(const char*, va_list);                            //function used for displaying formatted data (printf style)
 
 struct ETWEventCounters
@@ -1350,7 +1359,8 @@ class IORequest
         _ullStartTime(0),
         _ulRequestIndex(0xFFFFFFFF),
         _ullTotalWeight(0),
-        _fEqualWeights(true)
+        _fEqualWeights(true),
+        _ActivityId()
     {
         memset(&_overlapped, 0, sizeof(OVERLAPPED));
         _overlapped.Offset = 0xFFFFFFFF;
@@ -1412,6 +1422,9 @@ class IORequest
     void SetRequestIndex(UINT32 ulRequestIndex) { _ulRequestIndex = ulRequestIndex; }
     UINT32 GetRequestIndex() const { return _ulRequestIndex; }
 
+    void SetActivityId(GUID ActivityId) { _ActivityId = ActivityId; }
+    GUID GetActivityId() const { return _ActivityId; }
+
 private:
     OVERLAPPED _overlapped;
     vector<Target*> _vTargets;
@@ -1423,8 +1436,17 @@ class IORequest
     IOOperation _ioType;
     UINT64 _ullStartTime;
     UINT32 _ulRequestIndex;
+    GUID _ActivityId;
 };
 
+typedef struct _ACTIVITY_ID {
+    UINT32 Thread;
+    UINT32 Reserved;
+    UINT64 Count;
+} ACTIVITY_ID;
+
+C_ASSERT(sizeof(ACTIVITY_ID) == sizeof(GUID));
+
 class ThreadParameters
 {
 public:
@@ -1486,12 +1508,35 @@ class ThreadParameters
     DWORD GetTotalRequestCount() const;
     bool  InitializeMappedViewForTarget(Target& target, DWORD DesiredAccess);
 
+    GUID NextActivityId()
+    {
+        GUID ActivityId;
+        ACTIVITY_ID* ActivityGuid = (ACTIVITY_ID*)&ActivityId;
+
+        ActivityGuid->Thread = ulThreadNo;
+        ActivityGuid->Reserved = 0;
+        // The count is byte swapped so it's understandable in a trace.
+        ActivityGuid->Count = _byteswap_uint64(++_ullActivityCount);
+
+        return ActivityId;
+    }
+
 private:
     ThreadParameters(const ThreadParameters& T);
+    UINT64 _ullActivityCount;
 };
 
 class IResultParser
 {
 public:
     virtual string ParseResults(Profile& profile, const SystemInformation& system, vector<Results> vResults) = 0;
 };
+
+class EtwResultParser
+{
+public:
+    static void ParseResults(vector<Results> vResults);
+
+private:
+    static void _WriteResults(IOOperation type, const TargetResults& targetResults, size_t uThread);
+};
diff --git a/IORequestGenerator/IORequestGenerator.cpp b/IORequestGenerator/IORequestGenerator.cpp
@@ -748,15 +748,30 @@ static bool issueNextIO(ThreadParameters *p, IORequest *pIORequest, DWORD *pdwBy
     pOverlapped->Offset = li.LowPart;
     pOverlapped->OffsetHigh = li.HighPart;
 
-    printfv(p->pProfile->GetVerbose(), "t[%u:%u] new I/O op at %I64u (starting in block: %I64u)\n",
-        p->ulThreadNo,
-        iTarget,
-        li.QuadPart,
-        li.QuadPart / pTarget->GetBlockSizeInBytes());
-
     IOOperation readOrWrite = DecideIo(p->pRand, pTarget->GetWriteRatio());
     pIORequest->SetIoType(readOrWrite);
 
+    if (TraceLoggingProviderEnabled(g_hEtwProvider,
+                                    TRACE_LEVEL_VERBOSE,
+                                    DISKSPD_TRACE_IO))
+    {
+        GUID ActivityId = p->NextActivityId();
+        pIORequest->SetActivityId(ActivityId);
+
+        TraceLoggingWriteActivity(g_hEtwProvider,
+                                  "DiskSpd IO",
+                                  &ActivityId,
+                                  NULL,
+                                  TraceLoggingKeyword(DISKSPD_TRACE_IO),
+                                  TraceLoggingOpcode(EVENT_TRACE_TYPE_START),
+                                  TraceLoggingLevel(TRACE_LEVEL_VERBOSE),
+                                  TraceLoggingUInt32(p->ulThreadNo, "Thread"),
+                                  TraceLoggingString(readOrWrite == IOOperation::ReadIO ? "Read" : "Write", "IO Type"),
+                                  TraceLoggingUInt64(iTarget, "Target"),
+                                  TraceLoggingInt32(pTarget->GetBlockSizeInBytes(), "Block Size"),
+                                  TraceLoggingInt64(li.QuadPart, "Offset"));
+    }
+
     if (p->pTimeSpan->GetMeasureLatency())
     {
         pIORequest->SetStartTime(PerfTimer::GetTime());
@@ -841,6 +856,21 @@ static void completeIO(ThreadParameters *p, IORequest *pIORequest, DWORD dwBytes
     Target *pTarget = pIORequest->GetCurrentTarget();
     size_t iTarget = pTarget - &p->vTargets[0];
 
+    if (TraceLoggingProviderEnabled(g_hEtwProvider,
+                                    TRACE_LEVEL_VERBOSE,
+                                    DISKSPD_TRACE_IO))
+    {
+        GUID ActivityId = pIORequest->GetActivityId();
+
+        TraceLoggingWriteActivity(g_hEtwProvider,
+                                  "DiskSpd IO",
+                                  &ActivityId,
+                                  NULL,
+                                  TraceLoggingKeyword(DISKSPD_TRACE_IO),
+                                  TraceLoggingOpcode(EVENT_TRACE_TYPE_STOP),
+                                  TraceLoggingLevel(TRACE_LEVEL_VERBOSE));
+    }
+
     //check if I/O transferred all of the requested bytes
     if (dwBytesTransferred != pTarget->GetBlockSizeInBytes())
     {
@@ -2086,6 +2116,7 @@ bool IORequestGenerator::GenerateRequests(Profile& profile, IResultParser& resul
 
         // TODO: show results only for timespans that succeeded
         SystemInformation system;
+        EtwResultParser::ParseResults(vResults);
         string sResults = resultParser.ParseResults(profile, system, vResults);
         print("%s", sResults.c_str());
     }
@@ -2417,6 +2448,9 @@ bool IORequestGenerator::_GenerateRequestsForTimeSpan(const Profile& profile, co
     //
     if (timeSpan.GetWarmup() > 0)
     {
+        TraceLoggingActivity<g_hEtwProvider, DISKSPD_TRACE_INFO, TRACE_LEVEL_NONE> WarmActivity;
+        TraceLoggingWriteStart(WarmActivity, "Warm Up");
+
         if (bSynchStop)
         {
             assert(NULL != pSynch->hStopEvent);
@@ -2433,6 +2467,8 @@ bool IORequestGenerator::_GenerateRequestsForTimeSpan(const Profile& profile, co
         {
             Sleep(1000 * timeSpan.GetWarmup());
         }
+
+        TraceLoggingWriteStop(WarmActivity, "Warm Up");
     }
 
     if (!bBreak) // proceed only if user didn't break the test
@@ -2486,6 +2522,9 @@ bool IORequestGenerator::_GenerateRequestsForTimeSpan(const Profile& profile, co
             return false;
         }
 
+        TraceLoggingActivity<g_hEtwProvider, DISKSPD_TRACE_INFO, TRACE_LEVEL_NONE> RunActivity;
+        TraceLoggingWriteStart(RunActivity, "Run Time");
+
         //get cycle count (it will be used to calculate actual work time)
         ullStartTime = PerfTimer::GetTime();
 
@@ -2518,6 +2557,8 @@ bool IORequestGenerator::_GenerateRequestsForTimeSpan(const Profile& profile, co
         //get cycle count and perf counters
         ullTimeDiff = PerfTimer::GetTime() - ullStartTime;
 
+        TraceLoggingWriteStop(RunActivity, "Run Time");
+
         if (_GetSystemPerfInfo(&vPerfDone[0], g_SystemInformation.processorTopology._ulProcCount) == FALSE)
         {
             PrintError("Error getting performance counters\n");
@@ -2557,6 +2598,9 @@ bool IORequestGenerator::_GenerateRequestsForTimeSpan(const Profile& profile, co
     printfv(profile.GetVerbose(), "starting cool down...\n");
     if ((timeSpan.GetCooldown() > 0) && !bBreak)
     {
+        TraceLoggingActivity<g_hEtwProvider, DISKSPD_TRACE_INFO, TRACE_LEVEL_NONE> CoolActivity;
+        TraceLoggingWriteStart(CoolActivity, "Cool Down");
+
         if (bSynchStop)
         {
             assert(NULL != pSynch->hStopEvent);
@@ -2573,6 +2617,8 @@ bool IORequestGenerator::_GenerateRequestsForTimeSpan(const Profile& profile, co
         {
             Sleep(1000 * timeSpan.GetCooldown());
         }
+
+        TraceLoggingWriteStop(CoolActivity, "Cool Down");
     }
     printfv(profile.GetVerbose(), "finished test...\n");
 

diff --git a/diskspd.wprp b/diskspd.wprp
@@ -0,0 +1,39 @@
+<?xml version="1.0" encoding="utf-8"?>
+<WindowsPerformanceRecorder Author="Microsoft Corporation" Copyright="Microsoft Corporation. All rights reserved." Version="1.0">
+    <Profiles>
+        <EventCollector Id="EventCollectorDiskSpd" Name="WPR Event Collector">
+            <BufferSize Value="4"/>
+            <Buffers Value="1"/>
+        </EventCollector>
+        <EventCollector Id="EventCollectorDiskSpdIO" Name="WPR Event Collector">
+            <BufferSize Value="1024"/>
+            <Buffers Value="1000"/>
+        </EventCollector>
+        <EventProvider Id="EventProvider.Microsoft-Windows-DiskSpd" Name="CA13DB84-D0A9-5145-FCA4-468DA92FDC2D">
+            <Keywords>
+                <Keyword Value="0x1"/>
+            </Keywords>
+        </EventProvider>
+        <EventProvider Id="EventProvider.Microsoft-Windows-DiskSpd.Verbose" Name="CA13DB84-D0A9-5145-FCA4-468DA92FDC2D"/>
+        <Profile Id="DiskSpd.Light.Memory" Name="DiskSpd" Description="DiskSpd Storage Performance Tool" LoggingMode="Memory" DetailLevel="Light">
+            <Collectors>
+                <EventCollectorId Value="EventCollectorDiskSpd">
+                    <EventProviders>
+                        <EventProviderId Value="EventProvider.Microsoft-Windows-DiskSpd"/>
+                    </EventProviders>
+                </EventCollectorId>
+            </Collectors>
+        </Profile>
+        <Profile Id="DiskSpd.Light.File" Name="DiskSpd" Description="DiskSpd Storage Performance Tool" LoggingMode="File" DetailLevel="Light" Base="DiskSpd.Light.Memory"/>
+        <Profile Id="DiskSpd.Verbose.Memory" Name="DiskSpd" Description="DiskSpd Storage Performance Tool" LoggingMode="Memory" DetailLevel="Verbose">
+            <Collectors>
+                <EventCollectorId Value="EventCollectorDiskSpdIO">
+                    <EventProviders>
+                        <EventProviderId Value="EventProvider.Microsoft-Windows-DiskSpd.Verbose"/>
+                    </EventProviders>
+                </EventCollectorId>
+            </Collectors>
+        </Profile>
+        <Profile Id="DiskSpd.Verbose.File" Name="DiskSpd" Description="DiskSpd Storage Performance Tool" LoggingMode="File" DetailLevel="Verbose" Base="DiskSpd.Verbose.Memory"/>
+    </Profiles>
+</WindowsPerformanceRecorder>