Re: missing mmap events in perf profiles without dwarf callgraph

[Jiri Olsa <jolsa@redhat.com>]

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

> 
> 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

> ```
> 
> In this case, we see that the first mmap event happens at 0x55b2f29d2000, so 
> if we take that as the base address, we arrive at the offset 0x172e for 
> address 0x55b2f29d372e. This then indeed matches main+0x25, i.e.: 0x1709 + 
> 0x25 = 0x172e.
> 
> But... The question again is: How does perf stat/report know this fact with 
> just the singular mmap event in the plain `perf record a.out` case above?
> Why is there just one mmap event recorded in such a profile?

it's simple binary, and you're getting just executable mmaps

but the calculation seems weird and we're mising something,
I'll try to reproduce and come with an answer

jirka