Re: perf/jit doesn't cope well with mprotect() to jit containing pages
From: Andres Freund
Date: Thu Jan 26 2017 - 16:51:41 EST
On 2017-01-26 13:34:35 -0800, Stephane Eranian wrote:
> On Thu, Jan 26, 2017 at 1:22 PM, Andres Freund <andres@xxxxxxxxxxx> wrote:
> > 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.
> There is something I am not following here unless there is a bug in inject
> or perf report.
> The timestamps should take care of ordering what is mapped where and when.
> If look at the timestamps:
> 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
> The MMAP2 injected for the jitted function appears after the 2
> mappings. If you have samples timestamped between
> 595444.867737 and 595444.868140 - 1 coming from that function, they
> will be symbolized correctly. Otherwise things should work as perf
> report will consider from 595444.868140 that you jitted function
> cover the range of addresses. Unless there is something wrong in perf
> report or I am not understanding the problem.
If I just have a single JITed function it *is* symbolized correctly. But
if I have multiple ones only the last one is correctly symbolized...
The problem appears to be triggered by a single VMA being used for all
the mappings. Check how the length of the overall mapping increases
from 0x7efd3866e000(0x1000) increasing to 0x7efd3866b000(0x4000) (that's
the same mapping if you add the length, just increased in size by
another page). When script shows
> 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
all hits for 0x7efd3866e000 are symbolized correctly if, and only if,
they occur before the second PERF_RECORD_MMAP2 mapping to //anon. The
next function (JITing which triggered enlarging the VMA) is then
correctly symbolized, until the third function is JITed...
I've confirmed this by ignoring these //anon mappings by adding
if (event->mmap2.prot == 0)
to perf_event__jit_repipe_mmap2() - then everything works.
(note that I don't understand why prot is 0 in the first place for
these, but it was a convenient hack to filter the records).
Which seems to suggest to me that perf's tracking of memory regions is
over-eager in overwriting more specific mappings like
with the larger 0x7efd3866c000(0x3000) to //anon mapping.
Similarly, if I prevent the independent mmap()s from sharing a VMA (by
creating a mapping inbetween the individual function mappings which can't
be shared), everything works as well.