diff --git a/sycl/source/detail/event_impl.cpp b/sycl/source/detail/event_impl.cpp index 4084486139af3..786a86f877131 100644 --- a/sycl/source/detail/event_impl.cpp +++ b/sycl/source/detail/event_impl.cpp @@ -410,8 +410,7 @@ uint64_t event_impl::get_profiling_info() { 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( 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 = diff --git a/sycl/source/detail/queue_impl.cpp b/sycl/source/detail/queue_impl.cpp index b8bd5c3bc620f..4c92a53a4030c 100644 --- a/sycl/source/detail/queue_impl.cpp +++ b/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(); diff --git a/unified-runtime/source/adapters/level_zero/event.cpp b/unified-runtime/source/adapters/level_zero/event.cpp index 51bb588bbb9ec..b264618564fc9 100644 --- a/unified-runtime/source/adapters/level_zero/event.cpp +++ b/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 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()) diff --git a/unified-runtime/source/adapters/level_zero/event.hpp b/unified-runtime/source/adapters/level_zero/event.hpp index 9a977b8efa5e3..c971396f9df26 100644 --- a/unified-runtime/source/adapters/level_zero/event.hpp +++ b/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 diff --git a/unified-runtime/source/adapters/level_zero/queue.cpp b/unified-runtime/source/adapters/level_zero/queue.cpp index 1844140ef9c1c..45342df193a34 100644 --- a/unified-runtime/source/adapters/level_zero/queue.cpp +++ b/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(); diff --git a/unified-runtime/source/adapters/level_zero/v2/command_list_manager.cpp b/unified-runtime/source/adapters/level_zero/v2/command_list_manager.cpp index de4defaad57cd..16ef6f96d8bbc 100644 --- a/unified-runtime/source/adapters/level_zero/v2/command_list_manager.cpp +++ b/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(); diff --git a/unified-runtime/source/adapters/level_zero/v2/event.cpp b/unified-runtime/source/adapters/level_zero/v2/event.cpp index ffef28393d829..babef838be86d 100644 --- a/unified-runtime/source/adapters/level_zero/v2/event.cpp +++ b/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; diff --git a/unified-runtime/source/adapters/level_zero/v2/event.hpp b/unified-runtime/source/adapters/level_zero/v2/event.hpp index f7e6fe0a83c64..208371062fda7 100644 --- a/unified-runtime/source/adapters/level_zero/v2/event.hpp +++ b/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 getEventEndTimestampAndHandle(); - uint64_t getEventStartTimestmap() const; uint64_t getEventEndTimestamp(); ur::RefCount RefCount; diff --git a/unified-runtime/source/adapters/level_zero/v2/queue_batched.cpp b/unified-runtime/source/adapters/level_zero/v2/queue_batched.cpp index 88bebe21f10f5..c39a2a4ce8d5c 100644 --- a/unified-runtime/source/adapters/level_zero/v2/queue_batched.cpp +++ b/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) {