Re: [PATCH v8 2/4] perf inject: add jitdump mmap injection support

[Stephane Eranian]

Hi Arnaldo,

Sorry for the delay, I missed your message.

I tried with openjdk-8 on Ubuntu/Wily and I do not get the crash using
the same hello world test program.
In fact, if I print file_name, it is never NULL for me.

$ java -agentpath:/home/eranian/tip/tools/perf/jvmti/libjvmti.so hello
java: jvmti: jitdump in
/home/eranian/.debug/jit/java-jit-20160208.XX8wCwyY/jit-20156.dump
java: FILE_NAME: Object.java
java: FILE_NAME: String.java
java: FILE_NAME: String.java
java: FILE_NAME: String.java
java: FILE_NAME: String.java
java: FILE_NAME: String.java
java: FILE_NAME: System.java
java: FILE_NAME: Math.java
java: FILE_NAME: Object.java
java: FILE_NAME: Reference.java
java: FILE_NAME: AbstractStringBuilder.java
java: FILE_NAME: ThreadLocal.java
java: FILE_NAME: AbstractStringBuilder.java
java: FILE_NAME: String.java
Hello, World

So I am not sure what is different in your setup especially if the
function GetSourceFileName() did not fail.
Could you print file_name in your code to check?


As for the MMAP, it is normal to have the extra mmaps pointing to the
jitted code.
Event for a simple program as hello world, there are several function
jitted, including the
java interpreter itself. There is one MMAP for each jitted function.



On Fri, Feb 5, 2016 at 6:24 AM, Arnaldo Carvalho de Melo
<acme@xxxxxxxxxx> wrote:
>
> Em Fri, Feb 05, 2016 at 10:57:17AM -0300, Arnaldo Carvalho de Melo escreveu:
> > Duh:
> >
> > [acme@jouet java]$ java -agentpath:/home/acme/git/linux/tools/perf/jvmti/libjvmti.so hello
> > java: jvmti: jitdump in /home/acme/.debug/jit/java-jit-20160205.XXFb472a/jit-28966.dump
> > Hello, World
> > [acme@jouet java]$
>
> Ok, so mucho progress:
>
> [acme@jouet java]$ perf record -k 1 java -agentpath:/home/acme/git/linux/tools/perf/jvmti/libjvmti.so hello
> java: jvmti: jitdump in /home/acme/.debug/jit/java-jit-20160205.XXIiqiq7/jit-31400.dump
> Hello, World
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.030 MB perf.data (268 samples) ]
> [acme@jouet java]$ perf inject --jit -i perf.data -o perf.data.jitted
> [acme@jouet java]$ perf report -D -i perf.data | grep PERF_RECORD_MMAP > mmaps.before
> Failed to open /tmp/perf-31400.map, continuing without symbols
> [acme@jouet java]$ perf report -D -i perf.data. | grep PERF_RECORD_MMAP > mmaps.before
> perf.data.jitted      perf.data.jitted.old  perf.data.old
> [acme@jouet java]$ perf report -D -i perf.data.jitted | grep PERF_RECORD_MMAP > mmaps.jitted
> [acme@jouet java]$ diff -u mmaps.before mmaps.jitted
> --- mmaps.before        2016-02-05 11:01:16.019257683 -0300
> +++ mmaps.jitted        2016-02-05 11:01:28.966232802 -0300
> <SNIP>
> +77539479986521 0xfc80 [0xa0]: PERF_RECORD_MMAP2 31400/31413: [0x7f3f7d102880(0xc0) @ 0x40 fd:02 1840179 1]: --xs /home/acme/.debug/jit/java-jit-20160205.XXIiqiq7/jitted-31400-281.so
> +77539480189814 0xfd20 [0xa0]: PERF_RECORD_MMAP2 31400/31413: [0x7f3f7d0fef60(0x80) @ 0x40 fd:02 1840180 1]: --xs /home/acme/.debug/jit/java-jit-20160205.XXIiqiq7/jitted-31400-282.so
> +77539480541065 0xfdc0 [0xa0]: PERF_RECORD_MMAP2 31400/31413: [0x7f3f7d102560(0x180) @ 0x40 fd:02 1840181 1]: --xs /home/acme/.debug/jit/java-jit-20160205.XXIiqiq7/jitted-31400-283.so
> +77539480541871 0xfe60 [0xa0]: PERF_RECORD_MMAP2 31400/31413: [0x7f3f7d102360(0x180) @ 0x40 fd:02 1840182 1]: --xs /home/acme/.debug/jit/java-jit-20160205.XXIiqiq7/jitted-31400-284.so
> +77539480848667 0xff00 [0xa0]: PERF_RECORD_MMAP2 31400/31413: [0x7f3f7d102160(0x180) @ 0x40 fd:02 1840183 1]: --xs /home/acme/.debug/jit/java-jit-20160205.XXIiqiq7/jitted-31400-285.so
> +77539480910925 0xffa0 [0xa0]: PERF_RECORD_MMAP2 31400/31413: [0x7f3f7d101f60(0x180) @ 0x40 fd:02 1840184 1]: --xs /home/acme/.debug/jit/java-jit-20160205.XXIiqiq7/jitted-31400-286.so
> <SNIP>
>
> Quite a lot of those, but I noticed this, probably harmless, at the start:
>
>  0 0x3fd8 [0x88]: PERF_RECORD_MMAP -1/0: [0xffffffffa0991000(0x5000) @ 0]: x /lib/modules/4.3.4-300.fc23.x86_64/kernel/net/dns_resolver/dns_resolver.ko.xz
>  0 0x4060 [0x78]: PERF_RECORD_MMAP -1/0: [0xffffffffa0996000(0x7b000) @ 0]: x /lib/modules/4.3.4-300.fc23.x86_64/kernel/fs/nfs/nfsv4.ko.xz
>  0 0x40d8 [0x88]: PERF_RECORD_MMAP -1/0: [0xffffffffa0a11000(0x5f5eefff) @ 0]: x /lib/modules/4.3.4-300.fc23.x86_64/kernel/drivers/usb/storage/usb-storage.ko.xz
> -77539437123281 0x6b98 [0xa0]: PERF_RECORD_MMAP2 31400/31400: [0x557b73152000(0x202000) @ 0 fd:00 7858 3897326142]: r-xp /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.71-1.b15.fc23.x86_64/jre/bin/java
> +77539437123281 0x42a0 [0xa0]: PERF_RECORD_MMAP2 31400/31400: [0x557b73152000(0x202000) @ 0 fd:00 7858 3897326142]: r-xp /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.71-1.b15.fc23.x86_64/jre/bin/java
>
> I.e. the MMAP records for the kernel modules comes in ok, humm, because
> probably you don't hook on PERF_RECORD_MMAP in perf-inject, just on MMAP2, and
> in those the only difference is the second field, 0x6b98 -> 0x42a0, what is
> that?
>
I have both MMAP and MMAP2 hooks for the jit mode of perf inject.

>
> static void dump_event(struct perf_evlist *evlist, union perf_event *event,
>                        u64 file_offset, struct perf_sample *sample)
> {
>         if (sample)
>                 perf_evlist__print_tstamp(evlist, event, sample);
>
>         printf("%#" PRIx64 " [%#x]: PERF_RECORD_%s", file_offset,
>                event->header.size, perf_event__name(event->header.type));
>
> File offset, what changed?
>
As for this, the offset is not recorded in the MMAP2 record, this is
an artifact of the __perf_Session__process_events()
which passes the file_offset in the perf.data file (read by mmapping).
The offsets are changed because we inject
new mmap records, and thus the existing MMAP may be moved to a later
position in the file.

Hope this helps.

>
> -0x7c18 [0x8]: event: 68
> -.
> -. ... raw event: size 8 bytes
> -.  0000:  44 00 00 00 00 00 08 00                          D.......
> -.
> -0x7c18 [0x8]: PERF_RECORD_FINISHED_ROUND
> -
> -0x6a80 [0x28]: event: 9
>
> Humm, inject doesn't preserves PERF_RECORD_FINISHED_ROUND? Or user events in
> general? On purpose?
>
> - Arnaldo