janestreet/magic-trace

Exception raised while parsing perf output

dqminh opened this issue · 4 comments

dqminh commented

magic-trace failed to parse perf output with the following errors:

(monitor.ml.Error
 ("BUG: exception raised while parsing perf output. Please report this to https://github.com/janestreet/magic-trace/issues/"
  (exn Not_found)
  (perf_output
   ("1907478/1909463 457407.880965552:          1                                branches:uH:   int                      564aa58813d4 Builtins_RunMicrotasks+0x554 (/usr/local/bin/workload) =>     564aa584fa00 Builtins_Call_ReceiverIsNotNullOrUndefined+0x0 (/usr/local/bin/workload)")))
 ("Raised at Base__Error.raise in file \"src/error.ml\" (inlined), line 9, characters 14-30"
  "Called from Base__Error.raise_s in file \"src/error.ml\", line 10, characters 19-40"
  "Called from Async_kernel__Pipe.map.(fun) in file \"src/pipe.ml\", line 1042, characters 65-70"
  "Called from Async_kernel__Job_queue.run_jobs in file \"src/job_queue.ml\", line 167, characters 6-47"
  "Caught by monitor Monitor.protect"))

I have:

perf --version
perf version 5.15.59

It looks to me that int flag is not recognized properly by magic-trace

cgaebel commented

I ran this through our test suite and it looks like it's parsing int just fine. The part that's confusing it is the bit that says 1 ... branches:uH:. I haven't seen that in my traces before.

Can you say more about how you invoked magic-trace and the machine you're running it on?

Also, can you take this again but with the environment variable setting MAGIC_TRACE_DEBUG=1 and the extra argument -z-print-perf-commands, and send me the perf commands it output?

Sorry it took so long for us to get back to you. We're still here, just distracted with some other projects for a little while.

dqminh commented

@cgaebel no problem at all, thanks for the reply

Can you say more about how you invoked magic-trace and the machine you're running it on?
Also, can you take this again but with the environment variable setting MAGIC_TRACE_DEBUG=1 and the extra argument -z-print-perf-commands, and send me the perf commands it output?

Here is the output of magic-trace.

perf record -o /tmp/magic_trace.tmp.0538ae/perf.data --timestamp --event=intel_pt/cyc=1,cyc_thresh=1,mtc_period=0/u -p 2993932 --snapshot=e
[ Attached. Press Ctrl-C to stop recording. ]
[ Got signal, detaching... ]
[ Snapshot taken. ]
[ perf record: Woken up 72 times to write data ]
Warning:
Processed 1034389 events and lost 25 chunks!

Check IO/CPU overload!

[ perf record: Captured and wrote 63.116 MB /tmp/magic_trace.tmp.0538ae/perf.data ]
[ Finished recording. ]
[ Decoding, this takes a while... ]
perf script -i /tmp/magic_trace.tmp.0538ae/perf.data --ns --itrace=bep -F pid,tid,time,flags,ip,addr,sym,symoff,synth,dso,event,period

The part that's confusing it is the bit that says 1 ... branches:uH:. I haven't seen that in my traces before.

I don't understand why this is confusing. Appearance of branches:uH: FLAG seems normal to me. Can you explain a bit more ?

pikrzysztof commented 
~/dev/web/org/queues/utilization-latency utilization-latency 16:32:28 RC=1» MAGIC_TRACE_DEBUG=1 magic-trace run -z-print-perf-commands ./target/debug/utilization-latency
perf record -o /tmp/magic_trace.tmp.4f22c9/perf.data --event=intel_pt/cyc=1,cyc_thresh=1,mtc_period=0/u --timestamp --per-thread -t 55120 --snapshot=e
[ Snapshot taken. ]
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.127 MB /tmp/magic_trace.tmp.4f22c9/perf.data ]
[ Finished recording. ]
[ Decoding, this takes a while... ]
perf script -i /tmp/magic_trace.tmp.4f22c9/perf.data --ns --itrace=be -F pid,tid,time,flags,ip,addr,sym,symoff
(monitor.ml.Error
 ("BUG: exception raised while parsing perf output. Please report this to https://github.com/janestreet/magic-trace/issues/"
  (exn Not_found)
  (perf_output
   "  55120/55120   27316.814463791:   tr end  async              55fcb56d25b4 _fini+0x0 =>                0 [unknown]"))
 ("Raised at Base__Error.raise in file \"src/error.ml\" (inlined), line 9, characters 14-30"
  "Called from Base__Error.raise_s in file \"src/error.ml\", line 10, characters 19-40"
  "Called from Async_kernel__Pipe.map.(fun) in file \"src/pipe.ml\", line 1042, characters 65-70"
  "Called from Async_kernel__Job_queue.run_jobs in file \"src/job_queue.ml\", line 167, characters 6-47"
  "Caught by monitor Monitor.protect"))
~/dev/web/org/queues/utilization-latency utilization-latency 16:33:49 RC=255» perf --version
perf version 6.6-1
~/dev/web/org/queues/utilization-latency utilization-latency 16:34:41 RC=0» uname -r
6.6.8-arch1-1
wbthomason commented

@pikrzysztof I'm also encountering this crash, but I think it may be expected - per #31, async is not supported (though it would be nice if it were added).