hexagon: support for op-trace (fine-grain tracing of HVX/HMX/DMA events)

[max-krasnyansky]

Overview

This PR introduces ggml-hexagon Op Trace.
Op Trace is basically a sequence of fine-grain events per HVX/HMX/DMA work/thread.
The NPU stores these events in a buffer provided by the host as part of the Op Batch request.
When the Op Batch response comes back the host dumps those events into the regular debug logging stream mixed with the existing Op Profile records.
The PR updates existing scripts/snapdragon/ggml-hexagon-profile.py script to generate some new stats based on the traces, and adds new scripts/snapdragon/ggml-hexagon-trace.py that generates Perfetto trace files for visualization.

This PR requires #24490 in order to handle the increased logging load.
For now to make it usable I included the logging update here, will remove once the logging stuff goes in.

Usage examples

Details

Run a model with op-tracing:

PROF=3 M=../gguf/Llama-3.2-3B-Instruct-Q4_0.gguf D=HTP0 ./scripts/snapdragon/adb/run-completion.sh --jinja -st -f ../sample_input.txt -n 16 --no-warmup 2>&1 | tee hex-log

PROF=3 is a shorthand for GGML_HEXAGON_OPPROFILE=3 which enables both general profiling and tracing

Here is an example of the logging output

0.01.576.635 D ggml-hex: HTP0 profile-op MUL_MAT: blk.0.attn_q.weight x attn_norm-0 -> Qcur-0 : 3072:3072 x 3072:42 -> 3072:42 : q4_0 x f32 -> f32 : 18:1728 x 4:12288 -> 4:12288 : usec 400 cycles 846644 start 3726762947 mhz 2116.6
0.01.576.635 D ggml-hex: HTP0 trace-op MUL_MAT: thread 0 event DMA info 4 start 3726780057
0.01.576.636 D ggml-hex: HTP0 trace-op MUL_MAT: thread 0 event HVX_A_PREP info 0 start 3726790493
0.01.576.636 D ggml-hex: HTP0 trace-op MUL_MAT: thread 0 event HVX_A_PREP info 0 stop 3726857686
0.01.576.636 D ggml-hex: HTP0 trace-op MUL_MAT: thread 0 event DMA info 4 stop 3726891401
0.01.576.637 D ggml-hex: HTP0 trace-op MUL_MAT: thread 0 event HVX_W_DEQUANT info 0 start 3726894440
0.01.576.637 D ggml-hex: HTP0 trace-op MUL_MAT: thread 0 event HVX_W_DEQUANT info 0 stop 3726988948
0.01.576.637 D ggml-hex: HTP0 trace-op MUL_MAT: thread 0 event DMA info 5 start 3726990058
0.01.576.638 D ggml-hex: HTP0 trace-op MUL_MAT: thread 0 event DMA info 5 stop 3727021387

These logs can be post-processed with the included scripts

$ ./scripts/snapdragon/ggml-hexagon-profile.py --timeline summary --tail 100 hex-log

====================================================================================================
MUL_MAT (3072:1024 x 3072:42 -> 1024:42 : q4_0 x f32 -> f32) - 163 usec 345609 cycles
====================================================================================================
  Thread 0 (HVX)  : W-DEQUANT 161582 (46.8%) | DMA 91008 (26.3%) | A-PREP 51117 (14.8%) | O-PROC 8332 (2.4%)
  Thread 1 (HVX)  : W-DEQUANT 176992 (51.2%) | A-PREP 49975 (14.5%) | O-PROC 4251 (1.2%)
  Thread 2 (HVX)  : W-DEQUANT 176625 (51.1%) | A-PREP 1509 (0.4%) | O-PROC 53 (0.0%)
  Thread 3 (HVX)  : W-DEQUANT 163565 (47.3%) | A-PREP 1562 (0.5%) | O-PROC 48 (0.0%)
  Thread 4 (HVX)  : W-DEQUANT 181874 (52.6%) | A-PREP 1078 (0.3%) | O-PROC 98 (0.0%)
  Thread 5 (HVX)  : W-DEQUANT 180736 (52.3%) | A-PREP 3137 (0.9%) | O-PROC 85 (0.0%)
  Thread 6 (HVX)  : W-DEQUANT 177743 (51.4%) | A-PREP 2377 (0.7%) | O-PROC 50 (0.0%)
  Thread 7 (HVX)  : W-DEQUANT 178647 (51.7%) | A-PREP 2109 (0.6%) | O-PROC 46 (0.0%)
  Thread 10 (HMX) : M-COMP 35937 (10.4%)

./scripts/snapdragon/ggml-hexagon-trace.py -o llama3.2-3B-optrace.perfetto-trace --tail 100 hex-log
Successfully generated Perfetto trace at llama3.2-3B-optrace.perfetto-trace

Use perfetto ui to load and display llama3.2-3B-optrace.perfetto-trace.

Requirements

• I have read and agree with the contributing guidelines
• AI usage disclosure: Yes. Mostly for the python post-proc scripts. Implemented the core tracing bits myself and used Antigravity to help instrument all matmul and flash-atten code.

[max-krasnyansky]

@lhez @ggml-org/maintainers
This should be ready to go in. The changes in common/log.cpp I've been waiting for are in.
Please take a look & approve.

[max-krasnyansky]

@ggml-org/maintainers can I get the second approval please (comments are welcome too of course).

[CISC]

Even though this is not likely to overflow it's common curtesy to use snprintf. :)

I see there are a few other sprintfs in hexagon already...

[max-krasnyansky]

Sounds good. Thanks for reviewing.
I'm going to merge but will follow up shortly. I have another big MUL_MAT update that is almost ready and it uses/extends this tracing stuff a bit so I'll just replace all sprintfs() in there.