Improve Wddm Residency logging

Related-To: NEO-4338

Change-Id: I5fefa1da6188befe27928b6bbfcc7bac89a6aef2
Signed-off-by: Zbigniew Zdanowicz <zbigniew.zdanowicz@intel.com>

shared/source/direct_submission/direct_submission_hw.inl

@@ -371,7 +371,7 @@ bool DirectSubmissionHw<GfxFamily>::dispatchCommandBuffer(BatchBuffer &batchBuff
     cpuCachelineFlush(semaphorePtr, MemoryConstants::cacheLineSize);
     currentQueueWorkCount++;
 
-    //whem ring buffer is not started at init or not restarted periodically
+    //when ring buffer is not started at init or being restarted
     if (!ringStart) {
         size_t submitSize = dispatchSize;
         if (buffersSwitched) {

shared/source/os_interface/windows/wddm/wddm.cpp

@@ -347,11 +347,11 @@ bool Wddm::makeResident(const D3DKMT_HANDLE *handles, uint32_t count, bool cantT
 
     status = getGdi()->makeResident(&makeResident);
     if (status == STATUS_PENDING) {
-        perfLogResidencyMakeResident(residencyLogger.get(), true);
+        perfLogResidencyMakeResident(residencyLogger.get(), true, makeResident.PagingFenceValue);
         updatePagingFenceValue(makeResident.PagingFenceValue);
         success = true;
     } else if (status == STATUS_SUCCESS) {
-        perfLogResidencyMakeResident(residencyLogger.get(), false);
+        perfLogResidencyMakeResident(residencyLogger.get(), false, makeResident.PagingFenceValue);
         success = true;
     } else {
         DEBUG_BREAK_IF(true);
@@ -1000,11 +1000,11 @@ bool Wddm::configureDeviceAddressSpace() {
 }
 
 void Wddm::waitOnPagingFenceFromCpu() {
-    perfLogStartWaitTime(residencyLogger.get());
+    perfLogStartWaitTime(residencyLogger.get(), currentPagingFenceValue);
     while (currentPagingFenceValue > *getPagingFenceAddress())
         perfLogResidencyEnteredWait(residencyLogger.get());
 
-    perfLogResidencyWaitPagingeFenceLog(residencyLogger.get());
+    perfLogResidencyWaitPagingeFenceLog(residencyLogger.get(), *getPagingFenceAddress());
 }
 
 void Wddm::setGmmInputArg(void *args) {

shared/source/os_interface/windows/wddm/wddm_residency_logger.h

@@ -37,24 +37,30 @@ class WddmResidencyLogger {
         fPagingLog("residency for: handles %u size %zu\n", count, size);
     }
 
-    void makeResidentLog(bool pendingMakeResident) {
+    void makeResidentLog(bool pendingMakeResident, UINT64 makeResidentPagingFence) {
         this->pendingMakeResident = pendingMakeResident;
+        this->makeResidentPagingFence = makeResidentPagingFence;
         makeResidentCall = true;
         pendingTime = std::chrono::high_resolution_clock::now();
     }
 
-    void startWaitTime() {
+    MOCKABLE_VIRTUAL void startWaitTime(UINT64 startWaitPagingFence) {
         waitStartTime = std::chrono::high_resolution_clock::now();
+        this->startWaitPagingFence = startWaitPagingFence;
     }
 
     void enteredWait() {
         enterWait = true;
     }
 
-    void waitPagingeFenceLog() {
+    void waitPagingeFenceLog(UINT64 stopWaitPagingFence) {
         endTime = std::chrono::high_resolution_clock::now();
 
         int64_t timeDiff = 0;
+        fPagingLog("makeResidentPagingFence: %x startWaitPagingFence: %x stopWaitPagingFence: %lld\n",
+                   makeResidentPagingFence,
+                   startWaitPagingFence,
+                   stopWaitPagingFence);
 
         timeDiff = std::chrono::duration_cast<std::chrono::microseconds>(endTime - pendingTime).count();
         fPagingLog("makeResidentCall: %x pending return: %x delta time makeResident: %lld\n",
@@ -67,6 +73,8 @@ class WddmResidencyLogger {
 
         makeResidentCall = false;
         enterWait = false;
+        makeResidentPagingFence = 0;
+        startWaitPagingFence = 0;
     }
 
     void trimRequired(UINT64 numBytesToTrim) {
@@ -81,19 +89,24 @@ class WddmResidencyLogger {
         va_end(args);
     }
 
-    bool pendingMakeResident = false;
-    bool enterWait = false;
-    bool makeResidentCall = false;
-    FILE *pagingLog = nullptr;
     std::chrono::high_resolution_clock::time_point pendingTime;
     std::chrono::high_resolution_clock::time_point waitStartTime;
     std::chrono::high_resolution_clock::time_point endTime;
+
+    UINT64 makeResidentPagingFence = 0ull;
+    UINT64 startWaitPagingFence = 0ull;
+
+    FILE *pagingLog = nullptr;
+
+    bool pendingMakeResident = false;
+    bool enterWait = false;
+    bool makeResidentCall = false;
 };
 
-inline void perfLogResidencyMakeResident(WddmResidencyLogger *log, bool pendingMakeResident) {
+inline void perfLogResidencyMakeResident(WddmResidencyLogger *log, bool pendingMakeResident, UINT64 makeResidentPagingFence) {
     if (residencyLoggingAvailable) {
         if (log) {
-            log->makeResidentLog(pendingMakeResident);
+            log->makeResidentLog(pendingMakeResident, makeResidentPagingFence);
         }
     }
 }
@@ -106,10 +119,10 @@ inline void perfLogResidencyReportAllocations(WddmResidencyLogger *log, uint32_t
     }
 }
 
-inline void perfLogStartWaitTime(WddmResidencyLogger *log) {
+inline void perfLogStartWaitTime(WddmResidencyLogger *log, UINT64 startWaitPagingFence) {
     if (residencyLoggingAvailable) {
         if (log) {
-            log->startWaitTime();
+            log->startWaitTime(startWaitPagingFence);
         }
     }
 }
@@ -122,10 +135,10 @@ inline void perfLogResidencyEnteredWait(WddmResidencyLogger *log) {
     }
 }
 
-inline void perfLogResidencyWaitPagingeFenceLog(WddmResidencyLogger *log) {
+inline void perfLogResidencyWaitPagingeFenceLog(WddmResidencyLogger *log, UINT64 stopWaitPagingFence) {
     if (residencyLoggingAvailable) {
         if (log) {
-            log->waitPagingeFenceLog();
+            log->waitPagingeFenceLog(stopWaitPagingFence);
         }
     }
 }

shared/test/unit_test/os_interface/windows/CMakeLists.txt

@@ -8,6 +8,7 @@ set(NEO_CORE_OS_INTERFACE_TESTS_WINDOWS
   ${CMAKE_CURRENT_SOURCE_DIR}/CMakeLists.txt
   ${CMAKE_CURRENT_SOURCE_DIR}/gdi_interface_tests.cpp
   ${CMAKE_CURRENT_SOURCE_DIR}/gmm_helper_tests_win.cpp
+  ${CMAKE_CURRENT_SOURCE_DIR}/mock_gdi_interface.cpp
   ${CMAKE_CURRENT_SOURCE_DIR}/mock_gdi_interface.h
   ${CMAKE_CURRENT_SOURCE_DIR}/wddm_preemption_tests.cpp
 )

shared/test/unit_test/os_interface/windows/mock_gdi_interface.cpp

@@ -0,0 +1,12 @@
+/*
+ * Copyright (C) 2020 Intel Corporation
+ *
+ * SPDX-License-Identifier: MIT
+ *
+ */
+
+#include "shared/test/unit_test/os_interface/windows/mock_gdi_interface.h"
+
+namespace NEO {
+UINT64 MockGdi::pagingFenceReturnValue = 0x3ull;
+} // namespace NEO

shared/test/unit_test/os_interface/windows/mock_gdi_interface.h

@@ -8,6 +8,8 @@
 #pragma once
 #include "shared/source/os_interface/windows/gdi_interface.h"
 
+#include "opencl/test/unit_test/mock_gdi/mock_gdi.h"
+
 namespace NEO {
 
 class MockGdi : public Gdi {
@@ -17,6 +19,7 @@ class MockGdi : public Gdi {
     }
     ~MockGdi(){};
 
+    static UINT64 pagingFenceReturnValue;
     bool nonZeroNumBytesToTrim = false;
 
     void setNonZeroNumBytesToTrimInEvict() {
@@ -25,11 +28,12 @@ class MockGdi : public Gdi {
     }
 
     static NTSTATUS __stdcall makeResidentMock(IN OUT D3DDDI_MAKERESIDENT *arg) {
-        if (arg->AllocationList[0] == static_cast<D3DKMT_HANDLE>(-1)) {
+        if (arg->AllocationList[0] == INVALID_HANDLE) {
             return STATUS_SEVERITY_ERROR;
         }
         getMakeResidentArg() = *arg;
-        return 0;
+        arg->PagingFenceValue = pagingFenceReturnValue;
+        return STATUS_PENDING;
     }
 
     static NTSTATUS __stdcall evictMock(IN D3DKMT_EVICT *arg) {