Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Exception raised while parsing perf output #257

Open
dqminh opened this issue Aug 31, 2022 · 4 comments
Open

Exception raised while parsing perf output #257

dqminh opened this issue Aug 31, 2022 · 4 comments
Labels
bug Something isn't working
Milestone

Comments

@dqminh
Copy link

dqminh commented Aug 31, 2022

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

@dqminh dqminh added the bug Something isn't working label Aug 31, 2022
@cgaebel
Copy link
Contributor

cgaebel commented Sep 25, 2022

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
Copy link
Author

dqminh commented Sep 28, 2022

@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 ?

Xyene added a commit to Xyene/magic-trace that referenced this issue Nov 14, 2022
Not quite sure why we'd be seeing this, but let's not crash when we do.
For now, treat a software interrupt as a jump.

Ref janestreet#257
Xyene added a commit to Xyene/magic-trace that referenced this issue Nov 14, 2022
Not quite sure why we'd be seeing this, but let's not crash when we do.
For now, treat a software interrupt as a jump.

Ref janestreet#257
@Xyene Xyene added this to the v1.2.0 milestone Nov 14, 2022
Xyene added a commit to Xyene/magic-trace that referenced this issue Nov 14, 2022
Not quite sure why we'd be seeing this, but let's not crash when we do.
For now, treat a software interrupt as a jump.

Ref janestreet#257
@pikrzysztof
Copy link

pikrzysztof commented Dec 31, 2023

~/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
Copy link

@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).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

5 participants