(still) unable to resolve JIT symbols

[oi0000]

Hi Johannes,

I'm trying to profile a Java program (SPECjbb2015) using linux perf + your perf-map-agent.

• java version "1.8.0_111" Java(TM) SE Runtime Environment (build 1.8.0_111-b14) Java HotSpot(TM) 64-Bit Server VM (build 25.111-b14, mixed mode)
• perf-map-agent is compiled with JAVA_HOME set to the directory of the above java (i.e. java is ${JAVA_HOME}/bin/java )
• Lunux version is 4.4.0-45 (Ubuntu)
• -XX:+PreserveFramePointer is used with java invocation
• /opt/perf-map-agent-master/bin/create-java-perf-map.sh $pid is invoked right after Java invocation where $pid is the pid of java
• the symbols from Java runtime seem to be OK, as I can see lines like follows: 6.44% 201751 java libjvm.so [.] PSPromotionManager::copy_to_survivor_space
• Most unresolved symbols are from perf-$pid-map, but still few came from libXXX (e.g. libc) or vdso
• Profiling 'cycles' events, the aggregated number of samples for unresolved symbols take about 55% to 60% of the total samples.
• Since JRE symbols are resolved, unresolved symbols seem to come from SPECjbb' jar file. I recompiled it with the following options to pom.xml -verbose -g -Xlint:all,-options,-path

  which inflated the jar size from 1.8MB to 9.1MB However, the results looked the same ( was already true in the original pom.xml).

Do you think of any (possible) mistake I'm making ? Or any options I should try ? Thank you very much Hitoshi

[ceeaspb]

Hi Can you run "perf-java-record-stack" script and see if it works for you (ie. then running "perf script" afterwards produces symbols)? This should run the commands in the right order. You may have run create-java-perf-map.sh too early and/or before "perf record".

Else there could be other reasons:

• the perf map file in /tmp could not be read by "perf script/report/etc"
• perf had an issue identifying how to resolve the symbols. Re-run with some simple main class with a loop burning cpu. Attach the output from "perf script" + the perf map file from /tmp and the perf.data file may also help.

[jrudolph]

Thanks for the report @oi0000. Good suggestions, @ceeaspb. The most likely reason is either that the /tmp/perf-<pid>.map file wasn't generated for some reason or that it isn't accessible for the user running the perf tools.

create-java-perf-map.sh $pid is invoked right after Java invocation where $pid is the pid of java

It might not work to run the script right after the Java invocation because Java code might not have been JIT compiled. So, make sure to warmup the JVM (i.e. JIT compilation is mostly done) before running the script and then run perf tools afterwards.

[oi0000]

@ceeaspb @jrudolph Thank you very much for replying.

I ran /perf-java-record-stack on the PID of the java process and got perf-$pid-data file (in /tmp). Then I run perf report in /tmp Here are the output for the first entry (children) of the perf report

# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 72  of event 'cycles'
# Event count (approx.): 109619682
#
# Children      Self  Command       Shared Object      Symbol                                        
# ........  ........  ............  .................  ..............................................
#
    27.94%     0.00%  perf          perf               [.] 0xffffffffffc5e4b3                        
                   |
                   ---0x5e4b3
                      |          
                      |--27.74%-- 0x15fab
                      |          0x6d753
                      |          __GI___execve
                      |          return_from_execve
                      |          sys_execve
                      |          do_execveat_common.isra.33
                      |          insert_vm_struct
                      |          security_vm_enough_memory_mm
                      |          __vm_enough_memory
                      |          __percpu_counter_add
                      |          
                       --0.21%-- __GI___ioctl
                                 entry_SYSCALL_64_fastpath
                                 sys_ioctl

(should I post the full output of perf report ?, maybe somewhere else and post ULR here?)

I looked though to the end of 'perf report', but could not find that directly came from the application (i.e. not from JVM RT).

For the invocation of perf-map-agent, the command script goes like this % java % java_pid=$! % create-java-perf-map.sh $java_pid % perf record -a -p $java_pid

The java application (in particular, SPECjbb2015) is set to run for 10mins. I first used --delay=120000 to skip the first 2mins of the execution, but wondered if it had any side-effect and removed it (also tried (sleep 120; perf record..)& but did not make any difference on symbol resolution). Do you think 10 minutes is not enough for the purpose of resolving symbols?

I think (not very confident though) /tmp/perf-$pid-map files are readable; because the symbols like Ljava/lang/String;::indexOf can be found in /tmp/perf...map and also perf report shows the output for such symbols. (any idea for checking if the perf-..map is readable ?)

Again, thank you very much hitoshi

[jrudolph]

Do you think 10 minutes is not enough for the purpose of resolving symbols?

Yes, that should be more than enough. Depending on the number of classfiles it can take several minutes (the Scala compiler is notorious for long JIT times) but usual programs JIT-compile in ~30s to a somewhat stable state (given that the workload during the warmup phase is similar to the workload afterwards).

% create-java-perf-map.sh $java_pid % perf record -a -p $java_pid

In stable state, the ordering of these two commands would not matter. The perf-map-record-stack script runs them the other way around to make sure that methods compiled during the perf record call are also included in the perf.map file.

[oi0000]

Johannes,

Thank you very much for replying. Actually, I was going to write here because it seemed I could solve the issue.

In fact, your advice "It might not work to run the script right after the Java invocation because Java code might not have been JIT compiled." was true. I thought I delayed the invocation of the script before, but it seems that the delay was not enough. Together with other options I tried, I delayed the script invocation 2 minutes after Java (and then perf). This also let me skip profiling the warm-up period of the workload

Thanks very much for your help.