device timing histograms (#440)

* initial version of device timing histograms

* fix Linux build

* c++20 fixes, final cleanup

* move the number of histogram bins

Author: bashbaug

docs/controls.md

@@ -299,6 +299,10 @@ If set to a nonzero value, the Intercept Layer for OpenCL Applications will incl
 
 If set to a nonzero value, the Intercept Layer for OpenCL Applications will add event profiling to track the minimum, maximum, and average device time for each OpenCL command. This operation may be fairly intrusive and may have side effects; in particular it forces all command queues to be created with PROFILING\_ENABLED and may increment the reference count for application events. When the process exits, this information will be included in the file "clIntercept\_report.txt".
 
+##### `DevicePerformanceTimingHistogram` (bool)
+
+If set to a nonzero value, the Intercept Layer for OpenCL Applications will report a histogram of device times in addition to the table of device times for each OpenCL command.
+
 ##### `DevicePerformanceTimeKernelInfoTracking` (bool)
 
 If set to a nonzero value, the Intercept Layer for OpenCL Applications will distinguish between OpenCL NDRange kernels using information such as the kernel's Preferred Work Group Size Multiple (AKA SIMD size).

intercept/src/chrometracer.cpp

@@ -202,13 +202,13 @@ void CChromeTracer::writeDeviceTiming(
 }
 
 // Shared lookup tables:
-static const size_t cNumStates = 3;
-static const char* colours[cNumStates] = {
+static constexpr size_t cNumStates = 3;
+static constexpr const char* colours[cNumStates] = {
     "thread_state_runnable",
     "cq_build_running",
     "thread_state_iowait"
 };
-static const char* suffixes[cNumStates] = {
+static constexpr const char* suffixes[cNumStates] = {
     "(Queued)",
     "(Submitted)",
     "(Execution)"

intercept/src/controls.h

@@ -58,6 +58,7 @@ CLI_CONTROL_SEPARATOR( Performance Timing Controls: )
 CLI_CONTROL( bool,          HostPerformanceTiming,                  false, "If set to a nonzero value, the Intercept Layer for OpenCL Applications will track the minimum, maximum, and average host CPU time for each OpenCL entry point.  When the process exits, this information will be included in the file \"clIntercept_report.txt\"." )
 CLI_CONTROL( bool,          ToolOverheadTiming,                     true,  "If set to a nonzero value, the Intercept Layer for OpenCL Applications will include some types of tool overhead in timing reports and some types of logging." )
 CLI_CONTROL( bool,          DevicePerformanceTiming,                false, "If set to a nonzero value, the Intercept Layer for OpenCL Applications will add event profiling to track the minimum, maximum, and average device time for each OpenCL command. This operation may be fairly intrusive and may have side effects; in particular it forces all command queues to be created with PROFILING_ENABLED and may increment the reference count for application events. When the process exits, this information will be included in the file \"clIntercept_report.txt\"." )
+CLI_CONTROL( bool,          DevicePerformanceTimingHistogram,       false, "If set to a nonzero value, the Intercept Layer for OpenCL Applications will report a histogram of device times in addition to the table of device times for each OpenCL command." )
 CLI_CONTROL( bool,          DevicePerformanceTimeKernelInfoTracking,false, "If set to a nonzero value, the Intercept Layer for OpenCL Applications will distinguish between OpenCL NDRange kernels using information such as the kernel's Preferred Work Group Size Multiple (AKA SIMD size)." )
 CLI_CONTROL( bool,          DevicePerformanceTimeGWOTracking,       false, "If set to a nonzero value, the Intercept Layer for OpenCL Applications will distinguish between OpenCL NDRange kernels with different global work offsets for the purpose of device performance timing." )
 CLI_CONTROL( bool,          DevicePerformanceTimeGWSTracking,       false, "If set to a nonzero value, the Intercept Layer for OpenCL Applications will distinguish between OpenCL NDRange kernels with different global work sizes for the purpose of device performance timing." )

intercept/src/intercept.cpp

@@ -136,7 +136,7 @@ CLIntercept::CLIntercept( void* pGlobalData )
 
     m_LoggedCLInfo = false;
 
-    m_EnqueueCounter.store(0, std::memory_order::memory_order_relaxed);
+    m_EnqueueCounter.store(0, std::memory_order_relaxed);
 
     m_EventsChromeTraced = 0;
     m_ProgramNumber = 0;
@@ -957,6 +957,55 @@ void CLIntercept::writeReport(
         }
     }
 
+    if( config().DevicePerformanceTimingHistogram )
+    {
+        CDeviceTimingHistogramMap::const_iterator id = m_DeviceTimingHistogramMap.begin();
+        while( id != m_DeviceTimingHistogramMap.end() )
+        {
+            const cl_device_id  device = (*id).first;
+            const SDeviceTimingHistogram& histogram = (*id).second;
+
+            const SDeviceInfo&  deviceInfo = m_DeviceInfoMap[device];
+
+            os << std::endl << "Device Performance Timing Histogram for " << deviceInfo.NameForReport << ":" << std::endl;
+
+            uint32_t total = 0;
+            for( uint32_t bin = 0; bin < SDeviceTimingHistogram::cNumBins; bin++ )
+            {
+                total += histogram.Bins[bin];
+            }
+
+            os << std::endl << "Total Events: " << total << std::endl << std::endl;
+
+            for( uint32_t bin = 0; bin < SDeviceTimingHistogram::cNumBins; bin++ )
+            {
+                if( bin == SDeviceTimingHistogram::cNumBins - 1 )
+                {
+                    os << " >= ";
+                }
+                else
+                {
+                    os << "  < ";
+                }
+                const uint32_t count = histogram.Bins[bin];
+                os  << std::setw(9) << (1ULL << bin) << " ns: " << std::setw(9) << count << " : ";
+
+                uint32_t dots = static_cast<uint32_t>( 64.0f * count / total );
+                if( count != 0 && dots == 0 )
+                {
+                    dots++;
+                }
+                for( uint32_t d = 0; d < dots; d++ )
+                {
+                    os << "*";
+                }
+                os << std::endl;
+            }
+
+            ++id;
+        }
+    }
+
 #if defined(USE_MDAPI)
     if( config().DevicePerfCounterEventBasedSampling )
     {
@@ -6626,6 +6675,20 @@ void CLIntercept::checkTimingEvents()
                                 commandStart,
                                 commandEnd );
                         }
+
+                        if( config().DevicePerformanceTimingHistogram )
+                        {
+                            SDeviceTimingHistogram& histogram = m_DeviceTimingHistogramMap[node.Device];
+
+                            constexpr uint32_t cNumBins = SDeviceTimingHistogram::cNumBins;
+                            const uint32_t count = Utils::CountLeadingZeroes( delta );
+                            const uint32_t bin = count == 64 ? 0 :
+                                count <= ( 64 - cNumBins ) ? cNumBins - 1 :
+                                64 - count;
+
+                            CLI_ASSERT( bin < cNumBins );
+                            histogram.Bins[bin]++;
+                        }
                     }
                 }
 

intercept/src/intercept.h

@@ -1183,6 +1183,18 @@ class CLIntercept
     typedef std::map< cl_device_id, CDeviceTimingStatsMap > CDeviceDeviceTimingStatsMap;
     CDeviceDeviceTimingStatsMap m_DeviceTimingStatsMap;
 
+    // These structures define a mapping between a device ID and histogram
+    // bins for kernel execution on that device.
+
+    struct SDeviceTimingHistogram
+    {
+        constexpr static uint32_t cNumBins = 30;
+        uint32_t    Bins[cNumBins] = { 0 };
+    };
+
+    typedef std::map< cl_device_id, SDeviceTimingHistogram > CDeviceTimingHistogramMap;
+    CDeviceTimingHistogramMap   m_DeviceTimingHistogramMap;
+
     // This defines a mapping between the kernel handle and information
     // about the kernel.
 

intercept/src/utils.cpp

@@ -10,6 +10,18 @@
 #include <fstream>
 #include <string>
 
+#ifdef __cpp_lib_bitops
+#include <bit>
+#endif
+
+#if defined(_WIN32) && !defined(__MINGW32__)
+#include <intrin.h>
+#endif
+
+#ifndef __has_builtin
+#define __has_builtin(x)    0
+#endif
+
 namespace Utils
 {
 
@@ -55,4 +67,47 @@ std::string GetUniqueFileName(const std::string& fileName)
     return newFileName;
 }
 
+uint32_t CountLeadingZeroes(uint64_t value)
+{
+#ifdef __cpp_lib_bitops
+    return std::countl_zero(value);
+#elif defined(_WIN32) && !defined(__MINGW32__)
+    if( value == 0 ) { return 64; }
+
+    unsigned long index;
+
+    if( value < 1ULL << 32 )
+    {
+        _BitScanReverse(&index, static_cast<unsigned long>(value));
+        return 63 - index;
+    }
+
+    value >>= 32;
+    _BitScanReverse(&index, static_cast<unsigned long>(value));
+    return 31 - index;
+#elif __has_builtin(__builtin_clz)
+    if( value == 0 ) { return 64; }
+
+    if( value < 1ULL << 32 )
+    {
+        return 32 + __builtin_clz(static_cast<uint32_t>(value));
+    }
+
+    value >>= 32;
+    return __builtin_clz(static_cast<uint32_t>(value));
+#else
+    if( value == 0 ) { return 64; }
+
+    uint32_t count = 0;
+    uint64_t mask = 1ULL << 63;
+    while( (value & mask) == 0 )
+    {
+        count++;
+        mask >>= 1;
+    }
+
+    return count;
+#endif
 }
+
+} // namespace Utils

intercept/src/utils.h

@@ -6,11 +6,13 @@
 
 #pragma once
 
+#include <cstdint>
 #include <string>
 
 namespace Utils
 {
 
 std::string GetUniqueFileName(const std::string& fileName);
+uint32_t CountLeadingZeroes(uint64_t value);
 
 }