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

[Arnaldo Carvalho de Melo <acme@kernel.org>]

Em Mon, Feb 08, 2016 at 10:53:48AM -0800, Stephane Eranian escreveu:
> 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.

All this is already upstream, in tip.git, Ingo merged those patches.

There were still some open questions tho, that I listed on the changelog
comments.

See below for some more things
 
> $ 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?

will try and do it after replying to the other parts of this message,
the patch that went upstream checks it in any case.
 
> 
> 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.

Ok, tons of ELF files, wonder if having just one would be better, but
that would be an improvement, not a requirement, I guess.
 
> On Fri, Feb 5, 2016 at 6:24 AM, Arnaldo Carvalho de Melo
> <acme@kernel.org> 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.

IIRC the different in the offsets came from 'perf inject' not preserving
FINISHED_ROUND events.
 
> > 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.

IIRC it was the missing FINISHED_ROUND, haven't checked if that was on
purpose an oversight or even if so if it ends up being harmless for most
workloads, have you tried this with long running or high sample freq?

 
> >
> > -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?

What about this question? Do you know? Oversight?

- Arnaldo