* 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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.