[SYCL] Fix event profiling for command_submit in L0 and other backends (#7526)

According to SYCL 2020 specification, the timeframe to calculated
command submission time:
> ... always some time after the [command group function
object](https://registry.khronos.org/SYCL/specs/sycl-2020/html/sycl-2020.html#command-group-function-object)
returns and before the associated call to queue::submit returns.

Currently, command submission time is calculated when a command is
submitted to the underlying device which may not necessarily be before
`queue::submit` returns, e.g `host_accessor` blocking command submission
until it's destroyed.
This patch changes that timeframe to be always before `queue::submit`
returns, specifically right after being persisted by the graph builder
and before being enqueued by graph processor.

---------

Signed-off-by: Rauf, Rana <[email protected]>
Co-authored-by: Romanov Vlad <[email protected]>
Co-authored-by: smaslov-intel <[email protected]>

Author: 3 people

sycl/include/sycl/detail/pi.def

@@ -141,8 +141,10 @@ _PI_API(piPluginGetLastError)
 
 _PI_API(piTearDown)
 
+
 _PI_API(piextUSMEnqueueFill2D)
 _PI_API(piextUSMEnqueueMemset2D)
 _PI_API(piextUSMEnqueueMemcpy2D)
 
+_PI_API(piGetDeviceAndHostTimer)
 #undef _PI_API

sycl/include/sycl/detail/pi.h

@@ -74,9 +74,10 @@
 // PI_EXT_ONEAPI_CONTEXT_INFO_USM_MEMSET2D_SUPPORT, and
 // PI_EXT_ONEAPI_CONTEXT_INFO_USM_MEMCPY2D_SUPPORT context info query
 // descriptors.
+// 12.22 Add piGetDeviceAndHostTimer to query device wall-clock timestamp
 
 #define _PI_H_VERSION_MAJOR 12
-#define _PI_H_VERSION_MINOR 21
+#define _PI_H_VERSION_MINOR 22
 
 #define _PI_STRING_HELPER(a) #a
 #define _PI_CONCAT(a, b) _PI_STRING_HELPER(a.b)
@@ -1898,9 +1899,24 @@ __SYCL_EXPORT pi_result piTearDown(void *PluginParameter);
 ///
 /// \return PI_SUCCESS if plugin is indicating non-fatal warning. Any other
 /// error code indicates that plugin considers this to be a fatal error and the
-/// runtime must handle it or end the application.
+/// Returns the global timestamp from \param device , and syncronized host
+/// timestamp
 __SYCL_EXPORT pi_result piPluginGetLastError(char **message);
 
+/// Queries  device for it's global timestamp in nanoseconds, and updates
+/// HostTime  with the value of the host timer at the closest possible point in
+/// time to that at which DeviceTime was returned.
+///
+/// \param Device device to query for timestamp
+/// \param DeviceTime pointer to store device timestamp in nanoseconds. Optional
+/// argument, can be nullptr
+/// \param HostTime  pointer to store host timestamp in
+/// nanoseconds. Optional argurment, can be nullptr in which case timestamp will
+/// not be written
+__SYCL_EXPORT pi_result piGetDeviceAndHostTimer(pi_device Device,
+                                                uint64_t *DeviceTime,
+                                                uint64_t *HostTime);
+
 struct _pi_plugin {
   // PI version supported by host passed to the plugin. The Plugin
   // checks and writes the appropriate Function Pointers in

sycl/plugins/cuda/pi_cuda.cpp

@@ -18,6 +18,7 @@
 
 #include <algorithm>
 #include <cassert>
+#include <chrono>
 #include <cuda.h>
 #include <cuda_device_runtime_api.h>
 #include <limits>
@@ -2150,7 +2151,6 @@ pi_result cuda_piContextCreate(const pi_context_properties *properties,
       piContextPtr = std::unique_ptr<_pi_context>(new _pi_context{
           _pi_context::kind::user_defined, newContext, *devices});
     }
-
     static std::once_flag initFlag;
     std::call_once(
         initFlag,
@@ -3905,6 +3905,7 @@ pi_result cuda_piEventGetProfilingInfo(pi_event event,
   switch (param_name) {
   case PI_PROFILING_INFO_COMMAND_QUEUED:
   case PI_PROFILING_INFO_COMMAND_SUBMIT:
+    // Note: No user for this case
     return getInfo<pi_uint64>(param_value_size, param_value,
                               param_value_size_ret, event->get_queued_time());
   case PI_PROFILING_INFO_COMMAND_START:
@@ -5502,6 +5503,35 @@ pi_result cuda_piTearDown(void *) {
   return PI_SUCCESS;
 }
 
+pi_result cuda_piGetDeviceAndHostTimer(pi_device Device, uint64_t *DeviceTime,
+                                       uint64_t *HostTime) {
+  _pi_event::native_type event;
+  ScopedContext active(Device->get_context());
+
+  if (DeviceTime) {
+    PI_CHECK_ERROR(cuEventCreate(&event, CU_EVENT_DEFAULT));
+    PI_CHECK_ERROR(cuEventRecord(event, 0));
+  }
+  if (HostTime) {
+
+    using namespace std::chrono;
+    *HostTime =
+        duration_cast<nanoseconds>(steady_clock::now().time_since_epoch())
+            .count();
+  }
+
+  if (DeviceTime) {
+    PI_CHECK_ERROR(cuEventSynchronize(event));
+
+    float elapsedTime = 0.0f;
+    PI_CHECK_ERROR(
+        cuEventElapsedTime(&elapsedTime, _pi_platform::evBase_, event));
+    *DeviceTime = (uint64_t)(elapsedTime * (double)1e6);
+  }
+
+  return PI_SUCCESS;
+}
+
 const char SupportedVersion[] = _PI_CUDA_PLUGIN_VERSION_STRING;
 
 pi_result piPluginInit(pi_plugin *PluginInit) {
@@ -5650,6 +5680,7 @@ pi_result piPluginInit(pi_plugin *PluginInit) {
   _PI_CL(piextKernelSetArgSampler, cuda_piextKernelSetArgSampler)
   _PI_CL(piPluginGetLastError, cuda_piPluginGetLastError)
   _PI_CL(piTearDown, cuda_piTearDown)
+  _PI_CL(piGetDeviceAndHostTimer, cuda_piGetDeviceAndHostTimer)
 
 #undef _PI_CL
 

sycl/plugins/cuda/pi_cuda.hpp

@@ -88,6 +88,7 @@ struct _pi_device {
   native_type cuDevice_;
   std::atomic_uint32_t refCount_;
   pi_platform platform_;
+  pi_context context_;
 
   static constexpr pi_uint32 max_work_item_dimensions = 3u;
   size_t max_work_item_sizes[max_work_item_dimensions];
@@ -103,6 +104,10 @@ struct _pi_device {
 
   pi_platform get_platform() const noexcept { return platform_; };
 
+  void set_context(pi_context ctx) { context_ = ctx; };
+
+  pi_context get_context() { return context_; };
+
   void save_max_work_item_sizes(size_t size,
                                 size_t *save_max_work_item_sizes) noexcept {
     memcpy(max_work_item_sizes, save_max_work_item_sizes, size);
@@ -178,6 +183,7 @@ struct _pi_context {
               bool backend_owns = true)
       : kind_{k}, cuContext_{ctxt}, deviceId_{devId}, refCount_{1},
         has_ownership{backend_owns} {
+    deviceId_->set_context(this);
     cuda_piDeviceRetain(deviceId_);
   };
 

sycl/plugins/esimd_emulator/pi_esimd_emulator.cpp

@@ -2049,6 +2049,12 @@ pi_result piTearDown(void *) {
   return PI_SUCCESS;
 }
 
+pi_result piGetDeviceAndHostTimer(pi_device device, uint64_t *deviceTime,
+                                  uint64_t *hostTime) {
+  PiTrace(
+      "Warning : Querying device clock not supported under PI_ESIMD_EMULATOR");
+  return PI_SUCCESS;
+}
 const char SupportedVersion[] = _PI_ESIMD_PLUGIN_VERSION_STRING;
 
 pi_result piPluginInit(pi_plugin *PluginInit) {

sycl/plugins/hip/pi_hip.cpp

@@ -18,6 +18,7 @@
 
 #include <algorithm>
 #include <cassert>
+#include <chrono>
 #include <hip/hip_runtime.h>
 #include <limits>
 #include <memory>
@@ -605,15 +606,16 @@ pi_uint64 _pi_event::get_start_time() const {
   assert(is_started());
 
   PI_CHECK_ERROR(
-      hipEventElapsedTime(&miliSeconds, context_->evBase_, evStart_));
+      hipEventElapsedTime(&miliSeconds, _pi_platform::evBase_, evStart_));
   return static_cast<pi_uint64>(miliSeconds * 1.0e6);
 }
 
 pi_uint64 _pi_event::get_end_time() const {
   float miliSeconds = 0.0f;
   assert(is_started() && is_recorded());
 
-  PI_CHECK_ERROR(hipEventElapsedTime(&miliSeconds, context_->evBase_, evEnd_));
+  PI_CHECK_ERROR(
+      hipEventElapsedTime(&miliSeconds, _pi_platform::evBase_, evEnd_));
   return static_cast<pi_uint64>(miliSeconds * 1.0e6);
 }
 
@@ -1988,10 +1990,16 @@ pi_result hip_piContextCreate(const pi_context_properties *properties,
           _pi_context::kind::user_defined, newContext, *devices});
     }
 
-    // Use default stream to record base event counter
-    PI_CHECK_ERROR(
-        hipEventCreateWithFlags(&piContextPtr->evBase_, hipEventDefault));
-    PI_CHECK_ERROR(hipEventRecord(piContextPtr->evBase_, 0));
+    static std::once_flag initFlag;
+    std::call_once(
+        initFlag,
+        [](pi_result &err) {
+          // Use default stream to record base event counter
+          PI_CHECK_ERROR(
+              hipEventCreateWithFlags(&_pi_platform::evBase_, hipEventDefault));
+          PI_CHECK_ERROR(hipEventRecord(_pi_platform::evBase_, 0));
+        },
+        errcode_ret);
 
     // For non-primary scoped contexts keep the last active on top of the stack
     // as `cuCtxCreate` replaces it implicitly otherwise.
@@ -2021,8 +2029,6 @@ pi_result hip_piContextRelease(pi_context ctxt) {
 
   std::unique_ptr<_pi_context> context{ctxt};
 
-  PI_CHECK_ERROR(hipEventDestroy(context->evBase_));
-
   if (!ctxt->is_primary()) {
     hipCtx_t hipCtxt = ctxt->get();
     // hipCtxSynchronize is not supported for AMD platform so we can just
@@ -3728,6 +3734,7 @@ pi_result hip_piEventGetProfilingInfo(pi_event event,
   switch (param_name) {
   case PI_PROFILING_INFO_COMMAND_QUEUED:
   case PI_PROFILING_INFO_COMMAND_SUBMIT:
+    // Note: No user for this case
     return getInfo<pi_uint64>(param_value_size, param_value,
                               param_value_size_ret, event->get_queued_time());
   case PI_PROFILING_INFO_COMMAND_START:
@@ -5229,6 +5236,34 @@ pi_result hip_piTearDown(void *PluginParameter) {
   return PI_SUCCESS;
 }
 
+pi_result hip_piGetDeviceAndHostTimer(pi_device Device, uint64_t *DeviceTime,
+                                      uint64_t *HostTime) {
+  _pi_event::native_type event;
+
+  ScopedContext active(Device->get_context());
+
+  if (DeviceTime) {
+    PI_CHECK_ERROR(hipEventCreateWithFlags(&event, hipEventDefault));
+    PI_CHECK_ERROR(hipEventRecord(event));
+  }
+  if (HostTime) {
+    using namespace std::chrono;
+    *HostTime =
+        duration_cast<nanoseconds>(steady_clock::now().time_since_epoch())
+            .count();
+  }
+
+  if (DeviceTime) {
+    PI_CHECK_ERROR(hipEventSynchronize(event));
+
+    float elapsedTime = 0.0f;
+    PI_CHECK_ERROR(
+        hipEventElapsedTime(&elapsedTime, _pi_platform::evBase_, event));
+    *DeviceTime = (uint64_t)(elapsedTime * (double)1e6);
+  }
+  return PI_SUCCESS;
+}
+
 const char SupportedVersion[] = _PI_HIP_PLUGIN_VERSION_STRING;
 
 pi_result piPluginInit(pi_plugin *PluginInit) {
@@ -5371,10 +5406,13 @@ pi_result piPluginInit(pi_plugin *PluginInit) {
   _PI_CL(piextKernelSetArgSampler, hip_piextKernelSetArgSampler)
   _PI_CL(piPluginGetLastError, hip_piPluginGetLastError)
   _PI_CL(piTearDown, hip_piTearDown)
+  _PI_CL(piGetDeviceAndHostTimer, hip_piGetDeviceAndHostTimer)
 
 #undef _PI_CL
 
   return PI_SUCCESS;
 }
 
 } // extern "C"
+
+hipEvent_t _pi_platform::evBase_{nullptr};

sycl/plugins/hip/pi_hip.hpp

@@ -65,6 +65,7 @@ using _pi_stream_guard = std::unique_lock<std::mutex>;
 ///  when devices are used.
 ///
 struct _pi_platform {
+  static hipEvent_t evBase_; // HIP event used as base counter
   std::vector<std::unique_ptr<_pi_device>> devices_;
 };
 
@@ -80,6 +81,7 @@ struct _pi_device {
   native_type cuDevice_;
   std::atomic_uint32_t refCount_;
   pi_platform platform_;
+  pi_context context_;
 
 public:
   _pi_device(native_type cuDevice, pi_platform platform)
@@ -90,6 +92,10 @@ struct _pi_device {
   pi_uint32 get_reference_count() const noexcept { return refCount_; }
 
   pi_platform get_platform() const noexcept { return platform_; };
+
+  void set_context(pi_context ctx) { context_ = ctx; };
+
+  pi_context get_context() { return context_; };
 };
 
 /// PI context mapping to a HIP context object.
@@ -146,11 +152,9 @@ struct _pi_context {
   _pi_device *deviceId_;
   std::atomic_uint32_t refCount_;
 
-  hipEvent_t evBase_; // HIP event used as base counter
-
   _pi_context(kind k, hipCtx_t ctxt, _pi_device *devId)
-      : kind_{k}, hipContext_{ctxt}, deviceId_{devId}, refCount_{1},
-        evBase_(nullptr) {
+      : kind_{k}, hipContext_{ctxt}, deviceId_{devId}, refCount_{1} {
+    deviceId_->set_context(this);
     hip_piDeviceRetain(deviceId_);
   };
 

sycl/plugins/level_zero/pi_level_zero.cpp

@@ -5949,7 +5949,10 @@ pi_result piEventGetProfilingInfo(pi_event Event, pi_profiling_info ParamName,
   }
   case PI_PROFILING_INFO_COMMAND_QUEUED:
   case PI_PROFILING_INFO_COMMAND_SUBMIT:
-    // TODO: Support these when Level Zero supported is added.
+    // Note: No users for this case
+    // TODO: Implement commmand submission time when needed,
+    //        by recording device timestamp (using zeDeviceGetGlobalTimestamps)
+    //        before submitting command to device
     return ReturnValue(uint64_t{0});
   default:
     zePrint("piEventGetProfilingInfo: not supported ParamName\n");
@@ -9321,4 +9324,22 @@ pi_result _pi_buffer::free() {
   return PI_SUCCESS;
 }
 
+pi_result piGetDeviceAndHostTimer(pi_device Device, uint64_t *DeviceTime,
+                                  uint64_t *HostTime) {
+  const uint64_t &ZeTimerResolution =
+      Device->ZeDeviceProperties->timerResolution;
+  const uint64_t TimestampMaxCount =
+      ((1ULL << Device->ZeDeviceProperties->kernelTimestampValidBits) - 1ULL);
+  uint64_t DeviceClockCount, Dummy;
+
+  ZE_CALL(zeDeviceGetGlobalTimestamps,
+          (Device->ZeDevice, HostTime == nullptr ? &Dummy : HostTime,
+           &DeviceClockCount));
+
+  if (DeviceTime != nullptr) {
+
+    *DeviceTime = (DeviceClockCount & TimestampMaxCount) * ZeTimerResolution;
+  }
+  return PI_SUCCESS;
+}
 } // extern "C"