[SYCL] Implement event_profiling::command_submit for level-zero

[raaiq1]

This feature implements calculating and returning the submission time of a command group associated with an event in level-zero. The submission time calculated by querying the device's wall-clock time right before a commandlist is submitted for execution.

Signed-off-by: Rauf, Rana [email protected]

[romanovvlad]

Not sure the approach is correct.
The specification says:

info::event_command_status::submitted

Indicates that the command has been submitted to the SYCL queue but has not yet started running on the device.

So, it sounds like the submitted timestamp should be taken when a command enqueued to the SYCL queue rather than to L0 queue, they could be different timestamps. For example:

auto HostAcc = Buf.get_access();
Q.submit(/*a kernel writing to Buf*/); // Command1

The Command1 is not enqueued to L0 queue until HostAcc is destroyed while submission to the SYCL queue happens before.
Also we need a solution for host and interop tasks, and I would expect that their timestamp are aligned with kernel tasks for a given SYCL queue.

What about having something like:

In device c'tor:

InitTimeDiff = piGetDeviceTime(PIDevice) - get_host_time();

In the queue::submit:

ResEvent->SubmitTime = get_host_time();

In the event::get_info:

case command_submit:
  return SubmitTime;
case command_start:
  return Device->InitTimeDiff + piGetEventInfo(PIEvent, START_TIME);
case command_end:
  return Device->InitTimeDiff + piGetEventInfo(PIEvent, END_TIME);

[smaslov-intel]

This feature implements calculating and returning the submission time of a command group associated with an event in level-zero. The submission time calculated by querying the device's wall-clock time right before a commandlist is submitted for execution.

I don't fully understand what it is trying to do and why, please elaborate. How are currently returned times not OK?

[raaiq1]

I don't fully understand what it is trying to do and why, please elaborate. How are currently returned times not OK?

Currently, level-zero constantly returns 0 when querying for command submission time. Which is very misleading

[smaslov-intel]

I don't fully understand what it is trying to do and why, please elaborate. How are currently returned times not OK?

Currently, level-zero constantly returns 0 when querying for command submission time. Which is very misleading

I am rather asking about the code in piDeviceTime::get
What it does and why? And when is that OK to call?

[raaiq1]

Ohh, sorry I misunderstood. All piDeviceTime::get does is get the current device time when called.

And when is that OK to call?

I'm not sure if I understand correctly what you mean. If you're asking at what point it's called when submitting a command to L0; for that, I've set the arbitrary point of right before the call to queue->executeCommandList()

[raaiq1]

@smaslov-intel If you mean in what functions it should be used in. It should be where commands are being enqueued such as piEnqueueEventsWaitWithBarrier, piEnqueueKernelLaunch, etc.

[smaslov-intel]

can this be moved to executeCommandList?

[raaiq1]

I would need to add a pi_event parameter to executeCommandList and executeOpenCommandList. Is that okay?

[smaslov-intel]

Why don't you just record ALL events in the command-list? Maybe we should actually do this at batch submission?

[raaiq1]

Why don't you just record ALL events in the command-list?

Wouldn't it be redundant to record all events as their profiling information wouldn't be visible to the user?

Maybe we should actually do this at batch submission?

I might be wrong but doesn't executeCommandList submit to the command to a batch if were not using immediatecommandlist ?

[smaslov-intel]

The executeCommandList does add commands to a batch, but closes it and submits if the batch is full. This is the time when I think you should record the "command_submit" time. All events in the command-list are from these enqueue interfaces, so you are already recording submit time for all of the commands.

[raaiq1]

According to SYCL specifications, the submission time has to be calculated before the submit method returns. If we record the submission time when the batch is submitted, can't we run into a possibility that the time is recorded after queue.submit() returns ?

[smaslov-intel]

I think you are right here, still you'd do it inside executeCommandList

[raaiq1]

There seems to be an with issue with this design and SYCL RT as well, as @romanovvlad highlighted. The following code in hanging indefinetly under the current design:

accessor HostAcc = Buf.get_access();
auto e=Q.submit(/*a kernel writing to Buf*/); // Command1
std::cout << e.get_profiling_info<info::event_profiling::command_submit>(); //program hangs here
HostAcc.~accessor();

Seems like get_profiling_info() is waiting for Command1 to complete even though querying the submission time shouldn't require such operation and the Command1 cannot execute untill HostAcc is destroyed. Even if I fix that problem, the returned time is always 0. Calculating the submission time in SYCL not L0 seems to solve this issue. I've opened a draft PR for the alternate design: #7526

[smaslov-intel]

I've lost track of where this is going.

There seems to be an with issue with this design and SYCL RT as well, as @romanovvlad highlighted. The following code in hanging indefinetly under the current design:

accessor HostAcc = Buf.get_access();
auto e=Q.submit(/*a kernel writing to Buf*/); // Command1
std::cout << e.get_profiling_info<info::event_profiling::command_submit>(); //program hangs here
HostAcc.~accessor();

Seems like get_profiling_info() is waiting for Command1 to complete even though querying the submission time shouldn't require such operation and the Command1 cannot execute untill HostAcc is destroyed. Even if I fix that problem, the returned time is always 0. Calculating the submission time in SYCL not L0 seems to solve this issue. I've opened a draft PR for the alternate design: #7526

There is no "waiting" in the L0 Plugin, just querying:

llvm/sycl/plugins/level_zero/pi_level_zero.cpp

Line 5780 in 7b47ebb

pi_result piEventGetProfilingInfo(pi_event Event, pi_profiling_info ParamName,

[raaiq1]

There is no waiting in the plugin layer but there is at SYCL runtime, where all specializations of event::get_profiling_info() have a wait before they query for profiling info. If I remove the wait operation for the command_submit specialization, I get constantly get 0 in return.

[smaslov-intel]

There is no waiting in the plugin layer but there is at SYCL runtime, where all specializations of event::get_profiling_info() have a wait before they query for profiling info. If I remove the wait operation for the command_submit specialization, I get constantly get 0 in return.

So, are you going to remove the wait() since it's against the spec? Why "0" is returned always after that?

[raaiq1]

So, are you going to remove the wait() since it's against the spec?

Yes, I'll prepare a separate PR to resolve that issue soon.

Why "0" is returned always after that?

I'm not sure. I still need to figure that out.

[raaiq1]

Why "0" is returned always after that?

Seems like the host_accessor is blocking the enqueue of the kernel in "Command1" (from the example in my earlier post), which in turn queries the submit time