[SYCL] Record submit time for shortcut operations (#18455)

We record submission time for commands submitted via handler, but this
was missing for shortcut commands.

Also this PR changes the values returned by `command_submit`,
`command_start`, `command_end` for non-host events without UR event
handle - such events may appear if command is nop, for example, USM
operations for 0 bytes.
Such scenario is not explicitly specified in SYCL spec. Before changes,
we used to return 0 for all three quieries. But for consistency,I
believe it makes sense to return the same recorded submit time for all
three: `command_submit = command_start = command_end`. It seems more
convenient from user's perspective, for example if user submits sequence
set of commands and there is some nop command in the middle of sequence:
`command1`
`command2 (nop)`
`command3`
and user calculates wants to calculate differences between submission
time (or start time) of `command2` and `command1`, then he will get
negative value: `0 - submit_time_of_command2` (if we return `0`).
And there can be more nop operations (if SYCL runtime optimizes out
something), so if we return `0`, user always has to check if the
returned timestamp is 0 or not before using it in any calculations. So
returning non-zero submit time seems better.

Author: againull

sycl/source/detail/event_impl.cpp

@@ -348,7 +348,10 @@ event_impl::get_profiling_info<info::event_profiling::command_start>() {
       return get_event_profiling_info<info::event_profiling::command_start>(
           Handle, this->getAdapter());
     }
-    return 0;
+    // If command is nop (for example, USM operations for 0 bytes) return
+    // recorded submission time. If event is created using default constructor,
+    // 0 will be returned.
+    return MSubmitTime;
   }
   if (!MHostProfilingInfo)
     throw sycl::exception(
@@ -367,7 +370,10 @@ uint64_t event_impl::get_profiling_info<info::event_profiling::command_end>() {
       return get_event_profiling_info<info::event_profiling::command_end>(
           Handle, this->getAdapter());
     }
-    return 0;
+    // If command is nop (for example, USM operations for 0 bytes) return
+    // recorded submission time. If event is created using default constructor,
+    // 0 will be returned.
+    return MSubmitTime;
   }
   if (!MHostProfilingInfo)
     throw sycl::exception(

sycl/source/detail/queue_impl.cpp

@@ -486,6 +486,7 @@ event queue_impl::submitMemOpHelper(const std::shared_ptr<queue_impl> &Self,
       {
         NestedCallsTracker tracker;
         ur_event_handle_t UREvent = nullptr;
+        EventImpl->setSubmissionTime();
         MemOpFunc(MemOpArgs..., getUrEvents(ExpandedDepEvents), &UREvent);
         EventImpl->setHandle(UREvent);
         EventImpl->setEnqueued();

sycl/test-e2e/Basic/submit_time.cpp

@@ -8,18 +8,22 @@
 // Test fails on hip flakily, disable temprorarily.
 // UNSUPPORTED: hip
 
+#include <cassert>
+#include <iostream>
 #include <sycl/detail/core.hpp>
 #include <sycl/properties/all_properties.hpp>
 #include <sycl/usm.hpp>
 
 int main(void) {
+  constexpr size_t n = 16;
   sycl::queue q({sycl::property::queue::enable_profiling{}});
-  int *data = sycl::malloc_host<int>(1024, q);
+  int *data = sycl::malloc_host<int>(n, q);
+  int *dest = sycl::malloc_host<int>(n, q);
 
-  for (int i = 0; i < 20; i++) {
+  for (int i = 0; i < 5; i++) {
     auto event = q.submit([&](sycl::handler &cgh) {
       cgh.parallel_for<class KernelTime>(
-          sycl::range<1>(1024), [=](sycl::id<1> idx) { data[idx] = idx; });
+          sycl::range<1>(n), [=](sycl::id<1> idx) { data[idx] = idx; });
     });
 
     event.wait();
@@ -30,8 +34,42 @@ int main(void) {
     auto end_time =
         event.get_profiling_info<sycl::info::event_profiling::command_end>();
 
+    // Print for debugging
+    std::cout << "Kernel Event - Submit: " << submit_time
+              << ", Start: " << start_time << ", End: " << end_time
+              << std::endl;
+
+    assert(submit_time != 0 && "Submit time should not be zero");
     assert((submit_time <= start_time) && (start_time <= end_time));
   }
+
+  // All shortcut memory operations use queue_impl::submitMemOpHelper.
+  // This test covers memcpy as a representative, extend if other operations
+  // diverge.
+  for (int i = 0; i < 5; i++) {
+    auto memcpy_event = q.memcpy(dest, data, sizeof(int) * n);
+    memcpy_event.wait();
+
+    auto submit_time =
+        memcpy_event
+            .get_profiling_info<sycl::info::event_profiling::command_submit>();
+    auto start_time =
+        memcpy_event
+            .get_profiling_info<sycl::info::event_profiling::command_start>();
+    auto 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;
+
+    assert(submit_time != 0 && "Submit time should not be zero");
+    assert((submit_time <= start_time) && (start_time <= end_time));
+  }
+
   sycl::free(data, q);
+  sycl::free(dest, q);
   return 0;
 }

sycl/test-e2e/Regression/dummy_event_info.cpp

@@ -19,9 +19,13 @@ int main() {
   assert(e.get_info<info::event::command_execution_status>() ==
          info::event_command_status::complete);
   assert(e.get_info<info::event::reference_count>() == 0);
-  assert(e.get_profiling_info<sycl::info::event_profiling::command_submit>() ==
-         0);
-  assert(e.get_profiling_info<sycl::info::event_profiling::command_start>() ==
-         0);
-  assert(e.get_profiling_info<sycl::info::event_profiling::command_end>() == 0);
+  auto submit_time =
+      e.get_profiling_info<sycl::info::event_profiling::command_submit>();
+  auto start_time =
+      e.get_profiling_info<sycl::info::event_profiling::command_start>();
+  auto end_time =
+      e.get_profiling_info<sycl::info::event_profiling::command_end>();
+
+  assert(submit_time == start_time);
+  assert(start_time == end_time);
 }