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

[Stephane Eranian]

On Thu, Feb 11, 2016 at 2:16 PM, Arnaldo Carvalho de Melo
<acme@xxxxxxxxxx> wrote:
> 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@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.
>
> IIRC the different in the offsets came from 'perf inject' not preserving
> FINISHED_ROUND events.
>
That's an oversight. Is there code to repipe this event already?

>> > 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?
>
Not yet, let me try.

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

I pulled tip.git and jvmti does not compile anymore for me because of
the alternative vs.
update-java-alternatives problem.
Is it the case that on Fedora, you do not have
update-java-alternatives? If so, we could
have the Makefile check if it exists and if not default to what you have.

Thanks.