KEMBAR78
Running jfr2flame on concatenated JFR files produces nonsense stacktraces · Issue #849 · async-profiler/async-profiler · GitHub
Skip to content

Running jfr2flame on concatenated JFR files produces nonsense stacktraces #849

@gharris1727

Description

@gharris1727

Hi, and thanks so much for the async-profiler!

I'm trying to use the async-profiler to profile a short-lived JVM from start-to-finish.
I couldn't figure out a way to send a stop command during JVM shutdown, so I have been using this agent string to approximate a full profile:

-agentpath:/path/to/libasyncProfiler.so=start,event=wall,loop=1s,jfr,file=/tmp/output/%n.jfr

This generates multiple JFR files that I then concatenate together, and pass through jfr2flame. But the output isn't what I expect. Here's a repro case:

export PROFILER="/path/to/async/profiler"
echo "Thread.sleep(3000)" | jshell "-J-agentpath:$PROFILER/build/libasyncProfiler.so=start,event=wall,loop=1s,jfr,file=/tmp/output/%n.jfr"
cat /tmp/output/* > /tmp/combined.jfr
java -cp "$PROFILER/converter.jar" jfr2flame /tmp/combined.jfr /tmp/out.html --threads

Open the output HTML, click on the "main" thread, and search for "JShell.eval". For me on 2.9, it looks like this:
Flamegraph showing three separate blocks for JShell.eval
The stacktrace with the most samples appears to be the correct one, the ones on the right side show JShell.eval without a parent frame, or show JShell.eval eventually calling itself, which isn't happening in reality.

I checked the output of the jfr tool for the combined.jfr, and it looks to generate reasonable stacktraces:

jfr print --stack-depth 1000 /tmp/combined.jfr | grep -A 1 JShell.eval

The output looks like this:

    jdk.jshell.JShell.eval(String) line: 513
    jdk.internal.jshell.tool.JShellTool.processSource(String) line: 3633
--
    jdk.jshell.JShell.eval(String) line: 513
    jdk.internal.jshell.tool.JShellTool.processSource(String) line: 3633
--
<snipped>

The jfr tool shows stack frame above JShell.eval is always JShellTool.processSource, where the flame graph does not make this clear. I checked other discrepancies in the flamegraph against the jfr tool, and they sometimes disagree, as if the end of one stacktrace got appended to the other.

I would expect that after profiling a program that only calls a method once, that method would only appear once in the flamegraph with a consistent stacktrace. This should happen whether or not the profile is performed in one JFR file or across multiple JFR files with loop.

  1. The jshell usage is just a concise example, I am profiling a non-trivial program and seeing similar behavior.
  2. I don't see the corruption when running jfr2flame on the individual JFR files generated by the loop.
  3. I tried using the jfr tool to assemble the JFR files and got the same result as plain concatenation
  4. Changing the order of concatenation appears to change the resulting flame graph, but doesn't fix it.

Thanks!

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions