Re: perf/jit doesn't cope well with mprotect() to jit containing pages

[Andres Freund]

On 2017-01-26 13:17:56 -0800, Stephane Eranian wrote:
> > Nope, not yet.  I didn't want to submit an implementation that has the
> > ugly hack of mmap()ing /dev/zero pages to prevent VMA merging ;). But
> > once that's resolved I plan to push it upstream (they indicated
> > interest).  As long as I somehow prevent VMA merging (or just filter
> > out PERF_RECORD_MMAP2 records with prot 0), that support works.
> >
> > The problem is that (quoted below) without that hack the subsequent
> > mmaps just expand the previous VMAs which leads to perf loosing its
> > (address,range) -> symbol mappings for previously (in the same expanded
> > range) known symbols.
> >
> 
> Which timeclock source are you using to timestamp the jitdump records?
> It needs to match whatever you are using with perf record. Otherwise, inject
> will not work correctly. If you use CLOCK_MONOTONIC, then you need to
> use perf record -k mono as well.

Neither works without preventing the same VMA from being reused, both
work with.

Look at the following strace output from a demo application creating two
JITed functions:

mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7efd3866e000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7efd3866d000
mprotect(0x7efd3866e000, 4096, PROT_READ|PROT_EXEC) = 0
mprotect(0x7efd3866d000, 4096, PROT_READ|PROT_EXEC) = 0
write(2, "Function loaded: evalexpr0 at 139626038091776 0x7efd3866e000 len 69", 68) = 68

mmap(0x7efd3866f000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7efd3866c000
mmap(0x7efd3866e000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7efd3866b000
mprotect(0x7efd3866c000, 4096, PROT_READ|PROT_EXEC) = 0
mprotect(0x7efd3866b000, 4096, PROT_READ|PROT_EXEC) = 0
write(2, "Function loaded: evalexpr1 at 139626038083584 0x7efd3866c000 len 69", 68) = 68

...

i.e. it mmaps single pages for the each JITed function's sections. Which
makes sense, because the first function is JITed independently from the
second one.

The corresponding MMAP2 records according to perf perf script
--show-mmap-events are:
        postgres  4107 595444.867737: PERF_RECORD_MMAP2 4107/4107: [0x7efd3866e000(0x1000) @ 0x7efd3866e000 00:00 0 0]: ---p //anon
        postgres  4107 595444.867825: PERF_RECORD_MMAP2 4107/4107: [0x7efd3866d000(0x2000) @ 0x7efd3866d000 00:00 0 0]: ---p //anon
        postgres  4107 595444.884090: PERF_RECORD_MMAP2 4107/4107: [0x7efd3866c000(0x3000) @ 0x7efd3866c000 00:00 0 0]: ---p //anon
        postgres  4107 595444.884113: PERF_RECORD_MMAP2 4107/4107: [0x7efd3866b000(0x4000) @ 0x7efd3866b000 00:00 0 0]: ---p //anon
Note how the size of the mapping continually increases, so that the each
MMAP2 record covers previous sections.

If one perf inject --jit into that it looks like:
        postgres  4107 595444.867737: PERF_RECORD_MMAP2 4107/4107: [0x7efd3866e000(0x1000) @ 0x7efd3866e000 00:00 0 0]: ---p //anon
        postgres  4107 595444.867825: PERF_RECORD_MMAP2 4107/4107: [0x7efd3866d000(0x2000) @ 0x7efd3866d000 00:00 0 0]: ---p //anon
        postgres  4107 595444.868140: PERF_RECORD_MMAP2 4107/4107: [0x7efd3866e000(0x45) @ 0x40 fd:02 33434534 1]: --xs /home/andres/.debug/jit/llvm-IR-jit-20161209.XXfN0K3O/jitted-4107-1.so
        postgres  4107 595444.884090: PERF_RECORD_MMAP2 4107/4107: [0x7efd3866c000(0x3000) @ 0x7efd3866c000 00:00 0 0]: ---p //anon
        postgres  4107 595444.884113: PERF_RECORD_MMAP2 4107/4107: [0x7efd3866b000(0x4000) @ 0x7efd3866b000 00:00 0 0]: ---p //anon
        postgres  4107 595444.884232: PERF_RECORD_MMAP2 4107/4107: [0x7efd3866c000(0x45) @ 0x40 fd:02 33434599 1]: --xs /home/andres/.debug/jit/llvm-IR-jit-20161209.XXfN0K3O/jitted-4107-2.so

Note how the first injected record is also covered by the following
"//anon" event.  This leads to the the curious effect that samples for
the first function (evalexpr0) are associated with the right generated
.so, until the second function is JITed.

I hacked up perf inject to omit such MMAP2 records by adding
        if (event->mmap2.prot == 0)
                return 0;
to perf_event__jit_repipe_mmap2() and suddenly things work.

I presume the increasing MMAP2 size is triggered by the consecutive
pages being represented as a single page-range in the kernel?

If I, to work around such consecutive pages, force another page to be
mmap()ed inbetween, and avoid using MAP_ANONYMOUS, the problem also goes
away.

BTW, it's also a bit weird that those MMAP2 records triggered by
mprotect/mmap, have prot set to 0...

- Andres