[PTI-LIB] Reduce L0 usage for device tracing (#449)

- call less zeDeviceGetGlobalTimestamps
- rely on gpu frequency as a constant when convert gpu cycles to cpu
- use of gpu ze..mem..fill for tracing mem ops on gpu in local mode
- adjust tests correspondingly
---------
Signed-off-by: jfedorov <julia.fedorova@intel.com>

Author: jfedorov

sdk/src/levelzero/ze_collector.h

@@ -42,6 +42,7 @@
 #include "utils.h"
 #include "ze_event_cache.h"
 #include "ze_local_collection_helpers.h"
+#include "ze_timer_helper.h"
 #include "ze_utils.h"
 #include "ze_wrappers.h"
 
@@ -64,6 +65,10 @@ struct ZeInstanceData {
 
 inline thread_local ZeInstanceData ze_instance_data;
 
+// Used for CPU/GPU sync points. See description to ZeCollector::GetDeviceTimestamps function
+inline thread_local std::map<ze_device_handle_t, std::unique_ptr<CPUGPUTimeInterpolationHelper>>
+    timer_helpers_;
+
 struct ZeKernelGroupSize {
   uint32_t x;
   uint32_t y;
@@ -140,6 +145,7 @@ struct ZeDeviceDescriptor {
   uint64_t device_time_origin = 0;
   uint64_t device_timer_frequency = 0;
   uint64_t device_timer_mask = 0;
+  uint64_t device_sync_delta = 50'000'000ULL;  // 50ms
   ze_driver_handle_t driver = nullptr;
   ze_context_handle_t context = nullptr;
   ze_pci_ext_properties_t pci_properties{};
@@ -247,6 +253,74 @@ class ZeCollector {
   enum class ZeCollectionMode { Full = 0, Hybrid = 1, Local = 2 };
   enum class ZeCollectionState { Normal = 0, Abnormal = 1 };
 
+  /**
+   * \internal
+   * \brief Returns the current device timestamps, CPU in nanoceconds and GPU in ticks
+   *
+   * \param [in] device - the device to get the timestamps from
+   * \param [out] host_time - the CPU time in nanoseconds
+   * \param [out] device_time - the GPU time in ticks
+   * \return ZE_RESULT_SUCCESS on success, ZE_RESULT_ERROR on failure
+   *
+   * Previously, zeDeviceGetGlobalTimestamps was called every time CPU and GPU timestamps
+   * needed to be synced (via utils::ze::GetDeviceTimestamps(device, host_time, device_time);)
+   * GPU cycles were then converted to CPU (aka host) timescale.
+   * However, zeDeviceGetGlobalTimestamps has a high latency,
+   * so it is not sutable for frequent calls (e.g. each dozen of micro-secs), especially in profiler
+   *
+   * The current implementation calls zeDeviceGetGlobalTimestamp less often:
+   * once in ~ dozens (or hundreds) of milliseconds
+   * (see CPUGPUTimeInterpolationHelper.delta) - for sync CPU/GPU point
+   * per thread per device. (per thread - to avoid any synchronization between threads)
+   * The delta between sycn points is selected  empirically, but it is important keep in mind that
+   * on systems with 32 GPU time counter - this counter would wrap around every few seconds.
+   * The delta should be less than this wrap around time.
+   *
+   * Another change - the GPU timer frequency is not interpolated anymore but rather
+   * taken from the device descriptor. This assumes that it is constant.
+   *
+   * The function is called synchroniously in a profiled thread, once per device.
+   *
+   * InterpolationHelper keeps the sync point from some recent past.
+   * If CPU time, from the recent sych point, exceeded delta - makes a new sych point.
+   * The sync point data are returned to a caller. The caller ueses the sync point data
+   * to convert GPU cycles to CPU time or do other ops with them.
+   *
+   */
+  ze_result_t GetDeviceTimestamps(ze_device_handle_t device, uint64_t* host_time,
+                                  uint64_t* device_time) {
+    PTI_ASSERT(device != nullptr);
+    PTI_ASSERT(host_time != nullptr);
+    PTI_ASSERT(device_time != nullptr);
+    if (timer_helpers_.find(device) == timer_helpers_.end()) {
+      timer_helpers_[device] = std::make_unique<CPUGPUTimeInterpolationHelper>(
+          device, device_descriptors_[device].device_timer_frequency,
+          device_descriptors_[device].device_timer_mask,
+          device_descriptors_[device].device_sync_delta);
+    }
+    uint64_t anchor_host_time = 0;
+    uint64_t anchor_device_time = 0;
+    auto helper = timer_helpers_[device].get();
+    uint64_t current_host_time = utils::GetTime();
+    if (current_host_time - helper->cpu_timestamp_ > helper->delta_) {
+      ze_result_t res =
+          utils::ze::GetDeviceTimestamps(device, &anchor_host_time, &anchor_device_time);
+      PTI_ASSERT(res == ZE_RESULT_SUCCESS);
+      helper->cpu_timestamp_ = anchor_host_time;
+      helper->gpu_timestamp_ = anchor_device_time;
+    } else {
+      anchor_host_time = helper->cpu_timestamp_;
+      anchor_device_time = helper->gpu_timestamp_;
+    }
+    current_host_time = utils::GetTime();
+    uint64_t current_device_time = anchor_device_time + ((current_host_time - anchor_host_time) /
+                                                         timer_helpers_[device]->coeff_);
+
+    *host_time = current_host_time;
+    *device_time = current_device_time;
+    return ZE_RESULT_SUCCESS;
+  }
+
   static ZeCollectionMode SelectZeCollectionMode(bool introspection_capable, bool& disabled_mode,
                                                  bool& hybrid_mode) {
     ZeCollector::ZeCollectionMode mode = ZeCollectionMode::Full;
@@ -375,6 +449,7 @@ class ZeCollector {
         swap_event_pool_(512),
         startstop_mode_changer(this) {
     CreateDeviceMap();
+    UpdateDeviceSyncDelta();
     ze_result_t res = l0_wrapper_.InitDynamicTracingWrappers();
     if (ZE_RESULT_SUCCESS == res) {
       loader_dynamic_tracing_capable_ = true;
@@ -450,6 +525,27 @@ class ZeCollector {
     }
   }
 
+  void UpdateDeviceSyncDelta() {
+    // in future we can try make it per device
+    SPDLOG_DEBUG("In {}", __FUNCTION__);
+    uint64_t delta = 0;
+    auto env_string = utils::GetEnv("PTI_DEVICE_SYNC_DELTA");
+    SPDLOG_INFO("Checking DeviceSyncDelta by PTI_DEVICE_SYNC_DELTA environment variable");
+    if (!env_string.empty()) {
+      try {
+        delta = std::stoll(env_string);
+        SPDLOG_INFO("\tPTI_DEVICE_SYNC_DELTA is {} ns, will use it in device tracing", delta);
+      } catch (std::invalid_argument const& /*ex*/) {
+        delta = CPUGPUTimeInterpolationHelper::kSycnDeltaDefault;  // fallback to default
+      } catch (std::out_of_range const& /*ex*/) {
+        delta = CPUGPUTimeInterpolationHelper::kSycnDeltaDefault;  // fallback to default
+      }
+    }
+    for (auto& [device, descriptor] : device_descriptors_) {
+      descriptor.device_sync_delta = delta;
+    }
+  }
+
   void MarkIntrospection() {
     const auto drivers = utils::ze::GetDriverList();
     for (auto const driver : drivers) {
@@ -502,21 +598,6 @@ class ZeCollector {
     }
 
     desc.pci_properties = pci_device_properties;
-    uint64_t host_time = 0;
-    uint64_t ticks = 0;
-    uint64_t device_time = 0;
-
-    overhead::Init();
-    status = zeDeviceGetGlobalTimestamps(device, &host_time, &ticks);
-    overhead_fini(zeDeviceGetGlobalTimestamps_id);
-    PTI_ASSERT(status == ZE_RESULT_SUCCESS);
-
-    device_time = ticks & desc.device_timer_mask;
-    if (desc.device_timer_frequency) {
-      device_time = device_time * NSEC_IN_SEC / desc.device_timer_frequency;
-    }
-    desc.host_time_origin = host_time;
-    desc.device_time_origin = device_time;
     return desc;
   }
 
@@ -1033,10 +1114,7 @@ class ZeCollector {
       // as all command lists submitted to the execution into queue - they are not immediate
       PTI_ASSERT(!info.immediate);
       PTI_ASSERT(info.device != nullptr);
-      overhead::Init();
-      ze_result_t status =
-          zeDeviceGetGlobalTimestamps(info.device, &host_time_sync, &device_time_sync);
-      overhead_fini(zeDeviceGetGlobalTimestamps_id);
+      ze_result_t status = GetDeviceTimestamps(info.device, &host_time_sync, &device_time_sync);
       PTI_ASSERT(status == ZE_RESULT_SUCCESS);
 
       const std::lock_guard<std::mutex> lock(lock_);
@@ -1434,9 +1512,7 @@ class ZeCollector {
     uint64_t host_timestamp = 0;
     uint64_t device_timestamp = 0;  // in ticks
 
-    overhead::Init();
-    ze_result_t status = zeDeviceGetGlobalTimestamps(device, &host_timestamp, &device_timestamp);
-    overhead_fini(zeDeviceGetGlobalTimestamps_id);
+    ze_result_t status = collector->GetDeviceTimestamps(device, &host_timestamp, &device_timestamp);
     PTI_ASSERT(status == ZE_RESULT_SUCCESS);
 
     ze_instance_data.timestamp_host = host_timestamp;
@@ -1539,13 +1615,12 @@ class ZeCollector {
       } else if (command->props.type == KernelCommandType::kMemory) {
         SPDLOG_TRACE("\t\tDevices in Memory command: src: {}, dst {}",
                      (void*)command->props.src_device, (void*)command->props.dst_device);
-        bool is_two_devices =
-            (command->props.src_device != nullptr && command->props.dst_device != nullptr) ? true
-                                                                                           : false;
-        append_res = A2AppendBridgeMemoryCopyOrFill(
-            command->command_list, command->event_self, command->event_swap, command->props.dst,
-            command->props.src, command->props.bytes_transferred, command->props.value_size,
-            is_two_devices);
+
+        auto buffer = device_buffer_pool_.GetBuffers(command->context, command->device);
+        PTI_ASSERT(buffer != nullptr);
+        append_res = A2AppendBridgeMemoryCopyOrFillEx(command->command_list, command->event_self,
+                                                      command->event_swap, buffer,
+                                                      device_buffer_pool_.buffer_size_);
       } else if (command->props.type == KernelCommandType::kCommand) {
         append_res =
             A2AppendBridgeBarrier(command->command_list, command->event_self, command->event_swap);
@@ -2397,6 +2472,7 @@ class ZeCollector {
   std::map<ze_command_queue_handle_t, ZeCommandQueue> command_queues_;
 
   A2BridgeKernelPool bridge_kernel_pool_;
+  A2DeviceBufferPool device_buffer_pool_;
   A2EventPool swap_event_pool_;
 
   Level0Wrapper l0_wrapper_;

sdk/src/levelzero/ze_local_collection_helpers.h

@@ -85,13 +85,42 @@ bool A2AppendBridgeMemoryCopyOrFill(ze_command_list_handle_t command_list,
   return result == ZE_RESULT_SUCCESS;
 }
 
+/**
+ * \internal
+ * ze..MemoryFill still has smaller latency than ze..MemoryCopy. So we use it to lower the overhead
+ */
+bool A2AppendBridgeMemoryCopyOrFillEx(ze_command_list_handle_t command_list,
+                                      ze_event_handle_t signal_event, ze_event_handle_t wait_event,
+                                      void* dst, size_t size) {
+  PTI_ASSERT(command_list != nullptr);
+  PTI_ASSERT(wait_event != nullptr);
+
+  SPDLOG_TRACE(
+      " --- In: {}, CmdList: {}, Signal event: {}, Wait event: {}, dst: {}, \
+                size: {}",
+      __FUNCTION__, static_cast<void*>(command_list), static_cast<void*>(signal_event),
+      static_cast<void*>(wait_event), dst, size);
+
+  uint32_t count = 1;
+  ze_result_t result = ZE_RESULT_SUCCESS;
+  SPDLOG_TRACE("\tAppending Bridge MemoryFill dst: {}, size: {}", dst, size);
+  uint32_t pattern = 0;
+  overhead::Init();
+  result = zeCommandListAppendMemoryFill(command_list, dst, &pattern, sizeof(pattern), size,
+                                         signal_event, count, &wait_event);
+  overhead_fini(zeCommandListAppendMemoryFill_id);
+  SPDLOG_DEBUG("\t\tBridge MemOp Append MemoryFill result: {}", (uint32_t)result);
+  return result == ZE_RESULT_SUCCESS;
+}
+
 bool A2AppendBridgeBarrier(ze_command_list_handle_t command_list, ze_event_handle_t signal_event,
                            ze_event_handle_t wait_event) {
   PTI_ASSERT(command_list != nullptr);
   PTI_ASSERT(wait_event != nullptr);
 
   SPDLOG_DEBUG(" --- In: {}, CmdList: {}, Signal event: {}, Wait event: {}", __FUNCTION__,
-               (void*)command_list, (void*)signal_event, (void*)wait_event);
+               static_cast<void*>(command_list), static_cast<void*>(signal_event),
+               static_cast<void*>(wait_event));
 
   uint32_t count = 1;
   overhead::Init();
@@ -425,4 +454,35 @@ std::vector<uint16_t> A2BridgeKernelPool::kernel_binary_{
     0x7274, 0x0079, 0x0000, 0x0013, 0x0002, 0x0002, 0x0000, 0x0021, 0x0003, 0x0003, 0x0000,
     0x0002, 0x0000, 0x0036, 0x0005, 0x0002, 0x0000, 0x0004, 0x0000, 0x0000, 0x0000, 0x0003,
     0x0000, 0x00f8, 0x0002, 0x0005, 0x0000, 0x00fd, 0x0001, 0x0038, 0x0001};
+
+class A2DeviceBufferPool {
+ public:
+  A2DeviceBufferPool() {}
+
+  void* GetBuffers(ze_context_handle_t context, ze_device_handle_t device) {
+    PTI_ASSERT(context != nullptr);
+    PTI_ASSERT(device != nullptr);
+    std::unique_lock lock(mutex_);
+    if (buffer_map_.find(std::pair(context, device)) == buffer_map_.end()) {
+      void* buff = nullptr;
+      ze_device_mem_alloc_desc_t alloc_desc = {ZE_STRUCTURE_TYPE_DEVICE_MEM_ALLOC_DESC, nullptr, 0,
+                                               0};
+      overhead::Init();
+      ze_result_t status = zeMemAllocDevice(context, &alloc_desc, buffer_size_, 64, device, &buff);
+      overhead_fini(zeMemAllocDevice_id);
+      PTI_ASSERT(status == ZE_RESULT_SUCCESS);
+      buffer_map_[std::pair(context, device)] = buff;
+      SPDLOG_TRACE("Device buffers created in {} for context: {}, device: {}, buff {}, size: {} ",
+                   __FUNCTION__, static_cast<void*>(context), static_cast<void*>(device),
+                   static_cast<void*>(buff), buffer_size_);
+    }
+    return buffer_map_[std::pair(context, device)];
+  }
+  const size_t buffer_size_ = 64;
+
+ private:
+  std::mutex mutex_;
+  std::map<std::pair<ze_context_handle_t, ze_device_handle_t>, void*> buffer_map_;
+};
+
 #endif  // PTI_TOOLS_ZE_LOCAL_COLLECTION_HELPERS_H_

sdk/src/levelzero/ze_timer_helper.h

@@ -0,0 +1,41 @@
+//
+//==============================================================
+// Copyright (C) Intel Corporation
+//
+// SPDX-License-Identifier: MIT
+// =============================================================
+
+#ifndef PTI_TOOLS_ZE_TIMER_HELPER_H_
+#define PTI_TOOLS_ZE_TIMER_HELPER_H_
+
+#include <level_zero/ze_api.h>
+
+#include "pti_assert.h"
+
+struct CPUGPUTimeInterpolationHelper {
+  const static uint64_t kSycnDeltaDefault = 50'000'000;
+  ze_device_handle_t device_;
+  uint32_t gpu_freq_;
+  uint64_t gpu_timer_mask_;
+  uint64_t cpu_timestamp_;
+  uint64_t gpu_timestamp_;
+  uint64_t delta_ = kSycnDeltaDefault;
+  uint64_t coeff_;
+  CPUGPUTimeInterpolationHelper(ze_device_handle_t device, uint32_t gpu_freq,
+                                uint64_t gpu_timer_mask, uint64_t sync_delta)
+      : device_(device),
+        gpu_freq_(gpu_freq),
+        gpu_timer_mask_(gpu_timer_mask),
+        cpu_timestamp_(0),
+        gpu_timestamp_(0) {
+    PTI_ASSERT(device_ != nullptr);
+    PTI_ASSERT(gpu_freq != 0ULL);
+    PTI_ASSERT(gpu_timer_mask != 0ULL);
+    if (sync_delta != 0ULL) {
+      delta_ = sync_delta;
+    }
+    coeff_ = 1'000'000'000 / gpu_freq_;
+  }
+};
+
+#endif  // PTI_TOOLS_ZE_TIMER_HELPER_H_

sdk/src/utils/ze_utils.h

@@ -361,15 +361,15 @@ inline std::string GetKernelName(ze_kernel_handle_t kernel, bool demangle = fals
   return std::string(name.begin(), name.end() - 1);
 }
 
-inline void GetDeviceTimestamps(ze_device_handle_t device, uint64_t* host_timestamp,
-                                uint64_t* device_timestamp) {
+inline ze_result_t GetDeviceTimestamps(ze_device_handle_t device, uint64_t* host_timestamp,
+                                       uint64_t* device_timestamp) {
   PTI_ASSERT(device != nullptr);
   PTI_ASSERT(host_timestamp != nullptr);
   PTI_ASSERT(device_timestamp != nullptr);
   overhead::Init();
   ze_result_t status = zeDeviceGetGlobalTimestamps(device, host_timestamp, device_timestamp);
   overhead_fini(zeDeviceGetGlobalTimestamps_id);
-  PTI_ASSERT(status == ZE_RESULT_SUCCESS);
+  return status;
 }
 
 inline uint64_t GetDeviceTimerFrequency(ze_device_handle_t device) {

sdk/test/CMakeLists.txt

@@ -316,22 +316,34 @@ if(HAVE_SYCL)
     PROPERTIES LABELS "functional")
 
   RequirePythonInterp()
+
+  set(L0_OVERHEAD_THRESHOLD 17)
+  set(LINK_OVERHEAD_THRESHOLD 3)
+  if (WIN32)
+    # Timer we use on Windows (as of implementation 02.14.25) has 100 ns resolution,
+    # due to that some functions latency measured as zero, so accumulated overhead is less than on Linux
+    set(L0_OVERHEAD_THRESHOLD 11)
+    # For some reason, on Windows, the link overhead is bigger than on Linux
+    # Need to investigate it - look into UR and XPTI
+    set(LINK_OVERHEAD_THRESHOLD 5)
+  endif()
+
   add_test(
     NAME perf-profiling-overhead
     COMMAND
-      ${Python_EXECUTABLE} ${PROJECT_SOURCE_DIR}/test/perf_test.py "${PTI_TEST_BIN_DIR}" 66 profiled
+      ${Python_EXECUTABLE} ${PROJECT_SOURCE_DIR}/test/perf_test.py "${PTI_TEST_BIN_DIR}" 60 profiled
   )
 
   add_test(
     NAME perf-link-overhead
     COMMAND
-      ${Python_EXECUTABLE} ${PROJECT_SOURCE_DIR}/test/perf_test.py "${PTI_TEST_BIN_DIR}" 8 linkonly
+      ${Python_EXECUTABLE} ${PROJECT_SOURCE_DIR}/test/perf_test.py "${PTI_TEST_BIN_DIR}" ${LINK_OVERHEAD_THRESHOLD} linkonly
   )
 
   add_test(
     NAME perf-overhead-view
     COMMAND
-      ${Python_EXECUTABLE} ${PROJECT_SOURCE_DIR}/test/perf_test.py "${PTI_TEST_BIN_DIR}" 50 overhead
+      ${Python_EXECUTABLE} ${PROJECT_SOURCE_DIR}/test/perf_test.py "${PTI_TEST_BIN_DIR}" ${L0_OVERHEAD_THRESHOLD} overhead
   )