[CUDA] ProfilingTag/profiling_queue.cpp failing on unrelated changes

[sarnex]

Describe the bug

https://github.com/intel/llvm/actions/runs/9374542664/job/25810825578

# RUN: at line 3
/__w/llvm/llvm/toolchain/bin//clang++   -fsycl -fsycl-targets=nvptx64-nvidia-cuda  /__w/llvm/llvm/llvm/sycl/test-e2e/ProfilingTag/profiling_queue.cpp -o /__w/llvm/llvm/build-e2e/ProfilingTag/Output/profiling_queue.cpp.tmp.out
# executed command: /__w/llvm/llvm/toolchain/bin//clang++ -fsycl -fsycl-targets=nvptx64-nvidia-cuda /__w/llvm/llvm/llvm/sycl/test-e2e/ProfilingTag/profiling_queue.cpp -o /__w/llvm/llvm/build-e2e/ProfilingTag/Output/profiling_queue.cpp.tmp.out
# note: command had no output on stdout or stderr
# RUN: at line 4
env SYCL_PI_CUDA_ENABLE_IMAGE_SUPPORT=1 ONEAPI_DEVICE_SELECTOR=cuda:gpu  /__w/llvm/llvm/build-e2e/ProfilingTag/Output/profiling_queue.cpp.tmp.out
# executed command: env SYCL_PI_CUDA_ENABLE_IMAGE_SUPPORT=1 ONEAPI_DEVICE_SELECTOR=cuda:gpu /__w/llvm/llvm/build-e2e/ProfilingTag/Output/profiling_queue.cpp.tmp.out
# .---command stdout------------
# | StartTagSubmit: 84403198
# | StartTagStart: 84461570
# | StartTagEnd: 84463615
# | EndTagSubmit: 84465667
# | EndTagStart: 84515838
# | EndTagEnd: 84518913
# | E1Start: 84467712
# | E1End: 84513793
# | E2Start: 84459518
# | E2End: 84503555
# | StartTagEnd <= E2Start Failed!
# `-----------------------------
# error: command failed with exit status: 1

This seems to also affect other ProfilingTag tests, e.g. in_order_queue.cpp in https://github.com/intel/llvm/actions/runs/9348977102/job/25729306575.

To reproduce

No response

Environment

No response

Additional context

No response

[steffenlarsen]

Edited the description as it looks like this affects other ProfilingTag tests as well.

[konradkusiak97]

This surprisingly still fails on CUDA with the latest changes to the timing events: oneapi-src/unified-runtime#1634

The only tests that I am able to trigger to fail are the default_queue.cpp and in_order_queue.cpp. In both cases the tests randomly fail with

StartTagSubmit <= StartTagEnd Failed! 
StartTagSubmit <= StartTagStart Failed!

Those only fail when other tests are run concurrently e.i. running default_queue.cpp 1000 times in a loop passes but if at the same time other tests are triggered, it will fail randomly.

Since we are using now an extra stream to record the submission time (the HostSubmitTimeStream), my guess is that sometimes this stream is just not ready to record before the main workload stream is (this one records start and end tags). Moving creation of the HostSubmitStream to urQueueCreate or even earlier, when Context is created also doesn't solve the issue so we might need to think of a different way how to record the host submission time, I might be wrong though.

[steffenlarsen]

Without having had a look, it only happening for default_queue.cpp and in_order_queue.cpp could point towards some differing behavior w.r.t. when profiling is enabled on the queue. This could be from either the runtime or the UR adapter, though given it only happens for CUDA I would assume the latter.

That said, it could also be timing-based, so it could also be a red herring.

[konradkusiak97]

I think the reason why the other two tests are not failing could be because when profiling is enabled on the queue, that triggers the HostSubmitTimeStream to be created and used already in the very first kernel, before StartTagE. I checked that If we move StartTagE before that kernel, those tests will also fail. Following this logic, I tried to create HostSubmitTimeStream regardless of if any profiling is enabled and use it also to record EvBase. This gave the best results with the tests only failing on the 10th try.

I think this could be timing-based as you say. In the end, we don't enforce any dependency between submit time event and start time event so we can't guarantee they will be recorded in that order maybe.