[UR][L0v2][SYCL] Avoid redundant global timestamp query for profiling tag events

sycl/source/detail/event_impl.cpp

@@ -410,8 +410,7 @@ uint64_t
 event_impl::get_profiling_info<info::event_profiling::command_submit>() {
   checkProfilingPreconditions();
   if (isProfilingTagEvent()) {
-    // For profiling tag events we rely on the submission time reported as
-    // the start time has undefined behavior.
+    // Tag events report command_submit through the adapter.
     return get_event_profiling_info<info::event_profiling::command_submit>(
         this->getHandle(), this->getAdapter());
   }
@@ -608,7 +607,8 @@ void event_impl::cleanDepEventsThroughOneLevel() {
 }
 
 void event_impl::setSubmissionTime() {
-  if (!MIsProfilingEnabled && !MProfilingTagEvent)
+  // Tag events obtain command_submit from the adapter.
+  if (!MIsProfilingEnabled || MProfilingTagEvent)
     return;
 
   if (std::shared_ptr<queue_impl> Queue =

sycl/source/detail/queue_impl.cpp

@@ -518,6 +518,8 @@ EventImplPtr queue_impl::submit_barrier_scheduler_bypass(
     ResEvent->setWorkerQueue(weak_from_this());
     ResEvent->setPotentiallyNativeRecorded(
         getContextImpl().isNativeRecordingActive());
+    if (EventForReuse)
+      ResEvent->markAsProfilingTagEvent();
     ResEvent->setSubmissionTime();
     ResEvent->setEnqueued();
     ResEvent->setStateIncomplete();

unified-runtime/source/adapters/level_zero/event.cpp

@@ -563,13 +563,14 @@ ur_result_t urEventGetProfilingInfo(
   // handle, so we short-circuit the return.
   // We don't support user events with timestamps due to requiring the UrQueue.
   if (isTimestampedEvent && Event->UrQueue) {
-    uint64_t ContextStartTime = Event->RecordEventStartTimestamp;
     switch (PropName) {
+    // The tag is an empty command, so all timestamps are the single
+    // GPU-written completion time.
     case UR_PROFILING_INFO_COMMAND_QUEUED:
     case UR_PROFILING_INFO_COMMAND_SUBMIT:
-      return ReturnValue(ContextStartTime);
+    case UR_PROFILING_INFO_COMMAND_START:
     case UR_PROFILING_INFO_COMMAND_END:
-    case UR_PROFILING_INFO_COMMAND_START: {
+    case UR_PROFILING_INFO_COMMAND_COMPLETE: {
       // If RecordEventEndTimestamp on the event is non-zero it means it has
       // collected the result of the queue already. In that case it has been
       // adjusted and is ready for immediate return.
@@ -584,7 +585,8 @@ ur_result_t urEventGetProfilingInfo(
         return UR_RESULT_ERROR_UNKNOWN;
       auto &EndTimeRecording = Entry->second;
 
-      // End time needs to be adjusted for resolution and valid bits.
+      // End time needs to be adjusted for resolution and valid bits. A single
+      // timestamp has no separate start value to detect wrap-around against.
       uint64_t ContextEndTime =
           (EndTimeRecording & TimestampMaxValue) * ZeTimerResolution;
 
@@ -593,13 +595,6 @@ ur_result_t urEventGetProfilingInfo(
       if (ContextEndTime == 0)
         return ReturnValue(ContextEndTime);
 
-      // Handle a possible wrap-around (the underlying HW counter is < 64-bit).
-      // Note, it will not report correct time if there were multiple wrap
-      // arounds, and the longer term plan is to enlarge the capacity of the
-      // HW timestamps.
-      if (ContextEndTime < ContextStartTime)
-        ContextEndTime += TimestampMaxValue * ZeTimerResolution;
-
       // Now that we have the result, there is no need to keep it in the queue
       // anymore, so we cache it on the event and evict the record from the
       // queue.
@@ -608,10 +603,6 @@ ur_result_t urEventGetProfilingInfo(
 
       return ReturnValue(ContextEndTime);
     }
-    case UR_PROFILING_INFO_COMMAND_COMPLETE:
-      UR_LOG(ERR, "urEventGetProfilingInfo: "
-                  "UR_PROFILING_INFO_COMMAND_COMPLETE not supported");
-      return UR_RESULT_ERROR_UNSUPPORTED_ENUMERATION;
     default:
       UR_LOG(ERR, "urEventGetProfilingInfo: not supported ParamName");
       return UR_RESULT_ERROR_INVALID_VALUE;
@@ -755,8 +746,6 @@ ur_result_t urEnqueueTimestampRecordingExp(
   // Lock automatically releases when this goes out of scope.
   std::scoped_lock<ur_shared_mutex> lock(Queue->Mutex);
 
-  ur_device_handle_t Device = Queue->Device;
-
   bool UseCopyEngine = false;
   ur_ze_event_list_t TmpWaitList;
   UR_CALL(TmpWaitList.createAndRetainUrZeEventList(
@@ -780,11 +769,6 @@ ur_result_t urEnqueueTimestampRecordingExp(
   // Reset the end timestamp, in case it has been previously used.
   OutEventInternal->RecordEventEndTimestamp = 0;
 
-  uint64_t DeviceStartTimestamp = 0;
-  UR_CALL(ur::level_zero::urDeviceGetGlobalTimestamps(
-      common_cast(Device), &DeviceStartTimestamp, nullptr));
-  OutEventInternal->RecordEventStartTimestamp = DeviceStartTimestamp;
-
   // Mark this event as timestamped
   OutEventInternal->IsTimestamped = true;
 
@@ -1503,7 +1487,6 @@ ur_result_t ur::level_zero::v1::ur_event_handle_t_::reset() {
   completionBatch = std::nullopt;
   OriginAllocEvent = nullptr;
   IsTimestamped = false;
-  RecordEventStartTimestamp = 0;
   RecordEventEndTimestamp = 0;
 
   if (!isHostVisible())

unified-runtime/source/adapters/level_zero/event.hpp

@@ -216,12 +216,9 @@ struct ur_event_handle_t_ : ur_object_t {
   // Indicates within creation of proxy event.
   bool IsCreatingHostProxyEvent = {false};
 
-  // Indicates the recorded start and end timestamps for the event. These are
-  // only set for events returned by timestamp recording enqueue functions.
-  // A non-zero value for RecordEventStartTimestamp indicates the event was the
-  // result of a timestamp recording. If RecordEventEndTimestamp is non-zero, it
-  // means the event has fetched the end-timestamp from the queue.
-  uint64_t RecordEventStartTimestamp = 0;
+  // The GPU-written global timestamp for a timestamp-recording event. Set to a
+  // non-zero adjusted value once the end-timestamp has been fetched from the
+  // queue; IsTimestamped tells whether the event is timestamp-recording.
   uint64_t RecordEventEndTimestamp = 0;
 
   // Besides each PI object keeping a total reference count in

unified-runtime/source/adapters/level_zero/queue.cpp

@@ -1660,19 +1660,11 @@ void ur::level_zero::v1::ur_queue_handle_t_::clearEndTimeRecordings() {
     auto &Event = Entry.first;
     auto &EndTimeRecording = Entry.second;
 
-    // Write the result back to the event if it is not dead.
-    uint64_t ContextEndTime =
+    // Write the result back to the event if it is not dead. A single
+    // GPU-written timestamp has no separate start value to detect wrap-around
+    // against.
+    Event->RecordEventEndTimestamp =
         (EndTimeRecording & TimestampMaxValue) * ZeTimerResolution;
-
-    // Handle a possible wrap-around (the underlying HW counter is < 64-bit).
-    // Note, it will not report correct time if there were multiple wrap
-    // arounds, and the longer term plan is to enlarge the capacity of the
-    // HW timestamps.
-    if (ContextEndTime < Event->RecordEventStartTimestamp)
-      ContextEndTime += TimestampMaxValue * ZeTimerResolution;
-
-    // Store it in the event.
-    Event->RecordEventEndTimestamp = ContextEndTime;
   }
   EndTimeRecordings.clear();
   EvictedEndTimeRecordings.clear();

unified-runtime/source/adapters/level_zero/v2/command_list_manager.cpp

@@ -602,7 +602,7 @@ ur_result_t ur_command_list_manager::appendTimestampRecordingExp(
 
   auto [pWaitEvents, numWaitEvents, _] = waitListView;
 
-  phEvent->recordStartTimestamp();
+  phEvent->initTimestampRecording();
 
   auto [timestampPtr, zeSignalEvent] = phEvent->getEventEndTimestampAndHandle();
 

unified-runtime/source/adapters/level_zero/v2/event.cpp

@@ -56,9 +56,10 @@ uint64_t event_profiling_data_t::getEventEndTimestamp() {
   assert(zeTimerResolution);
   assert(timestampMaxValue);
 
-  adjustedEventEndTimestamp = adjustEndEventTimestamp(
-      adjustedEventStartTimestamp, recordEventEndTimestamp, timestampMaxValue,
-      zeTimerResolution);
+  // A timestamp-recording event holds a single GPU-written global timestamp,
+  // so there is no separate start value to detect a wrap-around against.
+  adjustedEventEndTimestamp =
+      (recordEventEndTimestamp & timestampMaxValue) * zeTimerResolution;
 
   return adjustedEventEndTimestamp;
 }
@@ -67,33 +68,30 @@ void event_profiling_data_t::reset() {
   // This ensures that the event is consider as not timestamped.
   // We can't touch the recordEventEndTimestamp
   // as it may still be overwritten by the driver.
-  // In case event is resued and recordStartTimestamp
+  // In case event is resued and initTimestampRecording
   // is called again, adjustedEventEndTimestamp will always be updated correctly
   // to the new value as we wait for the event to be signaled.
   // If the event is reused on another queue, this means that the original
   // queue must have been destroyed (and the even pool released back to the
   // context) and the timstamp is already wrriten, so there's no race-condition
   // possible.
-  adjustedEventStartTimestamp = 0;
   adjustedEventEndTimestamp = 0;
   timestampRecorded = false;
 }
 
-void event_profiling_data_t::recordStartTimestamp(ur_device_handle_t hDevice) {
+void event_profiling_data_t::initTimestampRecording(
+    ur_device_handle_t hDevice) {
   zeTimerResolution = hDevice->getTimerResolution();
   timestampMaxValue = hDevice->getTimestampMask();
-
-  uint64_t deviceStartTimestamp = 0;
-  UR_CALL_THROWS(ur::level_zero::urDeviceGetGlobalTimestamps(
-      common_cast(hDevice), &deviceStartTimestamp, nullptr));
-
-  assert(adjustedEventStartTimestamp == 0);
-  adjustedEventStartTimestamp = deviceStartTimestamp;
   timestampRecorded = true;
 }
 
-uint64_t event_profiling_data_t::getEventStartTimestmap() const {
-  return adjustedEventStartTimestamp;
+void ur_event_handle_t_::initTimestampRecording() {
+  // queue and device must be set before calling this
+  assert(hQueue);
+  assert(hDevice);
+
+  profilingData.initTimestampRecording(hDevice);
 }
 
 bool event_profiling_data_t::recordingStarted() const {
@@ -145,18 +143,6 @@ void ur_event_handle_t_::onWaitListUse() {
   }
 }
 
-void ur_event_handle_t_::recordStartTimestamp() {
-  // queue and device must be set before calling this
-  assert(hQueue);
-  assert(hDevice);
-
-  profilingData.recordStartTimestamp(hDevice);
-}
-
-uint64_t ur_event_handle_t_::getEventStartTimestmap() const {
-  return profilingData.getEventStartTimestmap();
-}
-
 uint64_t ur_event_handle_t_::getEventEndTimestamp() {
   return profilingData.getEventEndTimestamp();
 }
@@ -345,16 +331,15 @@ ur_result_t urEventGetProfilingInfo(
   // For timestamped events we have the timestamps ready directly on the event
   // handle, so we short-circuit the return.
   if (isTimestampedEvent) {
-    uint64_t contextStartTime = event->getEventStartTimestmap();
     switch (propName) {
     case UR_PROFILING_INFO_COMMAND_QUEUED:
     case UR_PROFILING_INFO_COMMAND_SUBMIT:
-      return returnValue(contextStartTime);
-    case UR_PROFILING_INFO_COMMAND_END:
     case UR_PROFILING_INFO_COMMAND_START:
-    case UR_PROFILING_INFO_COMMAND_COMPLETE: {
+    case UR_PROFILING_INFO_COMMAND_END:
+    case UR_PROFILING_INFO_COMMAND_COMPLETE:
+      // The tag is an empty command, so all timestamps are the single
+      // GPU-written completion time.
       return returnValue(event->getEventEndTimestamp());
-    }
     default:
       UR_LOG(ERR, "urEventGetProfilingInfo: not supported ParamName");
       return UR_RESULT_ERROR_INVALID_VALUE;

unified-runtime/source/adapters/level_zero/v2/event.hpp

@@ -28,8 +28,9 @@ class event_pool;
 struct event_profiling_data_t {
   event_profiling_data_t(ze_event_handle_t hZeEvent) : hZeEvent(hZeEvent) {}
 
-  void recordStartTimestamp(ur_device_handle_t hDevice);
-  uint64_t getEventStartTimestmap() const;
+  // Cache the device timer resolution/mask and mark the event as
+  // timestamp-recording.
+  void initTimestampRecording(ur_device_handle_t hDevice);
 
   uint64_t getEventEndTimestamp();
   uint64_t *eventEndTimestampAddr();
@@ -43,7 +44,6 @@ struct event_profiling_data_t {
 private:
   ze_event_handle_t hZeEvent;
 
-  uint64_t adjustedEventStartTimestamp = 0;
   uint64_t recordEventEndTimestamp = 0;
   uint64_t adjustedEventEndTimestamp = 0;
 
@@ -127,16 +127,14 @@ struct ur_event_handle_t_ : v2::ur_object_t {
   // Get the device associated with this event
   ur_device_handle_t getDevice() const;
 
-  // Record the start timestamp of the event, to be obtained by
-  // urEventGetProfilingInfo. setQueue should be
-  // called before this.
-  void recordStartTimestamp();
+  // Mark this event as recording a GPU-written global timestamp, obtainable via
+  // urEventGetProfilingInfo. setQueue must be called first.
+  void initTimestampRecording();
 
-  // Get pointer to the end timestamp, and ze event handle.
+  // Get pointer to the timestamp storage, and ze event handle.
   // Caller is responsible for signaling the event once the timestamp is ready.
   std::pair<uint64_t *, ze_event_handle_t> getEventEndTimestampAndHandle();
 
-  uint64_t getEventStartTimestmap() const;
   uint64_t getEventEndTimestamp();
 
   ur::RefCount RefCount;

unified-runtime/source/adapters/level_zero/v2/queue_batched.cpp

@@ -863,16 +863,6 @@ ur_result_t ur_queue_batched_t::bindlessImagesSignalExternalSemaphoreExp(
       getEvent(lockedBatch, phEvent));
 }
 
-// In case of queues with batched submissions, which use regular command lists
-// (similarly to command buffers), the start timestamp would be recorded as the
-// operation is submitted (event.recordStartTimestamp() in
-// appendTimestampRecordingExp does not use the queue but directly the device),
-// but the end timestamp would wait for the submission of the given regular
-// command list. The difference between the start and end timestamps would
-// reflect the delay in the batch submission, the difference between end
-// timestamps would reflect the actual time of execution.
-//
-
 ur_result_t ur_queue_batched_t::enqueueTimestampRecordingExp(
     bool blocking, uint32_t numEventsInWaitList,
     const ur_event_handle_t *phEventWaitList, ur_event_handle_t *phEvent) {