[SYCL] Make host task timestamps share the same base as device tasks

Currently, we use std::chrono to record  `command_submit`, `command_start`
and `command_end` timestamps for host tasks. So, if there there is a mix
of device tasks and host tasks submitted to the queue, they have a
different time base and inconvenient to use/compare.
This PR makes host task timestamps to have the same time base as device
tasks.

Author: againull

sycl/include/sycl/detail/host_profiling_info.hpp

@@ -10,18 +10,27 @@
 
 #include <sycl/detail/export.hpp> // for __SYCL_EXPORT
 
+#include <memory>   // for std::weak_ptr
 #include <stdint.h> // for uint64_t
 
 namespace sycl {
 inline namespace _V1 {
 namespace detail {
 
+class queue_impl;
+
 /// Profiling info for the host execution.
 class __SYCL_EXPORT HostProfilingInfo {
   uint64_t StartTime = 0;
   uint64_t EndTime = 0;
+  // Queue that was used to submit the host task.
+  std::weak_ptr<queue_impl> SubmitQueue;
 
 public:
+  // Sets the queue that was used to submit the host task.
+  void setSubmitQueue(const std::weak_ptr<queue_impl> &Queue) {
+    SubmitQueue = Queue;
+  }
   /// Returns event's start time.
   ///
   /// \return event's start time in nanoseconds.

sycl/source/detail/event_impl.cpp

@@ -113,10 +113,26 @@ void event_impl::setComplete() {
   assert(false && "setComplete is not supported for non-host event");
 }
 
-static uint64_t inline getTimestamp() {
-  auto Timestamp = std::chrono::high_resolution_clock::now().time_since_epoch();
-  return std::chrono::duration_cast<std::chrono::nanoseconds>(Timestamp)
-      .count();
+static uint64_t inline getTimestamp(
+    const std::weak_ptr<queue_impl> &QueueWeakPtr) {
+  if (QueueImplPtr Queue = QueueWeakPtr.lock()) {
+    try {
+      return Queue->getDeviceImpl().getCurrentDeviceTime();
+    } catch (sycl::exception &e) {
+      if (e.code() == sycl::errc::feature_not_supported)
+        throw sycl::exception(
+            make_error_code(errc::profiling),
+            std::string("Unable to get command group submission time: ") +
+                e.what());
+      std::rethrow_exception(std::current_exception());
+    }
+  } else {
+    // Returning host time
+    using namespace std::chrono;
+    return duration_cast<nanoseconds>(
+               high_resolution_clock::now().time_since_epoch())
+        .count();
+  }
 }
 
 ur_event_handle_t event_impl::getHandle() const { return MEvent.load(); }
@@ -179,7 +195,6 @@ event_impl::event_impl(const QueueImplPtr &Queue)
 void event_impl::setQueue(const QueueImplPtr &Queue) {
   MQueue = Queue;
   MIsProfilingEnabled = Queue->MIsProfilingEnabled;
-
   // TODO After setting the queue, the event is no longer default
   // constructed. Consider a design change which would allow
   // for such a change regardless of the construction method.
@@ -476,9 +491,9 @@ event_impl::get_backend_info<info::device::backend_version>() const {
 }
 #endif
 
-void HostProfilingInfo::start() { StartTime = getTimestamp(); }
+void HostProfilingInfo::start() { StartTime = getTimestamp(SubmitQueue); }
 
-void HostProfilingInfo::end() { EndTime = getTimestamp(); }
+void HostProfilingInfo::end() { EndTime = getTimestamp(SubmitQueue); }
 
 ur_native_handle_t event_impl::getNative() {
   if (isHost())
@@ -568,24 +583,10 @@ void event_impl::setSubmissionTime() {
   if (!MIsProfilingEnabled && !MProfilingTagEvent)
     return;
 
-  if (QueueImplPtr Queue = MQueue.lock()) {
-    try {
-      MSubmitTime = Queue->getDeviceImpl().getCurrentDeviceTime();
-    } catch (sycl::exception &e) {
-      if (e.code() == sycl::errc::feature_not_supported)
-        throw sycl::exception(
-            make_error_code(errc::profiling),
-            std::string("Unable to get command group submission time: ") +
-                e.what());
-      std::rethrow_exception(std::current_exception());
-    }
-  } else {
-    // Returning host time
-    using namespace std::chrono;
-    MSubmitTime = duration_cast<nanoseconds>(
-                      high_resolution_clock::now().time_since_epoch())
-                      .count();
-  }
+  if (isHost())
+    MSubmitTime = getTimestamp(MSubmittedQueue);
+  else
+    MSubmitTime = getTimestamp(MQueue);
 }
 
 uint64_t event_impl::getSubmissionTime() { return MSubmitTime; }

sycl/source/detail/event_impl.hpp

@@ -243,6 +243,8 @@ class event_impl {
   /// @return
   void setSubmittedQueue(const QueueImplPtr &SubmittedQueue) {
     MSubmittedQueue = SubmittedQueue;
+    if (MHostProfilingInfo)
+      MHostProfilingInfo->setSubmitQueue(SubmittedQueue);
   };
 
   /// Indicates if this event is not associated with any command and doesn't

sycl/test-e2e/Basic/submit_time.cpp

@@ -46,30 +46,71 @@ int main(void) {
   // All shortcut memory operations use queue_impl::submitMemOpHelper.
   // This test covers memcpy as a representative, extend if other operations
   // diverge.
+  uint64_t memcpy_submit_time = 0;
+  uint64_t memcpy_start_time = 0;
+  uint64_t memcpy_end_time = 0;
   for (int i = 0; i < 5; i++) {
     auto memcpy_event = q.memcpy(dest, data, sizeof(int) * n);
     memcpy_event.wait();
 
-    auto submit_time =
+    auto memcpy_submit_time =
         memcpy_event
             .get_profiling_info<sycl::info::event_profiling::command_submit>();
-    auto start_time =
+    auto memcpy_start_time =
         memcpy_event
             .get_profiling_info<sycl::info::event_profiling::command_start>();
-    auto end_time =
+    auto memcpy_end_time =
         memcpy_event
             .get_profiling_info<sycl::info::event_profiling::command_end>();
 
     // Print for debugging
-    std::cout << "Memcpy Event - Submit: " << submit_time
-              << ", Start: " << start_time << ", End: " << end_time
-              << std::endl;
+    std::cout << "Memcpy Event - Submit: " << memcpy_submit_time
+              << ", Start: " << memcpy_start_time
+              << ", End: " << memcpy_end_time << std::endl;
 
-    assert(submit_time != 0 && "Submit time should not be zero");
-    assert((submit_time <= start_time) && (start_time <= end_time));
+    assert(memcpy_submit_time != 0 && "Submit time should not be zero");
+    assert((memcpy_submit_time <= memcpy_start_time) &&
+           (memcpy_start_time <= memcpy_end_time));
   }
 
   sycl::free(data, q);
   sycl::free(dest, q);
+
+  // Check that host_task profiling timestamps share the same base as device
+  // tasks.
+  auto host_task_event =
+      q.submit([&](sycl::handler &cgh) { cgh.host_task([=]() {}); });
+  q.wait();
+  auto device_task_event = q.submit([&](sycl::handler &cgh) {
+    cgh.parallel_for<class DeviceTask>(sycl::range<1>(1), [=](sycl::id<1>) {});
+  });
+
+  const uint64_t host_submitted = host_task_event.template get_profiling_info<
+      sycl::info::event_profiling::command_submit>();
+  const uint64_t host_start = host_task_event.template get_profiling_info<
+      sycl::info::event_profiling::command_start>();
+  const uint64_t host_end = host_task_event.template get_profiling_info<
+      sycl::info::event_profiling::command_end>();
+  std::cout << "Submit time: " << host_submitted
+            << ", Start time: " << host_start << ", End time: " << host_end
+            << std::endl;
+
+  const uint64_t device_submitted =
+      device_task_event.template get_profiling_info<
+          sycl::info::event_profiling::command_submit>();
+  const uint64_t device_start = device_task_event.template get_profiling_info<
+      sycl::info::event_profiling::command_start>();
+  const uint64_t device_end = device_task_event.template get_profiling_info<
+      sycl::info::event_profiling::command_end>();
+  std::cout << "Device Submit time: " << device_submitted
+            << ", Device Start time: " << device_start
+            << ", Device End time: " << device_end << std::endl;
+  assert(host_submitted >= memcpy_submit_time &&
+         host_submitted <= device_submitted &&
+         "Host and device submit expected to share the same base");
+  assert(host_start >= memcpy_start_time && host_start <= device_start &&
+         "Host and device start expected to share the same base");
+  assert(host_end >= memcpy_end_time && host_end <= device_end &&
+         "Host and device end expected to share the same base");
   return 0;
 }

sycl/test/abi/sycl_symbols_windows.dump

@@ -295,6 +295,8 @@
 ??0AccessorBaseHost@detail@_V1@sycl@@QEAA@AEBV0123@@Z
 ??0AccessorBaseHost@detail@_V1@sycl@@QEAA@V?$id@$02@23@V?$range@$02@23@1W4mode@access@23@PEAXHH_K_NAEBVproperty_list@23@@Z
 ??0AccessorBaseHost@detail@_V1@sycl@@QEAA@V?$id@$02@23@V?$range@$02@23@1W4mode@access@23@PEAXHH_N_K4AEBVproperty_list@23@@Z
+??0HostProfilingInfo@detail@_V1@sycl@@QEAA@$$QEAV0123@@Z
+??0HostProfilingInfo@detail@_V1@sycl@@QEAA@AEBV0123@@Z
 ??0HostProfilingInfo@detail@_V1@sycl@@QEAA@XZ
 ??0LocalAccessorBaseHost@detail@_V1@sycl@@IEAA@AEBV?$shared_ptr@VLocalAccessorImplHost@detail@_V1@sycl@@@std@@@Z
 ??0LocalAccessorBaseHost@detail@_V1@sycl@@QEAA@$$QEAV0123@@Z
@@ -499,6 +501,7 @@
 ??0tls_code_loc_t@detail@_V1@sycl@@QEAA@AEBUcode_location@123@@Z
 ??0tls_code_loc_t@detail@_V1@sycl@@QEAA@XZ
 ??1AccessorBaseHost@detail@_V1@sycl@@QEAA@XZ
+??1HostProfilingInfo@detail@_V1@sycl@@QEAA@XZ
 ??1LocalAccessorBaseHost@detail@_V1@sycl@@QEAA@XZ
 ??1SYCLCategory@detail@_V1@sycl@@UEAA@XZ
 ??1SampledImageAccessorBaseHost@detail@_V1@sycl@@QEAA@XZ
@@ -4390,6 +4393,7 @@
 ?setNDRangeUsed@handler@_V1@sycl@@AEAAX_N@Z
 ?setStateExplicitKernelBundle@handler@_V1@sycl@@AEAAXXZ
 ?setStateSpecConstSet@handler@_V1@sycl@@AEAAXXZ
+?setSubmitQueue@HostProfilingInfo@detail@_V1@sycl@@QEAAXAEBV?$weak_ptr@Vqueue_impl@detail@_V1@sycl@@@std@@@Z
 ?setType@handler@_V1@sycl@@AEAAXW4CGType@detail@23@@Z
 ?setUserFacingNodeType@handler@_V1@sycl@@AEAAXW4node_type@experimental@oneapi@ext@23@@Z
 ?set_access_mode@experimental@oneapi@ext@_V1@sycl@@YAXPEBX_KW4address_access_mode@12345@AEBVcontext@45@@Z