Message-ID: <CABPqkBQtDPGUeUma86vw61Jsk2ynwvSXRZgGvxMsPnA-cbUMcQ@mail.gmail.com>
Date:   Thu, 26 Jan 2017 13:17:56 -0800
From:   Stephane Eranian <eranian@...gle.com>
To:     Andres Freund <andres@...razel.de>
Cc:     "eranian@...il.com" <eranian@...il.com>,
        LKML <linux-kernel@...r.kernel.org>,
        Arnaldo Carvalho de Melo <acme@...nel.org>,
        Jiri Olsa <jolsa@...hat.com>,
        Peter Zijlstra <peterz@...radead.org>,
        Ingo Molnar <mingo@...e.hu>,
        Anton Blanchard <anton@...abs.org>,
        Namhyung Kim <namhyung@...nel.org>
Subject: Re: perf/jit doesn't cope well with mprotect() to jit containing pages

On Thu, Jan 26, 2017 at 1:00 PM, Andres Freund <andres@...razel.de> wrote:
>
> Hi Stephane,
>
> On 2017-01-26 12:32:02 -0800, Stephane Eranian wrote:
> > On Fri, Dec 9, 2016 at 9:02 PM, Andres Freund <andres@...razel.de> wrote:
> > > Hi,
> > >
> > > While working on optionally jit-compiling parts of postgres using llvm
> > > (MCJIT currently, but Orc would have the same issue afaics), I'm trying
> > > to use perf jit support to make profiling of those JITed parts easier.
> > >
> > > Turns out the current jit support in perf doesn't work that well for
> > > LLVM - but it doesn't primarily look like LLVM's fault. Syscall-wise
> > > llvm does (heavily filtered):
> > >
> > Ok, when you say you are using perf jit with LLVM, I want to understand how?
>
> Sure.
>
>
> > The perf jit support requires cooperation from the jitted runtime. For
> > the case of Java
> > there is a JVMTI agent (shared lib) that generates a jitdump info file
> > with information about
> > how the runtime jitted functions and what is mapped where. The kernel
> > is still recording
> > the mmap syscalls. But you need more to map an address to a symbol.
> > You need to know
> > where and when the JIT compiler mapped functions, when they are
> > jitted, re-jitted or moved. This is the
> > role of the agent to encode all of this in the jitdump file which is
> > then used by perf inject
> > to rewrite the perf.data file with the new mmap records that point to
> > the .so files that it generates
> > for each jitted function.
>
> Right.
>
>
> > Did you write such support?
>
> Yes.  LLVM's jit has callback support both for symbol and debugging
> information. You can register additional sets of callbacks to be called
> (at runtime).
>
> There's basically
> +void PerfJITEventListener::NotifyObjectEmitted(
> +                                       const ObjectFile &Obj,
> +                                       const RuntimeDyld::LoadedObjectInfo &L) {
> and
> +void PerfJITEventListener::NotifyFreeingObject(const ObjectFile &Obj) {
>
> which is enough to use the perf jit support.
>
>
> > Is it already there in LLVM?
>
> 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.


>
> Greetings,
>
> Andres
>
> > If not, then you will not be able to correctly correlate symbols.
> >
> >
> > > 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.
> > >
> > > Am I doing something wrong, or is there a bug here?
> > >
> > > FWIW, this is on linux 4.8.8, with perf from master
> > > (v4.9-rc8-108-g810ac7b7558d).
> > >
> > > BTW, it's also a bit weird that those MMAP2 records triggered by
> > > mprotect/mmap, have prot set to 0...
> > >
> > > Regards,
> > >
> > > Andres
> > >

Powered by blists - more mailing lists