Skip to content

feat(rocprofiler-sdk): add hip event tracing sample - #11476

Draft
meserve-amd wants to merge 2 commits into
developfrom
users/meserve-amd/hip-event-sample
Draft

feat(rocprofiler-sdk): add hip event tracing sample#11476
meserve-amd wants to merge 2 commits into
developfrom
users/meserve-amd/hip-event-sample

Conversation

@meserve-amd

@meserve-amd meserve-amd commented Sep 10, 2026

Copy link
Copy Markdown
Contributor

Motivation

Adds an example that exercises HIP event tracing and kernel dispatch tracing.

The sample runs two scenarios. The first is a simple case where a wait is requested for stream 2 waiting on stream 1 and a wait event is produced. In the second case, the same wait is requested after stream 1's event is complete, resulting in no barrier and no wait event being traced.

The example uses both callback tracing and buffer tracing to show how they might be used. The callback tracing allows us to log the program flow directly and is most of the code. I attempted to add a lot of prose to the log to explain the scenarios as they were executing.

Technical Details

I recommend reading the README.md included in the PR

Sample Output

Perhaps the most useful part of the sample is its output, so:

$ bin/hip-event-tracing 
HipEventTracingTool (priority=0) is using rocprofiler-sdk v1.4.1 (1.4.1)
W0910 21:57:40.826546  397180 registration.cpp:763] initialized tool configure for HipEventTracingTool :: 0x7ff809bdfc00 :: 0x58f5000 :: 0x7ff809be2910 :: 0x7ff809be7d40
W0910 21:57:40.826566  397180 registration.cpp:813] invoking tool initialize for HipEventTracingTool :: 0x7ff809bdfc00 :: 0x58f5000 :: 0x7ff809be2910 :: 0x7ff809be7d40
[+    256.268 us] SETUP     :: tracing kind 'HIP_EVENT' with operations HIP_EVENT_RECORD and HIP_EVENT_WAIT
[+    295.667 us] NOTIFY    :: internal thread about to be created by rocprofiler (lib=1)
[+    429.500 us] NOTIFY    :: internal thread was created by rocprofiler (lib=1)
[+    446.115 us] NOTIFY    :: internal thread about to be created by rocprofiler (lib=1)
[+    501.348 us] NOTIFY    :: internal thread was created by rocprofiler (lib=1)
[+  90633.058 us] APP       :: hip-event-tracing: 2 iteration(s) of each case, 1024 elements, spin_kernel loop count 5000000

                  ========================================================================
[+  90652.417 us] APP       :: WARM-UP: running one of each kernel so that one-time setup work does not land in the middle of the first traced iteration
                  ========================================================================
[+  90696.534 us] DISPATCH  :: __amd_rocclr_fillBufferAligned.kd completed on queue 3
                    op=KERNEL_DISPATCH  kernel_id=  4 cid=   1 queue=3 start=2586825175867159 end=2586825175870639 elapsed=     3.480us
[+  90728.663 us] DISPATCH  :: __amd_rocclr_fillBufferAligned.kd completed on queue 3
                    op=KERNEL_DISPATCH  kernel_id=  4 cid=   3 queue=3 start=2586825175883359 end=2586825175886679 elapsed=     3.320us
[+  90739.699 us] DISPATCH  :: __amd_rocclr_fillBufferAligned.kd completed on queue 3
                    op=KERNEL_DISPATCH  kernel_id=  4 cid=   2 queue=3 start=2586825175877079 end=2586825175879319 elapsed=     2.240us
[+  93677.833 us] DISPATCH  :: _Z15follower_kernelPfm.kd completed on queue 2
                    op=KERNEL_DISPATCH  kernel_id= 17 cid=   6 queue=2 start=2586825176362772 end=2586825178900351 elapsed=  2537.579us
[+  93688.399 us] DISPATCH  :: _Z11spin_kernelPfm.kd completed on queue 1
                    op=KERNEL_DISPATCH  kernel_id= 18 cid=   4 queue=1 start=2586825176358212 end=2586825178896151 elapsed=  2537.939us
[+  93695.741 us] DISPATCH  :: _Z12scale_kernelPfif.kd completed on queue 1
                    op=KERNEL_DISPATCH  kernel_id= 16 cid=   5 queue=1 start=2586825178915831 end=2586825178917671 elapsed=     1.840us
[+  93723.963 us] APP       :: flushing the warm-up records
[+  93805.957 us] DISP BUF  :: __amd_rocclr_fillBufferAligned.kd dispatch on queue 3 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=   1 queue=3 kernel_id=  4 start=2586825175867159 end=2586825175870639 elapsed=     3.480us
[+  93831.726 us] DISP BUF  :: __amd_rocclr_fillBufferAligned.kd dispatch on queue 3 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=   3 queue=3 kernel_id=  4 start=2586825175883359 end=2586825175886679 elapsed=     3.320us
[+  93848.762 us] DISP BUF  :: __amd_rocclr_fillBufferAligned.kd dispatch on queue 3 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=   2 queue=3 kernel_id=  4 start=2586825175877079 end=2586825175879319 elapsed=     2.240us
[+  93866.699 us] DISP BUF  :: _Z15follower_kernelPfm.kd dispatch on queue 2 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=   6 queue=2 kernel_id= 17 start=2586825176362772 end=2586825178900351 elapsed=  2537.579us
[+  93881.562 us] DISP BUF  :: _Z11spin_kernelPfm.kd dispatch on queue 1 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=   4 queue=1 kernel_id= 18 start=2586825176358212 end=2586825178896151 elapsed=  2537.939us
[+  93896.114 us] DISP BUF  :: _Z12scale_kernelPfif.kd dispatch on queue 1 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=   5 queue=1 kernel_id= 16 start=2586825178915831 end=2586825178917671 elapsed=     1.840us

                  ========================================================================
[+  93920.150 us] APP       :: CASE 1. DEFERRED WAIT: the recorded event is still pending when stream B waits, so HIP schedules a real barrier
                  ========================================================================
[+  93929.775 us] APP       :: case 1, iteration 1 of 2.
[+  93932.669 us] APP       :: launching the long spin_kernel on stream A
[+  93942.093 us] APP       :: recording the event on stream A while spin_kernel is still running; expect a HIP_EVENT_RECORD barrier on stream A's queue
[+  93955.704 us] EVENT CB  :: HIP_EVENT_RECORD barrier about to be enqueued on queue 1
                    op=HIP_EVENT_RECORD phase=ENTER cid=   8 queue=1 src_queue=1 event=0x000005ba7b40
[+  93960.661 us] EVENT CB  :: HIP_EVENT_RECORD barrier enqueued on queue 1
                    op=HIP_EVENT_RECORD phase=EXIT  cid=   8 queue=1 src_queue=1 event=0x000005ba7b40
[+  93969.695 us] APP       :: stream B waits on stream A's not-yet-complete event; expect a HIP_EVENT_WAIT barrier on stream B's queue naming stream A's queue as its source
[+  93981.343 us] EVENT CB  :: HIP_EVENT_WAIT barrier about to be enqueued on queue 2, waiting on an event recorded in queue 1
                    op=HIP_EVENT_WAIT   phase=ENTER cid=  10 queue=2 src_queue=1 event=0x000005ba7b40
[+  93986.570 us] EVENT CB  :: HIP_EVENT_WAIT barrier enqueued on queue 2, waiting on an event recorded in queue 1
                    op=HIP_EVENT_WAIT   phase=EXIT  cid=  10 queue=2 src_queue=1 event=0x000005ba7b40
[+  94000.321 us] APP       :: launching follower_kernel on stream B; it cannot start until the wait barrier clears
[+  94008.604 us] APP       :: synchronizing both streams
[+ 130403.452 us] DISPATCH  :: _Z11spin_kernelPfm.kd completed on queue 1
                    op=KERNEL_DISPATCH  kernel_id= 18 cid=   7 queue=1 start=2586825179190654 end=2586825215628050 elapsed= 36437.396us
[+ 130417.714 us] EVENT CB  :: HIP_EVENT_RECORD barrier completed on the GPU on queue 1
                    op=HIP_EVENT_RECORD phase=NONE  cid=   8 queue=1 src_queue=1 event=0x000005ba7b40 start=2586825179196690 end=2586825215643357 elapsed= 36446.667us
[+ 130428.350 us] EVENT CB  :: HIP_EVENT_WAIT barrier completed on the GPU on queue 2, waiting on an event recorded in queue 1
                    op=HIP_EVENT_WAIT   phase=NONE  cid=  10 queue=2 src_queue=1 event=0x000005ba7b40 start=2586825179221237 end=2586825215656897 elapsed= 36435.660us
[+ 132603.389 us] DISPATCH  :: _Z15follower_kernelPfm.kd completed on queue 2
                    op=KERNEL_DISPATCH  kernel_id= 17 cid=  11 queue=2 start=2586825215648090 end=2586825217822226 elapsed=  2174.136us
[+ 132608.857 us] APP       :: case 1, iteration 2 of 2.
[+ 132615.487 us] APP       :: launching the long spin_kernel on stream A
[+ 132628.928 us] APP       :: recording the event on stream A while spin_kernel is still running; expect a HIP_EVENT_RECORD barrier on stream A's queue
[+ 132636.159 us] EVENT CB  :: HIP_EVENT_RECORD barrier about to be enqueued on queue 1
                    op=HIP_EVENT_RECORD phase=ENTER cid=  13 queue=1 src_queue=1 event=0x000005ba7b40
[+ 132642.198 us] EVENT CB  :: HIP_EVENT_RECORD barrier enqueued on queue 1
                    op=HIP_EVENT_RECORD phase=EXIT  cid=  13 queue=1 src_queue=1 event=0x000005ba7b40
[+ 132649.188 us] APP       :: stream B waits on stream A's not-yet-complete event; expect a HIP_EVENT_WAIT barrier on stream B's queue naming stream A's queue as its source
[+ 132657.922 us] EVENT CB  :: HIP_EVENT_WAIT barrier about to be enqueued on queue 2, waiting on an event recorded in queue 1
                    op=HIP_EVENT_WAIT   phase=ENTER cid=  15 queue=2 src_queue=1 event=0x000005ba7b40
[+ 132662.949 us] EVENT CB  :: HIP_EVENT_WAIT barrier enqueued on queue 2, waiting on an event recorded in queue 1
                    op=HIP_EVENT_WAIT   phase=EXIT  cid=  15 queue=2 src_queue=1 event=0x000005ba7b40
[+ 132669.659 us] APP       :: launching follower_kernel on stream B; it cannot start until the wait barrier clears
[+ 132677.551 us] APP       :: synchronizing both streams
[+ 167398.097 us] DISPATCH  :: _Z11spin_kernelPfm.kd completed on queue 1
                    op=KERNEL_DISPATCH  kernel_id= 18 cid=  12 queue=1 start=2586825217876546 end=2586825252622604 elapsed= 34746.058us
[+ 167407.691 us] EVENT CB  :: HIP_EVENT_RECORD barrier completed on the GPU on queue 1
                    op=HIP_EVENT_RECORD phase=NONE  cid=  13 queue=1 src_queue=1 event=0x000005ba7b40 start=2586825217877535 end=2586825252636579 elapsed= 34759.044us
[+ 167414.061 us] EVENT CB  :: HIP_EVENT_WAIT barrier completed on the GPU on queue 2, waiting on an event recorded in queue 1
                    op=HIP_EVENT_WAIT   phase=NONE  cid=  15 queue=2 src_queue=1 event=0x000005ba7b40 start=2586825217897476 end=2586825252643029 elapsed= 34745.553us
[+ 169596.061 us] DISPATCH  :: _Z15follower_kernelPfm.kd completed on queue 2
                    op=KERNEL_DISPATCH  kernel_id= 17 cid=  16 queue=2 start=2586825252641244 end=2586825254815260 elapsed=  2174.016us
[+ 169601.159 us] APP       :: all case 1 iterations are complete; flushing the buffer to take delivery of every barrier record collected across them at once
[+ 169655.912 us] DISP BUF  :: _Z11spin_kernelPfm.kd dispatch on queue 1 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=   7 queue=1 kernel_id= 18 start=2586825179190654 end=2586825215628050 elapsed= 36437.396us
[+ 169680.118 us] EVENT BUF :: HIP_EVENT_RECORD barrier on queue 1 delivered via the buffered service (context=19282, buffer=65468)
                    op=HIP_EVENT_RECORD kind=38 op_id= 1 cid=   8 queue=1 src_queue=1 event=0x000005ba7b40 start=2586825179196690 end=2586825215643357 elapsed= 36446.667us
[+ 169696.473 us] EVENT BUF :: HIP_EVENT_WAIT barrier on queue 2 delivered via the buffered service (context=19282, buffer=65468)
                    op=HIP_EVENT_WAIT   kind=38 op_id= 2 cid=  10 queue=2 src_queue=1 event=0x000005ba7b40 start=2586825179221237 end=2586825215656897 elapsed= 36435.660us
[+ 169712.297 us] DISP BUF  :: _Z15follower_kernelPfm.kd dispatch on queue 2 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=  11 queue=2 kernel_id= 17 start=2586825215648090 end=2586825217822226 elapsed=  2174.136us
[+ 169727.179 us] DISP BUF  :: _Z11spin_kernelPfm.kd dispatch on queue 1 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=  12 queue=1 kernel_id= 18 start=2586825217876546 end=2586825252622604 elapsed= 34746.058us
[+ 169742.713 us] EVENT BUF :: HIP_EVENT_RECORD barrier on queue 1 delivered via the buffered service (context=19282, buffer=65468)
                    op=HIP_EVENT_RECORD kind=38 op_id= 1 cid=  13 queue=1 src_queue=1 event=0x000005ba7b40 start=2586825217877535 end=2586825252636579 elapsed= 34759.044us
[+ 169758.397 us] EVENT BUF :: HIP_EVENT_WAIT barrier on queue 2 delivered via the buffered service (context=19282, buffer=65468)
                    op=HIP_EVENT_WAIT   kind=38 op_id= 2 cid=  15 queue=2 src_queue=1 event=0x000005ba7b40 start=2586825217897476 end=2586825252643029 elapsed= 34745.553us
[+ 169773.339 us] DISP BUF  :: _Z15follower_kernelPfm.kd dispatch on queue 2 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=  16 queue=2 kernel_id= 17 start=2586825252641244 end=2586825254815260 elapsed=  2174.016us

                  ========================================================================
[+ 169803.515 us] APP       :: CASE 2. ALREADY-COMPLETE WAIT: the recorded event has finished before stream B waits, so HIP schedules no barrier and nothing is traced
                  ========================================================================
[+ 169815.573 us] APP       :: case 2, iteration 1 of 2.
[+ 169818.848 us] APP       :: launching the short scale_kernel on stream A
[+ 169834.792 us] APP       :: recording the event on stream A; expect a HIP_EVENT_RECORD barrier
[+ 169842.384 us] EVENT CB  :: HIP_EVENT_RECORD barrier about to be enqueued on queue 1
                    op=HIP_EVENT_RECORD phase=ENTER cid=  18 queue=1 src_queue=1 event=0x000005ba7c80
[+ 169847.752 us] EVENT CB  :: HIP_EVENT_RECORD barrier enqueued on queue 1
                    op=HIP_EVENT_RECORD phase=EXIT  cid=  18 queue=1 src_queue=1 event=0x000005ba7c80
[+ 169854.542 us] APP       :: synchronizing on the event so that it is definitely complete
[+ 169875.314 us] DISPATCH  :: _Z12scale_kernelPfif.kd completed on queue 1
                    op=KERNEL_DISPATCH  kernel_id= 16 cid=  17 queue=1 start=2586825255081602 end=2586825255083122 elapsed=     1.520us
[+ 169886.911 us] EVENT CB  :: HIP_EVENT_RECORD barrier completed on the GPU on queue 1
                    op=HIP_EVENT_RECORD phase=NONE  cid=  18 queue=1 src_queue=1 event=0x000005ba7c80 start=2586825255082879 end=2586825255115779 elapsed=    32.900us
[+ 169896.626 us] APP       :: stream B waits on the already-complete event; expect NO HIP_EVENT_WAIT record at all, because HIP has nothing to wait for and schedules no barrier
[+ 169902.955 us] APP       :: launching follower_kernel on stream B; nothing gates it
[+ 169912.700 us] APP       :: synchronizing stream B
[+ 172114.881 us] DISPATCH  :: _Z15follower_kernelPfm.kd completed on queue 2
                    op=KERNEL_DISPATCH  kernel_id= 17 cid=  19 queue=2 start=2586825255159702 end=2586825257333839 elapsed=  2174.137us
[+ 172125.838 us] APP       :: case 2, iteration 2 of 2.
[+ 172130.645 us] APP       :: launching the short scale_kernel on stream A
[+ 172138.587 us] APP       :: recording the event on stream A; expect a HIP_EVENT_RECORD barrier
[+ 172144.486 us] EVENT CB  :: HIP_EVENT_RECORD barrier about to be enqueued on queue 1
                    op=HIP_EVENT_RECORD phase=ENTER cid=  21 queue=1 src_queue=1 event=0x000005ba7c80
[+ 172150.224 us] EVENT CB  :: HIP_EVENT_RECORD barrier enqueued on queue 1
                    op=HIP_EVENT_RECORD phase=EXIT  cid=  21 queue=1 src_queue=1 event=0x000005ba7c80
[+ 172157.475 us] APP       :: synchronizing on the event so that it is definitely complete
[+ 172165.948 us] DISPATCH  :: _Z12scale_kernelPfif.kd completed on queue 1
                    op=KERNEL_DISPATCH  kernel_id= 16 cid=  20 queue=1 start=2586825257386179 end=2586825257387819 elapsed=     1.640us
[+ 172175.623 us] EVENT CB  :: HIP_EVENT_RECORD barrier completed on the GPU on queue 1
                    op=HIP_EVENT_RECORD phase=NONE  cid=  21 queue=1 src_queue=1 event=0x000005ba7c80 start=2586825257385802 end=2586825257404861 elapsed=    19.059us
[+ 172180.961 us] APP       :: stream B waits on the already-complete event; expect NO HIP_EVENT_WAIT record at all, because HIP has nothing to wait for and schedules no barrier
[+ 172186.109 us] APP       :: launching follower_kernel on stream B; nothing gates it
[+ 172194.361 us] APP       :: synchronizing stream B
[+ 174400.909 us] DISPATCH  :: _Z15follower_kernelPfm.kd completed on queue 2
                    op=KERNEL_DISPATCH  kernel_id= 17 cid=  22 queue=2 start=2586825257442719 end=2586825259620016 elapsed=  2177.297us
[+ 174411.054 us] APP       :: all case 2 iterations are complete; flushing the buffer again
[+ 174463.333 us] DISP BUF  :: _Z12scale_kernelPfif.kd dispatch on queue 1 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=  17 queue=1 kernel_id= 16 start=2586825255081602 end=2586825255083122 elapsed=     1.520us
[+ 174497.144 us] EVENT BUF :: HIP_EVENT_RECORD barrier on queue 1 delivered via the buffered service (context=19282, buffer=65468)
                    op=HIP_EVENT_RECORD kind=38 op_id= 1 cid=  18 queue=1 src_queue=1 event=0x000005ba7c80 start=2586825255082879 end=2586825255115779 elapsed=    32.900us
[+ 174514.150 us] DISP BUF  :: _Z15follower_kernelPfm.kd dispatch on queue 2 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=  19 queue=2 kernel_id= 17 start=2586825255159702 end=2586825257333839 elapsed=  2174.137us
[+ 174530.034 us] DISP BUF  :: _Z12scale_kernelPfif.kd dispatch on queue 1 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=  20 queue=1 kernel_id= 16 start=2586825257386179 end=2586825257387819 elapsed=     1.640us
[+ 174545.698 us] EVENT BUF :: HIP_EVENT_RECORD barrier on queue 1 delivered via the buffered service (context=19282, buffer=65468)
                    op=HIP_EVENT_RECORD kind=38 op_id= 1 cid=  21 queue=1 src_queue=1 event=0x000005ba7c80 start=2586825257385802 end=2586825257404861 elapsed=    19.059us
[+ 174560.470 us] DISP BUF  :: _Z15follower_kernelPfm.kd dispatch on queue 2 delivered via the buffered service (context=19282, buffer=65468)
                    op=KERNEL_DISPATCH  kind=11 op_id= 2 cid=  22 queue=2 kernel_id= 17 start=2586825257442719 end=2586825259620016 elapsed=  2177.297us

                  ========================================================================
[+ 174591.547 us] APP       :: TEARDOWN
                  ========================================================================
W0910 21:57:41.001752  397180 registration.cpp:973] invoking tool finalize for HipEventTracingTool :: 0x7ff809bdfc00 :: 0x58f5000 :: 0x0 :: 0x7ff809be7d40
[+ 175205.966 us] SHUTDOWN  :: finalizing
Outputting collected data to hip_event_trace.log...

Issue Tracking

JIRA ID: AIPROFSDK-869

Test Plan

Adds sample test that verifies that verifies the example runs successfully, but does not place a hard requirement on a wait event being produced as that can be affected by hardware. (The sample includes a recommendation to increase the spin kernel duration if this occurs).

Test Result

Works on Navi4 tester

Submission Checklist

@therock-pr-bot

Copy link
Copy Markdown

✅ All Policy Checks Passed

Check Status Details
📝 PR Description ✅ Pass
Forbidden Files ✅ Pass
🧪 Unit Test ⚠️ Warning Error: Source/code files changed without an accompanying unit test.
Expected: add at least one test file named like test_<name>.py / test_<name>.cpp (or <name>_test.*).
Current: code file(s) changed: projects/rocprofiler-sdk/samples/hip_event_tracing/client.cpp, projects/rocprofiler-sdk/samples/hip_event_tracing/client.hpp, projects/rocprofiler-sdk/samples/hip_event_tracing/main.cpp; no test file found
🚫 Draft PR 🔜 To Be Enabled
🚩 Feature Flag 🔜 To Be Enabled
📊 Code Coverage 🔜 To Be Enabled

🎉 All policy checks passed!

📖 Need help? See the Policy FAQ for details on every check and how to fix failures.

🙋 Wish to Override Policy?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant