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... > 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 Yes, that's perfectly fine. Thanks for looking into that. > > > > 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 OK, thanks. Cheers -- Milian Wolff mail@milianw.de http://milianw.de