Create Wddm residency logging

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

shared/source/os_interface/windows/CMakeLists.txt

@@ -50,6 +50,8 @@ set(NEO_CORE_OS_INTERFACE_WINDOWS
   ${CMAKE_CURRENT_SOURCE_DIR}/wddm/wddm.cpp
   ${CMAKE_CURRENT_SOURCE_DIR}/wddm/wddm.h
   ${CMAKE_CURRENT_SOURCE_DIR}/wddm/wddm_defs.h
+  ${CMAKE_CURRENT_SOURCE_DIR}/wddm/wddm_residency_logger.h
+  ${CMAKE_CURRENT_SOURCE_DIR}/wddm/wddm_residency_logger_defs.h
   ${CMAKE_CURRENT_SOURCE_DIR}/wddm_memory_manager.cpp
   ${CMAKE_CURRENT_SOURCE_DIR}/wddm_memory_manager.h
   ${CMAKE_CURRENT_SOURCE_DIR}${BRANCH_DIR_SUFFIX}/wddm_memory_manager_allocate_in_device_pool.cpp

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

@@ -23,6 +23,7 @@
 #include "shared/source/os_interface/windows/os_interface.h"
 #include "shared/source/os_interface/windows/sys_calls.h"
 #include "shared/source/os_interface/windows/wddm/wddm_interface.h"
+#include "shared/source/os_interface/windows/wddm/wddm_residency_logger.h"
 #include "shared/source/os_interface/windows/wddm_allocation.h"
 #include "shared/source/os_interface/windows/wddm_engine_mapper.h"
 #include "shared/source/os_interface/windows/wddm_residency_allocations_container.h"
@@ -177,6 +178,7 @@ bool Wddm::createPagingQueue() {
         pagingQueue = CreatePagingQueue.hPagingQueue;
         pagingQueueSyncObject = CreatePagingQueue.hSyncObject;
         pagingFenceAddress = reinterpret_cast<UINT64 *>(CreatePagingQueue.FenceValueCPUVirtualAddress);
+        createPagingFenceLogger();
     }
 
     return status == STATUS_SUCCESS;
@@ -335,12 +337,14 @@ bool Wddm::evict(const D3DKMT_HANDLE *handleList, uint32_t numOfHandles, uint64_
     return status == STATUS_SUCCESS;
 }
 
-bool Wddm::makeResident(const D3DKMT_HANDLE *handles, uint32_t count, bool cantTrimFurther, uint64_t *numberOfBytesToTrim) {
+bool Wddm::makeResident(const D3DKMT_HANDLE *handles, uint32_t count, bool cantTrimFurther, uint64_t *numberOfBytesToTrim, size_t totalSize) {
     NTSTATUS status = STATUS_SUCCESS;
     D3DDDI_MAKERESIDENT makeResident = {0};
     UINT priority = 0;
     bool success = false;
 
+    perfLogResidencyReportAllocations(residencyLogger.get(), count, totalSize);
+
     makeResident.AllocationList = handles;
     makeResident.hPagingQueue = pagingQueue;
     makeResident.NumAllocations = count;
@@ -349,14 +353,16 @@ bool Wddm::makeResident(const D3DKMT_HANDLE *handles, uint32_t count, bool cantT
     makeResident.Flags.MustSucceed = cantTrimFurther ? 1 : 0;
 
     status = getGdi()->makeResident(&makeResident);
-
     if (status == STATUS_PENDING) {
+        perfLogResidencyMakeResident(residencyLogger.get(), true);
         updatePagingFenceValue(makeResident.PagingFenceValue);
         success = true;
     } else if (status == STATUS_SUCCESS) {
+        perfLogResidencyMakeResident(residencyLogger.get(), false);
         success = true;
     } else {
         DEBUG_BREAK_IF(true);
+        perfLogResidencyTrimRequired(residencyLogger.get(), makeResident.NumBytesToTrim);
         if (numberOfBytesToTrim != nullptr)
             *numberOfBytesToTrim = makeResident.NumBytesToTrim;
         UNRECOVERABLE_IF(cantTrimFurther);
@@ -683,10 +689,10 @@ bool Wddm::openNTHandle(HANDLE handle, WddmAllocation *alloc) {
     return true;
 }
 
-void *Wddm::lockResource(const D3DKMT_HANDLE &handle, bool applyMakeResidentPriorToLock) {
+void *Wddm::lockResource(const D3DKMT_HANDLE &handle, bool applyMakeResidentPriorToLock, size_t size) {
 
     if (applyMakeResidentPriorToLock) {
-        temporaryResources->makeResidentResource(handle);
+        temporaryResources->makeResidentResource(handle, size);
     }
 
     NTSTATUS status = STATUS_UNSUCCESSFUL;
@@ -1001,8 +1007,11 @@ bool Wddm::configureDeviceAddressSpace() {
 }
 
 void Wddm::waitOnPagingFenceFromCpu() {
+    perfLogStartWaitTime(residencyLogger.get());
     while (currentPagingFenceValue > *getPagingFenceAddress())
-        ;
+        perfLogResidencyEnteredWait(residencyLogger.get());
+
+    perfLogResidencyWaitPagingeFenceLog(residencyLogger.get());
 }
 
 void Wddm::setGmmInputArg(void *args) {
@@ -1021,4 +1030,10 @@ WddmVersion Wddm::getWddmVersion() {
     }
 }
 
+void Wddm::createPagingFenceLogger() {
+    if (DebugManager.flags.WddmResidencyLogger.get()) {
+        residencyLogger = std::make_unique<WddmResidencyLogger>(device, pagingFenceAddress);
+    }
+}
+
 } // namespace NEO

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

@@ -13,6 +13,7 @@
 #include "shared/source/os_interface/os_context.h"
 #include "shared/source/os_interface/windows/hw_device_id.h"
 #include "shared/source/os_interface/windows/wddm/wddm_defs.h"
+#include "shared/source/os_interface/windows/wddm/wddm_residency_logger.h"
 #include "shared/source/utilities/spinlock.h"
 
 #include "sku_info.h"
@@ -54,7 +55,7 @@ class Wddm {
     bool init();
 
     MOCKABLE_VIRTUAL bool evict(const D3DKMT_HANDLE *handleList, uint32_t numOfHandles, uint64_t &sizeToTrim);
-    MOCKABLE_VIRTUAL bool makeResident(const D3DKMT_HANDLE *handles, uint32_t count, bool cantTrimFurther, uint64_t *numberOfBytesToTrim);
+    MOCKABLE_VIRTUAL bool makeResident(const D3DKMT_HANDLE *handles, uint32_t count, bool cantTrimFurther, uint64_t *numberOfBytesToTrim, size_t totalSize);
     MOCKABLE_VIRTUAL bool mapGpuVirtualAddress(Gmm *gmm, D3DKMT_HANDLE handle, D3DGPU_VIRTUAL_ADDRESS minimumAddress, D3DGPU_VIRTUAL_ADDRESS maximumAddress, D3DGPU_VIRTUAL_ADDRESS preferredAddress, D3DGPU_VIRTUAL_ADDRESS &gpuPtr);
     bool mapGpuVirtualAddress(AllocationStorageData *allocationStorageData);
     MOCKABLE_VIRTUAL D3DGPU_VIRTUAL_ADDRESS reserveGpuVirtualAddress(D3DGPU_VIRTUAL_ADDRESS minimumAddress, D3DGPU_VIRTUAL_ADDRESS maximumAddress, D3DGPU_SIZE_T size);
@@ -67,7 +68,7 @@ class Wddm {
     MOCKABLE_VIRTUAL bool destroyAllocations(const D3DKMT_HANDLE *handles, uint32_t allocationCount, D3DKMT_HANDLE resourceHandle);
     MOCKABLE_VIRTUAL bool openSharedHandle(D3DKMT_HANDLE handle, WddmAllocation *alloc);
     bool openNTHandle(HANDLE handle, WddmAllocation *alloc);
-    MOCKABLE_VIRTUAL void *lockResource(const D3DKMT_HANDLE &handle, bool applyMakeResidentPriorToLock);
+    MOCKABLE_VIRTUAL void *lockResource(const D3DKMT_HANDLE &handle, bool applyMakeResidentPriorToLock, size_t size);
     MOCKABLE_VIRTUAL void unlockResource(const D3DKMT_HANDLE &handle);
     MOCKABLE_VIRTUAL void kmDafLock(D3DKMT_HANDLE handle);
     MOCKABLE_VIRTUAL bool isKmDafEnabled() const { return featureTable->ftrKmdDaf; }
@@ -184,6 +185,7 @@ class Wddm {
     bool destroyDevice();
     void getDeviceState();
     void handleCompletion(OsContextWin &osContext);
+    MOCKABLE_VIRTUAL void createPagingFenceLogger();
 
     static GetSystemInfoFcn getSystemInfo;
     static VirtualFreeFcn virtualFreeFnc;
@@ -192,5 +194,6 @@ class Wddm {
     std::unique_ptr<KmDafListener> kmDafListener;
     std::unique_ptr<WddmInterface> wddmInterface;
     std::unique_ptr<WddmResidentAllocationsContainer> temporaryResources;
+    std::unique_ptr<WddmResidencyLogger> residencyLogger;
 };
 } // namespace NEO

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

@@ -11,4 +11,11 @@ namespace NEO {
 Wddm *Wddm::createWddm(std::unique_ptr<HwDeviceId> hwDeviceId, RootDeviceEnvironment &rootDeviceEnvironment) {
     return new Wddm(std::move(hwDeviceId), rootDeviceEnvironment);
 }
+
+namespace ResLog {
+fopenFuncPtr fopenPtr = &fopen;
+vfprintfFuncPtr vfprintfPtr = &vfprintf;
+fcloseFuncPtr fclosePtr = &fclose;
+} // namespace ResLog
+
 } // namespace NEO

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

@@ -0,0 +1,141 @@
+/*
+ * Copyright (C) 2020 Intel Corporation
+ *
+ * SPDX-License-Identifier: MIT
+ *
+ */
+
+#pragma once
+#include "shared/source/helpers/debug_helpers.h"
+#include "shared/source/os_interface/windows/wddm/wddm_defs.h"
+#include "shared/source/os_interface/windows/wddm/wddm_residency_logger_defs.h"
+
+#include <chrono>
+#include <sstream>
+
+namespace NEO {
+
+class WddmResidencyLogger {
+  public:
+    WddmResidencyLogger(D3DKMT_HANDLE device, VOID *fenceValueCpuVirtualAddress) {
+        std::stringstream id;
+        id << std::hex;
+        id << "device-0x" << device << "_"
+           << "pfencecpu-0x" << fenceValueCpuVirtualAddress;
+        std::stringstream filename;
+        filename << "pagingfence_" << id.str() << ".log";
+        pagingLog = ResLog::fopenPtr(filename.str().c_str(), "at");
+        UNRECOVERABLE_IF(pagingLog == nullptr);
+        fPagingLog("%s\n", id.str().c_str());
+    }
+
+    ~WddmResidencyLogger() {
+        ResLog::fclosePtr(pagingLog);
+    }
+
+    void reportAllocations(uint32_t count, size_t size) {
+        fPagingLog("residency for: handles %u size %zu\n", count, size);
+    }
+
+    void makeResidentLog(bool pendingMakeResident) {
+        this->pendingMakeResident = pendingMakeResident;
+        makeResidentCall = true;
+        pendingTime = std::chrono::high_resolution_clock::now();
+    }
+
+    void startWaitTime() {
+        waitStartTime = std::chrono::high_resolution_clock::now();
+    }
+
+    void enteredWait() {
+        enterWait = true;
+    }
+
+    void waitPagingeFenceLog() {
+        endTime = std::chrono::high_resolution_clock::now();
+
+        int64_t timeDiff = 0;
+
+        timeDiff = std::chrono::duration_cast<std::chrono::microseconds>(endTime - pendingTime).count();
+        fPagingLog("makeResidentCall: %x pending return: %x delta time makeResident: %lld\n",
+                   makeResidentCall,
+                   pendingMakeResident,
+                   timeDiff);
+
+        timeDiff = std::chrono::duration_cast<std::chrono::microseconds>(endTime - waitStartTime).count();
+        fPagingLog("waiting: %x delta time wait loop: %lld\n", enterWait, timeDiff);
+
+        makeResidentCall = false;
+        enterWait = false;
+    }
+
+    void trimRequired(UINT64 numBytesToTrim) {
+        fPagingLog("trimming required: bytes to trim: %llu\n", numBytesToTrim);
+    }
+
+  protected:
+    void fPagingLog(char const *const formatStr, ...) {
+        va_list args;
+        va_start(args, formatStr);
+        ResLog::vfprintfPtr(pagingLog, formatStr, args);
+        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;
+};
+
+inline void perfLogResidencyMakeResident(WddmResidencyLogger *log, bool pendingMakeResident) {
+    if (residencyLoggingAvailable) {
+        if (log) {
+            log->makeResidentLog(pendingMakeResident);
+        }
+    }
+}
+
+inline void perfLogResidencyReportAllocations(WddmResidencyLogger *log, uint32_t count, size_t size) {
+    if (residencyLoggingAvailable) {
+        if (log) {
+            log->reportAllocations(count, size);
+        }
+    }
+}
+
+inline void perfLogStartWaitTime(WddmResidencyLogger *log) {
+    if (residencyLoggingAvailable) {
+        if (log) {
+            log->startWaitTime();
+        }
+    }
+}
+
+inline void perfLogResidencyEnteredWait(WddmResidencyLogger *log) {
+    if (residencyLoggingAvailable) {
+        if (log) {
+            log->enteredWait();
+        }
+    }
+}
+
+inline void perfLogResidencyWaitPagingeFenceLog(WddmResidencyLogger *log) {
+    if (residencyLoggingAvailable) {
+        if (log) {
+            log->waitPagingeFenceLog();
+        }
+    }
+}
+
+inline void perfLogResidencyTrimRequired(WddmResidencyLogger *log, UINT64 numBytesToTrim) {
+    if (residencyLoggingAvailable) {
+        if (log) {
+            log->trimRequired(numBytesToTrim);
+        }
+    }
+}
+
+} // namespace NEO

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

@@ -0,0 +1,28 @@
+/*
+ * Copyright (C) 2020 Intel Corporation
+ *
+ * SPDX-License-Identifier: MIT
+ *
+ */
+
+#pragma once
+#include <cstdarg>
+#include <cstdio>
+
+namespace NEO {
+namespace ResLog {
+using fopenFuncPtr = FILE *(*)(const char *, const char *);
+using vfprintfFuncPtr = int (*)(FILE *, char const *const formatStr, va_list arg);
+using fcloseFuncPtr = int (*)(FILE *);
+
+extern fopenFuncPtr fopenPtr;
+extern vfprintfFuncPtr vfprintfPtr;
+extern fcloseFuncPtr fclosePtr;
+} // namespace ResLog
+
+#if defined(_RELEASE_INTERNAL) || (_DEBUG)
+constexpr bool residencyLoggingAvailable = true;
+#else
+constexpr bool residencyLoggingAvailable = false;
+#endif
+} // namespace NEO

shared/source/os_interface/windows/wddm_memory_manager.cpp

@@ -298,7 +298,7 @@ void WddmMemoryManager::removeAllocationFromHostPtrManager(GraphicsAllocation *g
 
 void *WddmMemoryManager::lockResourceImpl(GraphicsAllocation &graphicsAllocation) {
     auto &wddmAllocation = static_cast<WddmAllocation &>(graphicsAllocation);
-    return getWddm(graphicsAllocation.getRootDeviceIndex()).lockResource(wddmAllocation.getDefaultHandle(), wddmAllocation.needsMakeResidentBeforeLock);
+    return getWddm(graphicsAllocation.getRootDeviceIndex()).lockResource(wddmAllocation.getDefaultHandle(), wddmAllocation.needsMakeResidentBeforeLock, wddmAllocation.getAlignedSize());
 }
 void WddmMemoryManager::unlockResourceImpl(GraphicsAllocation &graphicsAllocation) {
     auto &wddmAllocation = static_cast<WddmAllocation &>(graphicsAllocation);

shared/source/os_interface/windows/wddm_memory_operations_handler.cpp

@@ -23,9 +23,11 @@ MemoryOperationsStatus WddmMemoryOperationsHandler::makeResident(ArrayRef<Graphi
     constexpr uint32_t stackAllocations = 64;
     constexpr uint32_t stackHandlesCount = NEO::maxFragmentsCount * EngineLimits::maxHandleCount * stackAllocations;
     StackVec<D3DKMT_HANDLE, stackHandlesCount> handlesForResidency;
+    size_t totalSize = 0;
 
     for (const auto &allocation : gfxAllocations) {
         WddmAllocation *wddmAllocation = reinterpret_cast<WddmAllocation *>(allocation);
+        totalSize += wddmAllocation->getAlignedSize();
 
         if (wddmAllocation->fragmentsStorage.fragmentCount > 0) {
             for (uint32_t allocationId = 0; allocationId < wddmAllocation->fragmentsStorage.fragmentCount; allocationId++) {
@@ -39,7 +41,7 @@ MemoryOperationsStatus WddmMemoryOperationsHandler::makeResident(ArrayRef<Graphi
             totalHandlesCount += wddmAllocation->getNumHandles();
         }
     }
-    return residentAllocations->makeResidentResources(handlesForResidency.begin(), totalHandlesCount);
+    return residentAllocations->makeResidentResources(handlesForResidency.begin(), totalHandlesCount, totalSize);
 }
 
 MemoryOperationsStatus WddmMemoryOperationsHandler::evict(GraphicsAllocation &gfxAllocation) {

shared/source/os_interface/windows/wddm_residency_allocations_container.cpp

@@ -56,17 +56,17 @@ MemoryOperationsStatus WddmResidentAllocationsContainer::evictResources(const D3
     return MemoryOperationsStatus::SUCCESS;
 }
 
-MemoryOperationsStatus WddmResidentAllocationsContainer::makeResidentResource(const D3DKMT_HANDLE &handle) {
-    return makeResidentResources(&handle, 1u);
+MemoryOperationsStatus WddmResidentAllocationsContainer::makeResidentResource(const D3DKMT_HANDLE &handle, size_t size) {
+    return makeResidentResources(&handle, 1u, size);
 }
 
-MemoryOperationsStatus WddmResidentAllocationsContainer::makeResidentResources(const D3DKMT_HANDLE *handles, const uint32_t count) {
+MemoryOperationsStatus WddmResidentAllocationsContainer::makeResidentResources(const D3DKMT_HANDLE *handles, const uint32_t count, size_t size) {
     bool madeResident = false;
-    while (!(madeResident = wddm->makeResident(handles, count, false, nullptr))) {
+    while (!(madeResident = wddm->makeResident(handles, count, false, nullptr, size))) {
         if (evictAllResources() == MemoryOperationsStatus::SUCCESS) {
             continue;
         }
-        if (!wddm->makeResident(handles, count, false, nullptr)) {
+        if (!wddm->makeResident(handles, count, false, nullptr, size)) {
             DEBUG_BREAK_IF(true);
             return MemoryOperationsStatus::OUT_OF_MEMORY;
         };

shared/source/os_interface/windows/wddm_residency_allocations_container.h

@@ -25,8 +25,8 @@ class WddmResidentAllocationsContainer {
     MOCKABLE_VIRTUAL MemoryOperationsStatus evictAllResources();
     MOCKABLE_VIRTUAL MemoryOperationsStatus evictResource(const D3DKMT_HANDLE &handle);
     MemoryOperationsStatus evictResources(const D3DKMT_HANDLE *handles, const uint32_t count);
-    MOCKABLE_VIRTUAL MemoryOperationsStatus makeResidentResource(const D3DKMT_HANDLE &handle);
-    MemoryOperationsStatus makeResidentResources(const D3DKMT_HANDLE *handles, const uint32_t count);
+    MOCKABLE_VIRTUAL MemoryOperationsStatus makeResidentResource(const D3DKMT_HANDLE &handle, size_t size);
+    MemoryOperationsStatus makeResidentResources(const D3DKMT_HANDLE *handles, const uint32_t count, size_t size);
     MOCKABLE_VIRTUAL void removeResource(const D3DKMT_HANDLE &handle);
 
   protected:

shared/source/os_interface/windows/wddm_residency_controller.cpp

@@ -301,6 +301,7 @@ bool WddmResidencyController::makeResidentResidencyAllocations(const ResidencyCo
     const size_t residencyCount = allocationsForResidency.size();
     std::unique_ptr<D3DKMT_HANDLE[]> handlesForResidency(new D3DKMT_HANDLE[residencyCount * maxFragmentsCount * EngineLimits::maxHandleCount]);
     uint32_t totalHandlesCount = 0;
+    size_t totalSize = 0;
 
     auto lock = this->acquireLock();
 
@@ -310,6 +311,7 @@ bool WddmResidencyController::makeResidentResidencyAllocations(const ResidencyCo
         WddmAllocation *allocation = static_cast<WddmAllocation *>(allocationsForResidency[i]);
         ResidencyData &residencyData = allocation->getResidencyData();
         bool fragmentResidency[3] = {false, false, false};
+        totalSize += allocation->getAlignedSize();
 
         DBG_LOG(ResidencyDebugEnable, "Residency:", __FUNCTION__, "allocation =", allocation, residencyData.resident[osContextId] ? "resident" : "not resident");
 
@@ -337,7 +339,7 @@ bool WddmResidencyController::makeResidentResidencyAllocations(const ResidencyCo
     bool result = true;
     if (totalHandlesCount) {
         uint64_t bytesToTrim = 0;
-        while ((result = wddm.makeResident(handlesForResidency.get(), totalHandlesCount, false, &bytesToTrim)) == false) {
+        while ((result = wddm.makeResident(handlesForResidency.get(), totalHandlesCount, false, &bytesToTrim, totalSize)) == false) {
             this->setMemoryBudgetExhausted();
             const bool trimmingDone = this->trimResidencyToBudget(bytesToTrim);
             if (!trimmingDone) {
@@ -346,7 +348,7 @@ bool WddmResidencyController::makeResidentResidencyAllocations(const ResidencyCo
                     continue;
                 }
                 DEBUG_BREAK_IF(evictionStatus != MemoryOperationsStatus::MEMORY_NOT_FOUND);
-                result = wddm.makeResident(handlesForResidency.get(), totalHandlesCount, true, &bytesToTrim);
+                result = wddm.makeResident(handlesForResidency.get(), totalHandlesCount, true, &bytesToTrim, totalSize);
                 break;
             }
         }