On 05/28/20 17:32 PM, Ian Rogers wrote: > > So on tip/perf/core with: > 1c0cd2dbb993 perf jvmti: Fix jitdump for methods without debug info > 3ce17c1e52f4 perf jvmti: remove redundant jitdump line table entries > > I've been trying variants of: > > Before: > /tmp/perf/perf record -k 1 -e cycles:u -o /tmp/perf.data java > -agentpath:/tmp/perf/libperf-jvmti.so -XX:+PreserveFramePointer > -XX:InitialCodeCacheSize=20M -XX:ReservedCodeCacheSize=1G -jar > dacapo-9.12-bach.jar jython > /tmp/perf/perf inject -i /tmp/perf.data -o /tmp/perf-jit.data -j > /tmp/perf/perf report -i /tmp/perf-jit.data |grep class\ |wc -l > 578 > /tmp/perf/perf report -i /tmp/perf-jit.data |grep unknown |wc -l > 6 > > After: > /tmp/perf/perf record -k 1 -e cycles:u -o /tmp/perf.data java > -agentpath:/tmp/perf/libperf-jvmti.so -XX:+PreserveFramePointer > -XX:InitialCodeCacheSize=20M -XX:ReservedCodeCacheSize=1G -jar > dacapo-9.12-bach.jar jython > /tmp/perf/perf inject -i /tmp/perf.data -o /tmp/perf-jit.data -j > /tmp/perf/perf report -i /tmp/perf-jit.data |grep class\ |wc -l > 589 > /tmp/perf/perf report -i /tmp/perf-jit.data |grep unknown |wc -l > 60 > > So maybe the jit cache isn't behaving the way that the patch cures, > the uptick in unknowns appears consistent in my testing though. I > expect user error, is there an obvious explanation I'm missing? >
Hi Ian, I tried this as well with latest perf/core. The difference is that unresolved addresses currently look like: 0.00% java [JIT] tid 221782 [.] 0x0000ffff451499a4 0.00% java [JIT] tid 221782 [.] 0x0000ffff4514f3e8 0.00% java [JIT] tid 221782 [.] 0x0000ffff45149394 But after Steve's patch this becomes: 0.00% java [unknown] [.] 0x0000ffff58557d14 0.00% java [unknown] [.] 0x0000ffff785c03b4 0.00% java [unknown] [.] 0x0000ffff58386520 I couldn't see any events that were symbolised before but are no longer symbolised after this patch. I think most of these unknown events are caused by the asynchronous nature of the JVMTI event handling. After an nmethod is compiled the JVMTI event is posted to the Service Thread (*). So there can be a delay between the time the compiled code starts executing and the time the plugin receives the compiled code load event. Here's an edited down example: java 215881 750014.947873: 1289634 cycles:u: ffff7856ad10 [unknown] ([unknown]) Service Thread 215895 750014.947971: PERF_RECORD_MMAP2 215879/215895: [0xffff785694c0(0x640) @ 0x40 fd:01 121010091 1]: java 215881 750014.948665: 1295994 cycles:u: ffff7856ad10 org.python.core.__builtin__.range(org.python The plugin receives the event ~100us after the first sample inside that method. Ideally we would use the timestamp when the method was actually compiled, but I can't see any way to extract this information. However I also saw a few recurring [unknown] addresses that never have a corresponding code load event. I'm not sure where these come from. (*) http://hg.openjdk.java.net/jdk/jdk/file/50fe8727ed79/src/hotspot/share/code/nmethod.cpp#l1591 -- Nick