"magic-trace run -trace-include-kernel true" failure

[ednolan]

Tested with the following magic-trace versions:

• 5e8fdd3, built from source (output below is from testing this version)
• Version 1.0.2, 0a5dd46, downloaded from the releases page

Tested on Ubuntu 22.04, on an Intel i7-7700HQ processor.

Running without -trace-include-kernel succeeds:

$ _build/default/bin/magic_trace_bin.exe run true
[ perf record: Woken up 1 times to write data ]
[ Snapshot taken. ]
[ perf record: Captured and wrote 0.062 MB /tmp/magic_trace.tmp.09aec4/perf.data ]
[ Finished recording. ]
[ Decoding, this takes a while... ]
Warning: Debug info is unavailable, so filenames and line numbers will not be available in the trace.
See https://github.com/janestreet/magic-trace/wiki/Compiling-code-for-maximum-compatibility-with-magic-trace for more info.
Visit https://magic-trace.org/ and open trace.fxt to view trace.

Running with -trace-include-kernel fails:

$ sudo -s
root@ed-ubuntu-asus:/home/eddie/magic-trace# _build/default/bin/magic_trace_bin.exe run -trace-include-kernel true
[ Snapshot taken. ]
[ Finished recording. ]
[ Decoding, this takes a while... ]
Warning: Debug info is unavailable, so filenames and line numbers will not be available in the trace.
See https://github.com/janestreet/magic-trace/wiki/Compiling-code-for-maximum-compatibility-with-magic-trace for more info.
WARNING: The /tmp/magic_trace.tmp.6b36cb/perf.data/data file's data size field is 0 which is unexpected.
Was the 'perf record' command properly terminated?
(Unix.Exit (Exit_non_zero 255))

[Xyene]

Thanks for reporting.

Could you try:

• running with MAGIC_TRACE_DEBUG=1 magic-trace ... -z-print-perf
• run the perf commands yourself (you might want to use attach with a longer-running process)
• see if there are more descriptive errors?

[ednolan]

Here's the result of trying that:

root@ed-ubuntu-asus:/home/eddie/magic-trace# export MAGIC_TRACE_DEBUG=1
root@ed-ubuntu-asus:/home/eddie/magic-trace# _build/default/bin/magic_trace_bin.exe run -z-print-perf -trace-include-kernel true
perf record -o /tmp/magic_trace.tmp.fa06c8/perf.data --event=intel_pt/cyc=1,cyc_thresh=1,mtc_period=0/uk --timestamp --per-thread -t 186978 --snapshot=e --kcore
[ Snapshot taken. ]
[ Finished recording. ]
[ Decoding, this takes a while... ]
perf script -i /tmp/magic_trace.tmp.fa06c8/perf.data --ns --itrace=be -F pid,tid,time,flags,ip,addr,sym,symoff
Warning: Debug info is unavailable, so filenames and line numbers will not be available in the trace.
See https://github.com/janestreet/magic-trace/wiki/Compiling-code-for-maximum-compatibility-with-magic-trace for more info.
WARNING: The /tmp/magic_trace.tmp.fa06c8/perf.data/data file's data size field is 0 which is unexpected.
Was the 'perf record' command properly terminated?
(Unix.Exit (Exit_non_zero 255))
root@ed-ubuntu-asus:/home/eddie/magic-trace# yes > /dev/null &
[1] 187111
root@ed-ubuntu-asus:/home/eddie/magic-trace# perf record -o /tmp/magic_trace.tmp.fa06c8/perf.data --event=intel_pt/cyc=1,cyc_thresh=1,mtc_period=0/uk --timestamp --per-thread -t 187111 --snapshot=e --kcore
Perf session creation failed.

[ednolan]

Never mind the above, the perf command in question just failed because I pointed it to a temporary directory that had already been deleted. The same command works when I create the output directory manually:

root@ed-ubuntu-asus:/home/eddie/magic-trace# mkdir /tmp/test
root@ed-ubuntu-asus:/home/eddie/magic-trace# perf record -o /tmp/test/perf.data --event=intel_pt/cyc=1,cyc_thresh=1,mtc_period=0/uk --timestamp --per-thread -t 187111 --snapshot=e --kcore
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 4.027 MB /tmp/test/perf.data ]

And in fact, magic-trace attach works fine as well:

root@ed-ubuntu-asus:/home/eddie/magic-trace# _build/default/bin/magic_trace_bin.exe attach -z-print-perf -trace-include-kernel -p 187111
perf record -o /tmp/magic_trace.tmp.bab32c/perf.data --event=intel_pt/cyc=1,cyc_thresh=1,mtc_period=0/uk --timestamp --per-thread -t 187111 --snapshot=e --kcore
[ Attached. Press Ctrl-C to stop recording. ]
^C[ Got signal, detaching... ]
[ Snapshot taken. ]
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 4.027 MB /tmp/magic_trace.tmp.bab32c/perf.data ]
[ Finished recording. ]
[ Decoding, this takes a while... ]
perf script -i /tmp/magic_trace.tmp.bab32c/perf.data --ns --itrace=be -F pid,tid,time,flags,ip,addr,sym,symoff
Warning: Debug info is unavailable, so filenames and line numbers will not be available in the trace.
See https://github.com/janestreet/magic-trace/wiki/Compiling-code-for-maximum-compatibility-with-magic-trace for more info.
Warning:
2 instruction trace errors
Visit https://magic-trace.org/ and open trace.fxt to view trace.

It's just magic-trace run with the short-lived true process, and with -trace-include-kernel, that seems not to work.

[Xyene]

Thanks for trying that. What's your perf version? Snapshot-at-exit (which is necessary to get traces of very short-lived processes) was technically introduced in perf 5.4, but we've seen it be broken in 5.4 (but never in e.g. 5.17).

[ednolan]

root@ed-ubuntu-asus:/home/eddie/magic-trace# perf --version
perf version 5.15.30