jvm-profiling-tools / perf-map-agent

A java agent to generate method mappings to use with the linux `perf` tool
GNU General Public License v2.0
1.65k stars 260 forks source link

incorrect method resolution? #4

Closed phraktle closed 9 years ago

phraktle commented 10 years ago

Hi,

I'm seeing some methods being unexpectedly listed high on perf top, which are called very infrequently. I have cross-checked with a JMC flight recording (which I assume to be quite accurate), and these paths were not showing up there at all.

Is there a chance that the map is somehow inaccurate, perhaps over time with hotspot recompiling / deoptimizing / moving stuff around?

Btw, this agent is quite useful, keep up the good work :)

Regards, Viktor

jrudolph commented 10 years ago

There are two possible explanations:

1) Hotspot is indeed sometimes moving stuff around, so numbers may get inaccurate after a while because the map file is appended to during a run, restarting perf top should pickup the current data

2) Currently the map file contains only "top-level" methods into which a lot of smaller methods may have been inlined. This means that an entry for a method in the profile may in fact serve as a kind of container for everything that was inlined into the method as well. I've got a local version of the agent that emits more accurate map-files which also specifies for every part of a method which method was inlined at this PC.

phraktle commented 10 years ago

Thanks – I believe it was 1) in this case. I actually kinda like 2) as it is: perf top shows items with a reasonably large granularity :)

phraktle commented 10 years ago

I'm still seeing some strange artifacts in perf top (started fresh) that don't fit my mental model of the application and do not correlate with what JMC reports as hotspots. Not sure how to go further with this observation, as various profilers seem to have very different sampling biases. My understanding was that traditional java profilers (e.g. YourKit, JProfiler, etc) can only sample at safepoints, which makes them very inaccurate (our application has low enough latency for this bias to be obviously wrong). JMC seems to be doing a much better job, and I expected perf to be quite close.

jrudolph commented 10 years ago

You should be able to track (re)compilations with the -XX:+LogCompilation flag. This may offer some advice if address ranges were used several times. Another (hardcore) way of checking results would be to use -XX:+PrintAssembly and log the assembly into a file. Then go through some of the entries which perf report reports in its more verbose output modes and check the actual addresses against the disassembly if it makes more sense. Also, I've read that the addresses reported by the performance counters are not completely accurate so there could be a slight skew that may associate a sample with the wrong method (IMO only relevant for very small methods).

brendangregg commented 9 years ago

I debugged these and found that the dynamic ordering of the map file confused perf_events. If I took the map file and cleaned it up (removed stale entries, sorted), then perf_events would show correct symbols. My program to do this is https://github.com/brendangregg/Misc/blob/master/perf_events/perfmaptidy.pl, however, Johannes just updated perf-map-agent to dump the map file on-demand, which hopefully clears the issue (and my perfmaptidy.pl program should not be needed).

jrudolph commented 9 years ago

Is there a way to check this (or documentation on the expected format of the perm-<pid>.map file? As we are now generating the whole file in one go, we could also sort entries by address if that's required.

jrudolph commented 9 years ago

As @brendangregg noted above this should be fixed by now.