* missing mmap events in perf profiles without dwarf callgraph
@ 2021-01-11 16:56 Milian Wolff
2021-01-13 10:30 ` Jiri Olsa
0 siblings, 1 reply; 9+ messages in thread
From: Milian Wolff @ 2021-01-11 16:56 UTC (permalink / raw)
To: linux-perf-users; +Cc: Arnaldo Carvalho de Melo, Jiri Olsa
[-- Attachment #1: Type: text/plain, Size: 2789 bytes --]
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)
```
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)
```
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?
Thank you
--
Milian Wolff
mail@milianw.de
http://milianw.de
[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 833 bytes --]
^ permalink raw reply [flat|nested] 9+ messages in thread* Re: missing mmap events in perf profiles without dwarf callgraph 2021-01-11 16:56 missing mmap events in perf profiles without dwarf callgraph Milian Wolff @ 2021-01-13 10:30 ` Jiri Olsa 2021-01-13 17:47 ` Milian Wolff 0 siblings, 1 reply; 9+ messages in thread From: Jiri Olsa @ 2021-01-13 10:30 UTC (permalink / raw) To: Milian Wolff; +Cc: linux-perf-users, Arnaldo Carvalho de Melo, Jiri Olsa 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: missing mmap events in perf profiles without dwarf callgraph 2021-01-13 10:30 ` Jiri Olsa @ 2021-01-13 17:47 ` Milian Wolff 2021-01-13 18:45 ` Jiri Olsa 0 siblings, 1 reply; 9+ messages in thread From: Milian Wolff @ 2021-01-13 17:47 UTC (permalink / raw) To: Jiri Olsa; +Cc: linux-perf-users, Arnaldo Carvalho de Melo [-- Attachment #1: Type: text/plain, Size: 4015 bytes --] 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 [-- Attachment #2: This is a digitally signed message part. --] [-- Type: application/pgp-signature, Size: 833 bytes --] ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: missing mmap events in perf profiles without dwarf callgraph 2021-01-13 17:47 ` Milian Wolff @ 2021-01-13 18:45 ` Jiri Olsa 2021-01-13 19:18 ` Milian Wolff 0 siblings, 1 reply; 9+ messages in thread From: Jiri Olsa @ 2021-01-13 18:45 UTC (permalink / raw) To: Milian Wolff; +Cc: linux-perf-users, Arnaldo Carvalho de Melo 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: missing mmap events in perf profiles without dwarf callgraph 2021-01-13 18:45 ` Jiri Olsa @ 2021-01-13 19:18 ` Milian Wolff 2021-01-14 8:56 ` Namhyung Kim 0 siblings, 1 reply; 9+ messages in thread From: Milian Wolff @ 2021-01-13 19:18 UTC (permalink / raw) To: Jiri Olsa; +Cc: linux-perf-users, Arnaldo Carvalho de Melo [-- Attachment #1: Type: text/plain, Size: 10275 bytes --] 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 [-- Attachment #2: This is a digitally signed message part. --] [-- Type: application/pgp-signature, Size: 833 bytes --] ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: missing mmap events in perf profiles without dwarf callgraph 2021-01-13 19:18 ` Milian Wolff @ 2021-01-14 8:56 ` Namhyung Kim 2021-01-19 8:09 ` Milian Wolff 0 siblings, 1 reply; 9+ messages in thread From: Namhyung Kim @ 2021-01-14 8:56 UTC (permalink / raw) To: Milian Wolff; +Cc: Jiri Olsa, linux-perf-users, Arnaldo Carvalho de Melo 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? Thanks, Namhyung ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: missing mmap events in perf profiles without dwarf callgraph 2021-01-14 8:56 ` Namhyung Kim @ 2021-01-19 8:09 ` Milian Wolff 2021-01-19 9:36 ` Namhyung Kim 0 siblings, 1 reply; 9+ messages in thread From: Milian Wolff @ 2021-01-19 8:09 UTC (permalink / raw) To: Namhyung Kim; +Cc: Jiri Olsa, linux-perf-users, Arnaldo Carvalho de Melo [-- 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 --] ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: missing mmap events in perf profiles without dwarf callgraph 2021-01-19 8:09 ` Milian Wolff @ 2021-01-19 9:36 ` Namhyung Kim 2021-01-19 11:33 ` Milian Wolff 0 siblings, 1 reply; 9+ messages in thread From: Namhyung Kim @ 2021-01-19 9:36 UTC (permalink / raw) To: Milian Wolff; +Cc: Jiri Olsa, linux-perf-users, Arnaldo Carvalho de Melo Hi Milian, On Tue, Jan 19, 2021 at 5:11 PM Milian Wolff <mail@milianw.de> wrote: > > On Donnerstag, 14. Januar 2021 09:56:36 CET Namhyung Kim wrote: > > 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? I mean the below. In my case, address and offset of the .text section are same as 0x1080. Thanks, Namhyung $ readelf -S a.out There are 37 section headers, starting at offset 0x1df20: Section Headers: [Nr] Name Type Address Offset Size EntSize Flags Link Info Align [ 0] NULL 0000000000000000 00000000 0000000000000000 0000000000000000 0 0 0 [ 1] .interp PROGBITS 00000000000002a8 000002a8 000000000000001c 0000000000000000 A 0 0 1 [ 2] .note.gnu.bu[...] NOTE 00000000000002c4 000002c4 0000000000000024 0000000000000000 A 0 0 4 [ 3] .note.ABI-tag NOTE 00000000000002e8 000002e8 0000000000000020 0000000000000000 A 0 0 4 [ 4] .gnu.hash GNU_HASH 0000000000000308 00000308 0000000000000028 0000000000000000 A 5 0 8 [ 5] .dynsym DYNSYM 0000000000000330 00000330 0000000000000138 0000000000000018 A 6 1 8 [ 6] .dynstr STRTAB 0000000000000468 00000468 00000000000000fb 0000000000000000 A 0 0 1 [ 7] .gnu.version VERSYM 0000000000000564 00000564 000000000000001a 0000000000000002 A 5 0 2 [ 8] .gnu.version_r VERNEED 0000000000000580 00000580 0000000000000040 0000000000000000 A 6 2 8 [ 9] .rela.dyn RELA 00000000000005c0 000005c0 0000000000000108 0000000000000018 A 5 0 8 [10] .rela.plt RELA 00000000000006c8 000006c8 0000000000000060 0000000000000018 AI 5 23 8 [11] .init PROGBITS 0000000000001000 00001000 0000000000000017 0000000000000000 AX 0 0 4 [12] .plt PROGBITS 0000000000001020 00001020 0000000000000050 0000000000000010 AX 0 0 16 [13] .plt.got PROGBITS 0000000000001070 00001070 0000000000000008 0000000000000008 AX 0 0 8 [14] .text PROGBITS 0000000000001080 00001080 000000000000201e 0000000000000000 AX 0 0 16 ... ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: missing mmap events in perf profiles without dwarf callgraph 2021-01-19 9:36 ` Namhyung Kim @ 2021-01-19 11:33 ` Milian Wolff 0 siblings, 0 replies; 9+ messages in thread From: Milian Wolff @ 2021-01-19 11:33 UTC (permalink / raw) To: Namhyung Kim; +Cc: Jiri Olsa, linux-perf-users, Arnaldo Carvalho de Melo [-- Attachment #1: Type: text/plain, Size: 1238 bytes --] On Dienstag, 19. Januar 2021 10:36:11 CET Namhyung Kim wrote: > Hi Milian, > > On Tue, Jan 19, 2021 at 5:11 PM Milian Wolff <mail@milianw.de> wrote: > > On Donnerstag, 14. Januar 2021 09:56:36 CET Namhyung Kim wrote: > > > 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? > > I mean the below. In my case, address and offset of the .text section are > same as 0x1080. Ah, indeed for me it's not the same - there's the discrepancy of 0x1000 again: [13] .text PROGBITS 0000000000001610 00000610 0000000000000185 0000000000000000 AX 0 0 16 Thanks, that gives me a (complicated) path forward. We'd have to essentially load the elf file, find this offset, and then take it into account when telling elfutils where the file was actually mapped to originally. Cheers -- Milian Wolff mail@milianw.de http://milianw.de [-- Attachment #2: This is a digitally signed message part. --] [-- Type: application/pgp-signature, Size: 833 bytes --] ^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2021-01-19 18:27 UTC | newest] Thread overview: 9+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2021-01-11 16:56 missing mmap events in perf profiles without dwarf callgraph Milian Wolff 2021-01-13 10:30 ` Jiri Olsa 2021-01-13 17:47 ` Milian Wolff 2021-01-13 18:45 ` Jiri Olsa 2021-01-13 19:18 ` Milian Wolff 2021-01-14 8:56 ` Namhyung Kim 2021-01-19 8:09 ` Milian Wolff 2021-01-19 9:36 ` Namhyung Kim 2021-01-19 11:33 ` Milian Wolff
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).