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

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

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

Thank you!

-- 
Milian Wolff
mail@milianw.de
http://milianw.de