Re: missing mmap events in perf profiles without dwarf callgraph

[Jiri Olsa <jolsa@redhat.com>]

On Wed, Jan 13, 2021 at 06:47:22PM +0100, Milian Wolff wrote:
> On Mittwoch, 13. Januar 2021 11:30:31 CET Jiri Olsa wrote:
> > On Mon, Jan 11, 2021 at 05:56:52PM +0100, Milian Wolff wrote:
> > > Hey there,
> > > 
> > > in hotspot I noticed a symbolization bug for perf.data files that are
> > > recorded without `--call-graph dwarf`, i.e. something like this:
> > > 
> > > ```
> > > $ cat test.c
> > > int main()
> > > {
> > > 
> > >     int sum = 0;
> > >     for (int i = 0; i < 100000; ++i) sum += i;
> > >     return sum > 0;
> > > 
> > > }
> > > $ gcc -O0 -g test.c
> > > $ perf record ./a.out
> > > $ perf script --show-mmap-events | grep /a.out
> > > 
> > >            a.out 149719 18106.394277: PERF_RECORD_MMAP2 149719/149719:
> > > [0x55e0b3b5e000(0x1000) @ 0 00:31 22086 3699042272]: r-xp /tmp/a.out
> > > 
> > >            a.out 149719 18106.394748:     275254 cycles:u:     
> > >            55e0b3b5e72e
> > > 
> > > main+0x25 (/tmp/a.out)
> > > 
> > >            a.out 149719 18106.395011:     486078 cycles:u:     
> > >            55e0b3b5e72e
> > > 
> > > main+0x25 (/tmp/a.out)
> > > ```
> > 
> > for some reason I can't reproduce this and also I'm not getting
> > randomized VA for your example, while I see it in other processes,
> > which is strange.. I'll check on it deeper
> 
> Out of interest: what exactly are you not reproducing? And what do you mean by 
> "randomized VA"?

that address 55e0b3b5e72e is randomized by kernel,
but I had to compile your example with -pie to get it,
otherwise I was seeing the standard 0x0400000 something


I'm now seeing:

              ex 1381597 1084961.360877: PERF_RECORD_MMAP2 1381597/1381597: [0x558f08599000(0x1000) @ 0x1000 fd:03 155428 2806170740]: r-xp /home/jolsa/trash/ex
              ex 1381597 1084961.360889: PERF_RECORD_MMAP2 1381597/1381597: [0x7f283cc80000(0x21000) @ 0x2000 fd:01 274841 3265102552]: r-xp /usr/lib64/ld-2.31.so
              ex 1381597 1084961.360898: PERF_RECORD_MMAP2 1381597/1381597: [0x7ffc2cd9c000(0x2000) @ 0 00:00 0 0]: r-xp [vdso]
              ex 1381597 1084961.360917:          1 cycles:u:  ffffffffabc01007 [unknown] ([unknown])
              ex 1381597 1084961.360920:          1 cycles:u:  ffffffffabc01007 [unknown] ([unknown])
              ex 1381597 1084961.360922:          9 cycles:u:  ffffffffabc01007 [unknown] ([unknown])
              ex 1381597 1084961.360924:        180 cycles:u:  ffffffffabc01007 [unknown] ([unknown])
              ex 1381597 1084961.360929:       3839 cycles:u:  ffffffffabc01007 [unknown] ([unknown])
              ex 1381597 1084961.361010: PERF_RECORD_MMAP2 1381597/1381597: [0x7f283caa4000(0x150000) @ 0x25000 fd:01 313184 1927740165]: r-xp /usr/lib64/libc-2.31.so
              ex 1381597 1084961.361695:      22432 cycles:u:      558f08599140 main+0x17 (/home/jolsa/trash/ex)
              ex 1381597 1084961.361702:      20545 cycles:u:      558f08599140 main+0x17 (/home/jolsa/trash/ex)
              ex 1381597 1084961.361709:      99474 cycles:u:      558f08599140 main+0x17 (/home/jolsa/trash/ex)

and it seems to work because there's 0x1000 pgoffset (number behind @)
which for your test seems to be 0

I'm having sample with:
  558f08599140 main+0x17

that falls into:
              ex 1381597 1084961.360877: PERF_RECORD_MMAP2 1381597/1381597: [0x558f08599000(0x1000) @ 0x1000 fd:03 155428 2806170740]: r-xp /home/jolsa/trash/ex

0x558f08599140 - 0x558f08599000 + 0x1000 = 0x1140

with main symbol:

	$ nm ex | grep main
			 U __libc_start_main@@GLIBC_2.2.5
	0000000000001129 T main

0x1140 - 0x1129 = 0x17 which is correct


> 
> > > How does perf resolve the address 0x55e0b3b5e72e to main+0x25 here? If we
> > > look at this purely from the singular mmap event, this shouldn't be the
> > > case:
> > > 
> > > 1) The mmap event starts at 0x55e0b3b5e000, has size 0x1000, so its end is
> > > at 0x55e0b3b5f000.
> > > 
> > > 2) Address 55e0b3b5e72e is thus contained in this map, and at offset
> > > 0x72e.
> > > 
> > > 3) But main is not at this offset, it starts at 0x1709:
> > > 
> > > ```
> > > $ nm ./a.out | grep main
> > > 
> > >                  U __libc_start_main
> > > 
> > > 0000000000001709 T main
> > > ```
> > > 
> > > How does perf report/script still get the right answer here and knows that
> > > there's an offset of 0x1000?
> > > 
> > > Note that in reality, multiple mmap events occur. And the first one maps
> > > the file at an address with the 0x1000 offset. This can be seen by:
> > > 
> > > ```
> > > $ perf record --call-graph dwarf ./a.out
> > > $ perf script --show-mmap-events | grep /a.out
> > > a.out 149953 18488.265340: PERF_RECORD_MMAP2 149953/149953:
> > > [0x55b2f29d2000(0x4000) @ 0 00:31 22086 3699042272]: r--p /tmp/a.out
> > > a.out 149953 18488.265346: PERF_RECORD_MMAP2 149953/149953:
> > > [0x55b2f29d3000(0x1000) @ 0 00:31 22086 3699042272]: r-xp /tmp/a.out
> > > a.out 149953 18488.265348: PERF_RECORD_MMAP2 149953/149953:
> > > [0x55b2f29d4000(0x1000) @ 0 00:31 22086 3699042272]: rw-p /tmp/a.out
> > > a.out 149953 18488.265350: PERF_RECORD_MMAP2 149953/149953:
> > > [0x55b2f29d5000(0x1000) @ 0 00:31 22086 3699042272]: rw-p /tmp/a.out
> > > a.out 149953 18488.265706: PERF_RECORD_MMAP2 149953/149953:
> > > [0x55b2f29d4000(0x1000) @ 0 00:31 22086 3699042272]: r--p /tmp/a.out
> > > 
> > >             55b2f29d372e main+0x25 (/tmp/a.out)
> > >             55b2f29d372e main+0x25 (/tmp/a.out)
> > 
> > when you use '--call-graph dwarf' you also enable data mmaps,
> > so the extra mmap events are non-X mmaps
> 
> I see, is this an optimization to reduce the overhead when doing this 
> "shallow" sampling? Can one opt-in to the data mmaps without going the full 
> `--call-graph dwarf` way?

5c0cf22477ea perf record: Store data mmaps for dwarf unwind

says:
    But we've seen cases (softice) where DWARF unwinder went through non
    executable mmaps, which we need to lookup in MAP__VARIABLE tree.

it's hardcoded

jirka