Add utility to print ioctl times

Signed-off-by: Lukasz Jobczyk <lukasz.jobczyk@intel.com>

opencl/test/unit_test/linux/main_linux_dll.cpp

@@ -157,6 +157,91 @@ TEST(DrmTest, GivenSelectedExistingDeviceWhenOpenDirFailsThenRetryOpeningRenderD
     EXPECT_STREQ("00:03.0", hwDeviceIds[1]->getPciPath());
 }
 
+TEST(DrmTest, givenPrintIoctlTimesWhenCallIoctlThenStatisticsAreGathered) {
+    struct DrmMock : public Drm {
+        using Drm::ioctlStatistics;
+    };
+    ::testing::internal::CaptureStdout();
+
+    auto executionEnvironment = std::make_unique<ExecutionEnvironment>();
+    executionEnvironment->prepareRootDeviceEnvironments(1);
+    auto drm = static_cast<DrmMock *>(DrmWrap::createDrm(*executionEnvironment->rootDeviceEnvironments[0]).release());
+
+    DebugManagerStateRestore restorer;
+    DebugManager.flags.PrintIoctlTimes.set(true);
+
+    EXPECT_TRUE(drm->ioctlStatistics.empty());
+
+    int euTotal = 0u;
+    uint32_t contextId = 1u;
+
+    drm->getEuTotal(euTotal);
+    EXPECT_EQ(drm->ioctlStatistics.size(), 1u);
+
+    drm->getEuTotal(euTotal);
+    EXPECT_EQ(drm->ioctlStatistics.size(), 1u);
+
+    drm->setLowPriorityContextParam(contextId);
+    EXPECT_EQ(drm->ioctlStatistics.size(), 2u);
+
+    auto euTotalData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GETPARAM);
+    ASSERT_TRUE(euTotalData != drm->ioctlStatistics.end());
+    EXPECT_EQ(euTotalData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GETPARAM));
+    EXPECT_EQ(euTotalData->second.second, 2u);
+    EXPECT_NE(euTotalData->second.first, 0);
+    auto firstTime = euTotalData->second.first;
+
+    auto lowPriorityData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM);
+    ASSERT_TRUE(lowPriorityData != drm->ioctlStatistics.end());
+    EXPECT_EQ(lowPriorityData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM));
+    EXPECT_EQ(lowPriorityData->second.second, 1u);
+    EXPECT_NE(lowPriorityData->second.first, 0);
+
+    drm->getEuTotal(euTotal);
+    EXPECT_EQ(drm->ioctlStatistics.size(), 2u);
+
+    euTotalData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GETPARAM);
+    ASSERT_TRUE(euTotalData != drm->ioctlStatistics.end());
+    EXPECT_EQ(euTotalData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GETPARAM));
+    EXPECT_EQ(euTotalData->second.second, 3u);
+    EXPECT_NE(euTotalData->second.first, 0);
+
+    auto secondTime = euTotalData->second.first;
+    EXPECT_GT(secondTime, firstTime);
+
+    lowPriorityData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM);
+    ASSERT_TRUE(lowPriorityData != drm->ioctlStatistics.end());
+    EXPECT_EQ(lowPriorityData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM));
+    EXPECT_EQ(lowPriorityData->second.second, 1u);
+    EXPECT_NE(lowPriorityData->second.first, 0);
+
+    drm->destroyDrmContext(contextId);
+    EXPECT_EQ(drm->ioctlStatistics.size(), 3u);
+
+    euTotalData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GETPARAM);
+    ASSERT_TRUE(euTotalData != drm->ioctlStatistics.end());
+    EXPECT_EQ(euTotalData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GETPARAM));
+    EXPECT_EQ(euTotalData->second.second, 3u);
+    EXPECT_NE(euTotalData->second.first, 0);
+
+    lowPriorityData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM);
+    ASSERT_TRUE(lowPriorityData != drm->ioctlStatistics.end());
+    EXPECT_EQ(lowPriorityData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GEM_CONTEXT_SETPARAM));
+    EXPECT_EQ(lowPriorityData->second.second, 1u);
+    EXPECT_NE(lowPriorityData->second.first, 0);
+
+    auto destroyData = drm->ioctlStatistics.find(DRM_IOCTL_I915_GEM_CONTEXT_DESTROY);
+    ASSERT_TRUE(destroyData != drm->ioctlStatistics.end());
+    EXPECT_EQ(destroyData->first, static_cast<unsigned long>(DRM_IOCTL_I915_GEM_CONTEXT_DESTROY));
+    EXPECT_EQ(destroyData->second.second, 1u);
+    EXPECT_NE(destroyData->second.first, 0);
+
+    delete drm;
+
+    std::string output = ::testing::internal::GetCapturedStdout();
+    EXPECT_STRNE(output.c_str(), "");
+}
+
 TEST(DrmTest, GivenSelectedNonExistingDeviceWhenOpenDirFailsThenRetryOpeningRenderDevicesAndNoDevicesAreCreated) {
     VariableBackup<decltype(openFull)> backupOpenFull(&openFull);
     VariableBackup<decltype(failOnOpenDir)> backupOpenDir(&failOnOpenDir, true);

opencl/test/unit_test/test_files/igdrcl.config

@@ -219,6 +219,7 @@ EnableHostPointerImport = -1
 EnableHostUsmSupport = -1
 ForceBtpPrefetchMode = -1
 OverrideProfilingTimerResolution = -1
+PrintIoctlTimes = 0
 UpdateTaskCountFromWait = -1
 PreferCopyEngineForCopyBufferToBuffer = -1
 EnableStaticPartitioning = -1

shared/source/debug_settings/debug_variables_base.inl

@@ -128,6 +128,7 @@ DECLARE_DEBUG_VARIABLE(bool, PrintBOBindingResult, false, "tracks the result of
 DECLARE_DEBUG_VARIABLE(bool, PrintTagAllocationAddress, false, "Print tag allocation address for each engine")
 DECLARE_DEBUG_VARIABLE(bool, ProvideVerboseImplicitFlush, false, "provides verbose messages about implicit flush mechanism")
 DECLARE_DEBUG_VARIABLE(bool, PrintBlitDispatchDetails, false, "Print blit dispatch details")
+DECLARE_DEBUG_VARIABLE(bool, PrintIoctlTimes, false, "Print ioctl times")
 
 /*PERFORMANCE FLAGS*/
 DECLARE_DEBUG_VARIABLE(bool, DisableZeroCopyForBuffers, false, "When active all buffer allocations will not share memory with CPU.")

shared/source/os_interface/linux/drm_neo.cpp

@@ -69,7 +69,31 @@ int Drm::ioctl(unsigned long request, void *arg) {
     int ret;
     SYSTEM_ENTER();
     do {
+        auto measureTime = DebugManager.flags.PrintIoctlTimes.get();
+        std::chrono::steady_clock::time_point start;
+        std::chrono::steady_clock::time_point end;
+
+        if (measureTime) {
+            start = std::chrono::steady_clock::now();
+        }
+
         ret = SysCalls::ioctl(getFileDescriptor(), request, arg);
+
+        if (measureTime) {
+            end = std::chrono::steady_clock::now();
+            auto elapsedTime = std::chrono::duration_cast<std::chrono::nanoseconds>(end - start).count();
+
+            std::pair<long long, uint64_t> ioctlData{};
+            auto ioctlDataIt = this->ioctlStatistics.find(request);
+            if (ioctlDataIt != this->ioctlStatistics.end()) {
+                ioctlData = ioctlDataIt->second;
+            }
+
+            ioctlData.first += elapsedTime;
+            ioctlData.second++;
+
+            this->ioctlStatistics[request] = ioctlData;
+        }
     } while (ret == -1 && (errno == EINTR || errno == EAGAIN || errno == EBUSY));
     SYSTEM_LEAVE(request);
     return ret;
@@ -442,6 +466,19 @@ std::unique_ptr<uint8_t[]> Drm::query(uint32_t queryId, uint32_t queryItemFlags,
     return data;
 }
 
+void Drm::printIoctlStatistics() {
+    if (!DebugManager.flags.PrintIoctlTimes.get()) {
+        return;
+    }
+
+    printf("\n                 --- Ioctls statistics ---\n");
+    printf("        Request  Total time(ns)      Count   Avg time per ioctl\n");
+    for (const auto &ioctlData : this->ioctlStatistics) {
+        printf("%15lu %15llu %10lu %20f\n", ioctlData.first, ioctlData.second.first, ioctlData.second.second, ioctlData.second.first / static_cast<double>(ioctlData.second.second));
+    }
+    printf("\n");
+}
+
 bool Drm::createVirtualMemoryAddressSpace(uint32_t vmCount) {
     for (auto i = 0u; i < vmCount; i++) {
         uint32_t id = i;
@@ -501,6 +538,7 @@ bool Drm::translateTopologyInfo(const drm_i915_query_topology_info *queryTopolog
 
 Drm::~Drm() {
     destroyVirtualMemoryAddressSpace();
+    this->printIoctlStatistics();
 }
 
 } // namespace NEO

shared/source/os_interface/linux/drm_neo.h

@@ -27,6 +27,7 @@
 #include <string>
 #include <sys/ioctl.h>
 #include <unistd.h>
+#include <unordered_map>
 #include <vector>
 
 struct GT_SYSTEM_INFO;
@@ -214,6 +215,9 @@ class Drm {
 
     StackVec<uint32_t, size_t(ResourceClass::MaxSize)> classHandles;
 
+    std::unordered_map<unsigned long, std::pair<long long, uint64_t>> ioctlStatistics;
+    void printIoctlStatistics();
+
 #pragma pack(1)
     struct PCIConfig {
         uint16_t VendorID;