Re: missing mmap events in perf profiles without dwarf callgraph

[Milian Wolff <mail@milianw.de>]

[-- Attachment #1: Type: text/plain, Size: 8764 bytes --]

On Donnerstag, 14. Januar 2021 09:56:36 CET Namhyung Kim wrote:
> Hi,
> 
> On Thu, Jan 14, 2021 at 4:24 AM Milian Wolff <mail@milianw.de> wrote:
> > On Mittwoch, 13. Januar 2021 19:45:54 CET Jiri Olsa wrote:
> > > 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
> > 
> > Yes, that seems to be the issue here... Can anyone explain why that is the
> > case for me? When I let my little test app print /proc/self/maps (strace
> > and perf trace don't see mmap syscalls for these events btw -
> > interesting), then I see this:
> > 
> > ```
> > 55ac3bae5000-55ac3bae6000 r--p 00000000 00:31 11568                     
> > /tmp/ a.out
> > 55ac3bae6000-55ac3bae7000 r-xp 00000000 00:31 11568                     
> > /tmp/ a.out
> > 55ac3bae7000-55ac3bae9000 r--p 00000000 00:31 11568                     
> > /tmp/ a.out
> > 55ac3bae9000-55ac3baea000 rw-p 00001000 00:31 11568                     
> > /tmp/ a.out
> > ```
> > 
> > That matches what I'm getting from the perf events, i.e. pgoff = 0 for the
> > second (executable) mapping... Here's the output of `readelf -l a.out` -
> > can anyone explain what I'm seeing based on that maybe? My personal
> > knowlege in that area is not sufficient.
> > 
> > ```
> > $ readelf -l a.out
> > Elf file type is DYN (Shared object file)
> > Entry point 0x1b10
> > There are 11 program headers, starting at offset 64
> > 
> > Program Headers:
> >   Type           Offset             VirtAddr           PhysAddr
> >   
> >                  FileSiz            MemSiz              Flags  Align
> >   
> >   PHDR           0x0000000000000040 0x0000000000000040 0x0000000000000040
> >   
> >                  0x0000000000000268 0x0000000000000268  R      0x8
> >   
> >   INTERP         0x00000000000002a8 0x00000000000002a8 0x00000000000002a8
> >   
> >                  0x000000000000001c 0x000000000000001c  R      0x1
> >       
> >       [Requesting program interpreter: /lib64/ld-linux-x86-64.so.2]
> >   
> >   LOAD           0x0000000000000000 0x0000000000000000 0x0000000000000000
> >   
> >                  0x0000000000000b0c 0x0000000000000b0c  R      0x1000
> >   
> >   LOAD           0x0000000000000b10 0x0000000000001b10 0x0000000000001b10
> >   
> >                  0x0000000000000370 0x0000000000000370  R E    0x1000
> >   
> >   LOAD           0x0000000000000e80 0x0000000000002e80 0x0000000000002e80
> >   
> >                  0x0000000000000218 0x0000000000000218  RW     0x1000
> >   
> >   LOAD           0x0000000000001098 0x0000000000004098 0x0000000000004098
> >   
> >                  0x0000000000000070 0x00000000000001f8  RW     0x1000
> >   
> >   DYNAMIC        0x0000000000000e98 0x0000000000002e98 0x0000000000002e98
> >   
> >                  0x00000000000001d0 0x00000000000001d0  RW     0x8
> >   
> >   GNU_RELRO      0x0000000000000e80 0x0000000000002e80 0x0000000000002e80
> >   
> >                  0x0000000000000218 0x0000000000001180  R      0x1
> >   
> >   GNU_EH_FRAME   0x0000000000000988 0x0000000000000988 0x0000000000000988
> >   
> >                  0x0000000000000044 0x0000000000000044  R      0x4
> >   
> >   GNU_STACK      0x0000000000000000 0x0000000000000000 0x0000000000000000
> >   
> >                  0x0000000000000000 0x0000000000000000  RW     0x0
> >   
> >   NOTE           0x00000000000002c4 0x00000000000002c4 0x00000000000002c4
> >   
> >                  0x0000000000000038 0x0000000000000038  R      0x4
> >  
> >  Section to Segment mapping:
> >   Segment Sections...
> >   
> >    00
> >    01     .interp
> >    02     .interp .note.ABI-tag .note.gnu.build-id .dynsym .gnu.version
> > 
> > .gnu.version_r .gnu.hash .dynstr .rela.dyn .rela.plt .rodata
> > .gcc_except_table .eh_frame_hdr .eh_frame
> > 
> >    03     .text .init .fini .plt
> >    04     .fini_array .init_array .dynamic .got
> >    05     .data .tm_clone_table .got.plt .bss
> >    06     .dynamic
> >    07     .fini_array .init_array .dynamic .got
> >    08     .eh_frame_hdr
> >    09
> >    10     .note.ABI-tag .note.gnu.build-id
> > 
> > ```
> > 
> > I note that the following seems to correspond to my mapping event:
> > 
> > ```
> > 
> >   LOAD           0x0000000000000b10 0x0000000000001b10 0x0000000000001b10
> >   
> >                  0x0000000000000370 0x0000000000000370  R E    0x1000
> > 
> > ```
> > 
> > This is interesting - note how there's a difference of 0x100 between the
> > offset 0xb10 and the virt/phys addr at 0x1b10...
> > 
> > So to me it looks like it's correct that pgoff is 0, as the file offset is
> > 0xb10. But it's not enough to just look at the mapping information to
> > deduce the offset <-> virt/phys addr discrepancy.
> > 
> > Which makes it just the more surprising to me that perf script/report
> > seemingly copes with this situation despite these problems...
> 
> What I noticed is ss->adjust_symbols which is set for user DSOs.  It does
> 
>   sym.st_value -= shdr.sh_addr - shdr.sh_offset
> 
> Maybe your program's section header has different values?

Hey Namhyung,

how would I figure that one out? Isn't that data shown in the readelf output 
above? Put differently: Could someone else maybe show his readelf output so we 
can compare?

@ jirka: did you have a chance to figure out why/how perf stat/report is 
figuring out the right mapping address from the singular mapping event?

Thanks

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

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 833 bytes --]