* [PROBLEM] perf report is broken in latest linus git
@ 2009-08-13 9:28 Pekka Enberg
2009-08-13 9:36 ` Ingo Molnar
2009-08-13 14:14 ` [PATCH] perf_counter: Report the cloning task as parent on perf_counter_fork() Peter Zijlstra
0 siblings, 2 replies; 10+ messages in thread
From: Pekka Enberg @ 2009-08-13 9:28 UTC (permalink / raw)
To: mingo; +Cc: Peter Zijlstra, Arnaldo Carvalho de Melo, paulus, linux-kernel
Hi all!
I don't know what to make out of this. I am profiling my userspace VM with perf
and something happened between 2.6.31-rc4 (which worked perfectly) and latest
Linus git. I am seeing completely different perf profiles and from what I can
tell, the userspace part isn't causing which makes me think it's a kernel
bug. See below for the perf reports.
Pekka
Linux 2.6.31-rc4 (both kernel and userspace):
[ Note: this makes the most sense to me knowing what the app does. ]
penberg@penberg-laptop:~/testing/jato$ perf record -f jato HelloWorldSwing
[ perf record: Captured and wrote 1.401 MB perf.data (~61218 samples) ]
penberg@penberg-laptop:~/testing/jato$ perf report --sort comm,dso,symbol
# Samples: 60421
#
# Overhead Command Shared Object Symbol
# ........ ....... ....................................... ......
#
69.86% jato /home/penberg/bin/jato [.] gc_map_init
2.06% jato /lib/tls/i686/cmov/libc-2.8.90.so [.] _int_malloc
1.95% jato /lib/tls/i686/cmov/libc-2.8.90.so [.] __GI_strcmp
1.68% jato /lib/tls/i686/cmov/libc-2.8.90.so [.] __GI___libc_malloc
1.61% jato [kernel] [k] get_page_from_freelist
1.01% jato /home/penberg/bin/jato [.] zalloc
0.97% jato /usr/lib/libzip.so.1.0.0 [.] _zip_get_name
0.85% jato /home/penberg/bin/jato [.] cafebabe_constant_info_utf8_compare
0.69% jato /usr/lib/libz.so.1.2.3.3 [.] 0x0000000000e445
0.59% jato /lib/tls/i686/cmov/libc-2.8.90.so [.] cfree
0.58% jato /home/penberg/bin/jato [.] analyze_liveness
0.56% jato /home/penberg/bin/jato [.] split_interval_at
0.56% jato /usr/lib/libfontconfig.so.1.3.0 [.] 0x0000000001127e
0.56% jato /home/penberg/bin/jato [.] allocate_registers
Latest Linus git kernel with -rc4 perf userspace:
penberg@penberg-laptop:~/testing/jato$ perf record -f jato HelloWorldSwing
[ perf record: Captured and wrote 1.402 MB perf.data (~61261 samples) ]
penberg@penberg-laptop:~/testing/jato$ perf report --sort comm,dso,symbol|head -30
# Samples: 60457
#
# Overhead Command Shared Object Symbol
# ........ ....... ....................................... ......
#
[ Note: the jato executable doesn't appear anywhere in the trace. I'm
pretty sure the libzip functions, for example, are from jato, not perf. ]
36.14% perf /home/penberg/bin/perf [.] dso__synthesize_plt_symbols
35.20% perf /home/penberg/bin/perf [.] dso__new
3.57% perf /home/penberg/bin/jato [.] 0x0000000000c910
2.10% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] _int_malloc
1.89% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] __GI_strcmp
1.63% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] __GI___libc_malloc
1.44% perf [kernel] [k] get_page_from_freelist
1.04% perf /home/penberg/bin/perf [.] dso__load_sym
0.94% perf /usr/lib/libzip.so.1.0.0 [.] _zip_get_name
0.60% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] cfree
0.52% perf /home/penberg/bin/perf [.] dso__load_kernel
0.46% perf /usr/lib/libzip.so.1.0.0 [.] _zip_name_locate
0.46% perf /usr/lib/libfontconfig.so.1.3.0 [.] 0x00000000016706
0.42% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] _int_free
0.40% perf [kernel] [k] kunmap_atomic
0.38% perf /home/penberg/bin/perf [.] cmd_stat
0.34% perf /home/penberg/bin/perf [.] quote_c_style_counted
0.33% perf /usr/lib/libz.so.1.2.3.3 [.] 0x0000000000ea89
0.32% perf /home/penberg/bin/perf [.] 0x000000000261ea
0.32% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] malloc_consolidate
0.30% perf /home/penberg/bin/perf [.] strbuf_grow
0.30% perf /home/penberg/bin/perf [.] store_aux
0.30% perf /home/penberg/bin/jato [.] zalloc
0.29% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] __GI___libc_realloc
0.27% perf /home/penberg/bin/perf [.] strbuf_addf
Latest Linus git kernel and userspace:
[ perf record: Captured and wrote 1.348 MB perf.data (~58887 samples) ]
penberg@penberg-laptop:~/testing/jato$ perf record -f jato HelloWorldSwing
[ perf record: Captured and wrote 1.342 MB perf.data (~58623 samples) ]
penberg@penberg-laptop:~/testing/jato$ perf report | head -30
# Samples: 57821
#
# Overhead Command Shared Object Symbol
# ........ ....... ....................................... ......
#
72.88% perf /home/penberg/bin/perf [.] strbuf_readlink
6.53% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] 0x0000000014b8c0
3.31% perf /home/penberg/bin/jato [.] 0x0000000000c910
1.37% perf [kernel] [k] get_page_from_freelist
0.91% perf /usr/lib/libzip.so.1.0.0 [.] _zip_get_name
0.67% perf /home/penberg/bin/perf [.] strbuf_getline
0.59% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] __GI_strcmp
0.57% perf /usr/lib/libfontconfig.so.1.3.0 [.] 0x00000000019700
0.53% perf /usr/lib/libz.so.1.2.3.3 [.] 0x0000000000f0c5
0.50% perf /home/penberg/bin/perf [.] print_events
0.48% perf /home/penberg/bin/perf [.] quote_c_style_counted
0.47% perf /home/penberg/bin/perf [.] rb_erase
0.40% perf /home/penberg/bin/perf [.] strlist__load
0.40% perf /home/penberg/bin/perf [.] display_thread
0.40% perf /home/penberg/bin/perf [.] run_hook
0.34% perf [kernel] [k] kunmap_atomic
0.32% perf /home/penberg/bin/perf [.] strlist__parse_list_entry
0.31% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] _int_malloc
0.30% perf /home/penberg/bin/perf [.] dso__load
0.28% perf /usr/lib/libzip.so.1.0.0 [.] _zip_name_locate
0.28% perf /home/penberg/bin/perf [.] cmd_stat
0.26% perf /home/penberg/bin/perf [.] run_command_v_opt
0.25% perf /home/penberg/bin/perf [.] strlist__parse_list
0.23% perf a7d8bb0a [.] 0x000000a7d8bb0a
0.21% perf /home/penberg/bin/jato [.] cafebabe_constant_info_utf8_compare
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PROBLEM] perf report is broken in latest linus git
2009-08-13 9:28 [PROBLEM] perf report is broken in latest linus git Pekka Enberg
@ 2009-08-13 9:36 ` Ingo Molnar
2009-08-13 9:47 ` Pekka Enberg
2009-08-13 14:14 ` [PATCH] perf_counter: Report the cloning task as parent on perf_counter_fork() Peter Zijlstra
1 sibling, 1 reply; 10+ messages in thread
From: Ingo Molnar @ 2009-08-13 9:36 UTC (permalink / raw)
To: Pekka Enberg
Cc: Peter Zijlstra, Arnaldo Carvalho de Melo, paulus, linux-kernel
* Pekka Enberg <penberg@cs.helsinki.fi> wrote:
> Latest Linus git kernel with -rc4 perf userspace:
>
> penberg@penberg-laptop:~/testing/jato$ perf record -f jato HelloWorldSwing
> [ perf record: Captured and wrote 1.402 MB perf.data (~61261 samples) ]
>
> penberg@penberg-laptop:~/testing/jato$ perf report --sort comm,dso,symbol|head -30
> # Samples: 60457
> #
> # Overhead Command Shared Object Symbol
> # ........ ....... ....................................... ......
> #
>
> [ Note: the jato executable doesn't appear anywhere in the trace. I'm
> pretty sure the libzip functions, for example, are from jato, not perf. ]
>
> 36.14% perf /home/penberg/bin/perf [.] dso__synthesize_plt_symbols
> 35.20% perf /home/penberg/bin/perf [.] dso__new
> 3.57% perf /home/penberg/bin/jato [.] 0x0000000000c910
Perhaps it's this commit:
4d1e00a: perf symbol: Fix symbol parsing in certain cases: use the build-id as a symlink
it does not revert cleanly, so you might want to check out these two
commits:
4d1e00a
4d1e00a~1
and build perf on both, and check with your anomalous perf.data
(without changing it) whether the output makes most sense.
Ingo
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PROBLEM] perf report is broken in latest linus git
2009-08-13 9:36 ` Ingo Molnar
@ 2009-08-13 9:47 ` Pekka Enberg
2009-08-13 11:33 ` Peter Zijlstra
0 siblings, 1 reply; 10+ messages in thread
From: Pekka Enberg @ 2009-08-13 9:47 UTC (permalink / raw)
To: Ingo Molnar
Cc: Peter Zijlstra, Arnaldo Carvalho de Melo, paulus, linux-kernel
Hi Ingo,
On Thu, 2009-08-13 at 11:36 +0200, Ingo Molnar wrote:
> * Pekka Enberg <penberg@cs.helsinki.fi> wrote:
>
> > Latest Linus git kernel with -rc4 perf userspace:
> >
> > penberg@penberg-laptop:~/testing/jato$ perf record -f jato HelloWorldSwing
> > [ perf record: Captured and wrote 1.402 MB perf.data (~61261 samples) ]
> >
> > penberg@penberg-laptop:~/testing/jato$ perf report --sort comm,dso,symbol|head -30
> > # Samples: 60457
> > #
> > # Overhead Command Shared Object Symbol
> > # ........ ....... ....................................... ......
> > #
> >
> > [ Note: the jato executable doesn't appear anywhere in the trace. I'm
> > pretty sure the libzip functions, for example, are from jato, not perf. ]
> >
> > 36.14% perf /home/penberg/bin/perf [.] dso__synthesize_plt_symbols
> > 35.20% perf /home/penberg/bin/perf [.] dso__new
> > 3.57% perf /home/penberg/bin/jato [.] 0x0000000000c910
>
> Perhaps it's this commit:
>
> 4d1e00a: perf symbol: Fix symbol parsing in certain cases: use the build-id as a symlink
>
> it does not revert cleanly, so you might want to check out these two
> commits:
>
> 4d1e00a
> 4d1e00a~1
>
> and build perf on both, and check with your anomalous perf.data
> (without changing it) whether the output makes most sense.
The commit seems fine. Like I said, the perf.data file is busted even
with 2.6.31-rc4 userspace so I think it's a kernel bug.
Pekka
4d1e00a~1:
penberg@penberg-laptop:~/testing/jato$ perf report
# Samples: 57821
#
# Overhead Command Shared Object Symbol
# ........ ....... ....................................... ......
#
73.55% perf /home/penberg/bin/perf [.] dso__synthesize_plt_symbols
6.54% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] 0x0000000014b8c0
3.31% perf /home/penberg/bin/jato [.] 0x0000000000c910
1.37% perf [kernel] [k] get_page_from_freelist
1.05% perf /home/penberg/bin/perf [.] dso__load_sym
0.91% perf /usr/lib/libzip.so.1.0.0 [.] _zip_get_name
0.59% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] __GI_strcmp
0.57% perf /usr/lib/libfontconfig.so.1.3.0 [.] 0x00000000019700
0.53% perf /usr/lib/libz.so.1.2.3.3 [.] 0x0000000000f0c5
0.49% perf /home/penberg/bin/perf [.] dso__load_kernel
4d1e00a:
penberg@penberg-laptop:~/testing/jato$ perf report
# Samples: 57821
#
# Overhead Command Shared Object Symbol
# ........ ....... ....................................... ......
#
73.55% perf /home/penberg/bin/perf [.] dso__synthesize_plt_symbols
6.53% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] 0x0000000014b8c0
3.31% perf /home/penberg/bin/jato [.] 0x0000000000c910
1.37% perf [kernel] [k] get_page_from_freelist
1.05% perf /home/penberg/bin/perf [.] dso__load_sym
0.91% perf /usr/lib/libzip.so.1.0.0 [.] _zip_get_name
0.59% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] __GI_strcmp
0.57% perf /usr/lib/libfontconfig.so.1.3.0 [.] 0x00000000019700
0.53% perf /usr/lib/libz.so.1.2.3.3 [.] 0x0000000000f0c5
0.49% perf /home/penberg/bin/perf [.] dso__load_kernel
0.43% perf /home/penberg/bin/perf [.] cmd_stat
0.35% perf /home/penberg/bin/perf [.] store_aux
0.34% perf [kernel] [k] kunmap_atomic
0.33% perf /home/penberg/bin/perf [.] quote_c_style_counted
0.31% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] _int_malloc
0.29% perf /home/penberg/bin/perf [.] 0x00000000026951
0.29% perf /home/penberg/bin/perf [.] strbuf_addf
0.28% perf /usr/lib/libzip.so.1.0.0 [.] _zip_name_locate
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PROBLEM] perf report is broken in latest linus git
2009-08-13 9:47 ` Pekka Enberg
@ 2009-08-13 11:33 ` Peter Zijlstra
2009-08-13 12:02 ` Pekka Enberg
0 siblings, 1 reply; 10+ messages in thread
From: Peter Zijlstra @ 2009-08-13 11:33 UTC (permalink / raw)
To: Pekka Enberg; +Cc: Ingo Molnar, Arnaldo Carvalho de Melo, paulus, linux-kernel
On Thu, 2009-08-13 at 12:47 +0300, Pekka Enberg wrote:
> Hi Ingo,
>
> On Thu, 2009-08-13 at 11:36 +0200, Ingo Molnar wrote:
> > * Pekka Enberg <penberg@cs.helsinki.fi> wrote:
> >
> > > Latest Linus git kernel with -rc4 perf userspace:
> > >
> > > penberg@penberg-laptop:~/testing/jato$ perf record -f jato HelloWorldSwing
> > > [ perf record: Captured and wrote 1.402 MB perf.data (~61261 samples) ]
> > >
> > > penberg@penberg-laptop:~/testing/jato$ perf report --sort comm,dso,symbol|head -30
> > > # Samples: 60457
> > > #
> > > # Overhead Command Shared Object Symbol
> > > # ........ ....... ....................................... ......
> > > #
> > >
> > > [ Note: the jato executable doesn't appear anywhere in the trace. I'm
> > > pretty sure the libzip functions, for example, are from jato, not perf. ]
> > >
> > > 36.14% perf /home/penberg/bin/perf [.] dso__synthesize_plt_symbols
> > > 35.20% perf /home/penberg/bin/perf [.] dso__new
> > > 3.57% perf /home/penberg/bin/jato [.] 0x0000000000c910
> >
> > Perhaps it's this commit:
> >
> > 4d1e00a: perf symbol: Fix symbol parsing in certain cases: use the build-id as a symlink
> >
> > it does not revert cleanly, so you might want to check out these two
> > commits:
> >
> > 4d1e00a
> > 4d1e00a~1
> >
> > and build perf on both, and check with your anomalous perf.data
> > (without changing it) whether the output makes most sense.
>
> The commit seems fine. Like I said, the perf.data file is busted even
> with 2.6.31-rc4 userspace so I think it's a kernel bug.
Hrmm, does a -tip kernel work as expected? I'll go audit the kernel
changes between -rc4 and -rc5.
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PROBLEM] perf report is broken in latest linus git
2009-08-13 11:33 ` Peter Zijlstra
@ 2009-08-13 12:02 ` Pekka Enberg
2009-08-13 12:24 ` Pekka Enberg
0 siblings, 1 reply; 10+ messages in thread
From: Pekka Enberg @ 2009-08-13 12:02 UTC (permalink / raw)
To: Peter Zijlstra
Cc: Ingo Molnar, Arnaldo Carvalho de Melo, paulus, linux-kernel
On Thu, 2009-08-13 at 13:33 +0200, Peter Zijlstra wrote:
> > > Perhaps it's this commit:
> > >
> > > 4d1e00a: perf symbol: Fix symbol parsing in certain cases: use the build-id as a symlink
> > >
> > > it does not revert cleanly, so you might want to check out these two
> > > commits:
> > >
> > > 4d1e00a
> > > 4d1e00a~1
> > >
> > > and build perf on both, and check with your anomalous perf.data
> > > (without changing it) whether the output makes most sense.
> >
> > The commit seems fine. Like I said, the perf.data file is busted even
> > with 2.6.31-rc4 userspace so I think it's a kernel bug.
>
> Hrmm, does a -tip kernel work as expected? I'll go audit the kernel
> changes between -rc4 and -rc5.
tip/master seems to be broken too:
penberg@penberg-laptop:~/testing/jato$ perf report
# Samples: 65806
#
# Overhead Command Shared Object Symbol
# ........ ....... ....................................... ......
#
64.31% perf /home/penberg/bin/perf [.] strlist__load
3.10% perf /home/penberg/bin/jato [.] 0x0000000000c6e8
1.61% perf [kernel] [k] get_page_from_freelist
1.13% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] _int_malloc
1.11% perf /lib/tls/i686/cmov/libpthread-2.8.90.so [.] 0x00000000012532
1.08% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] _fitoa
0.96% perf a7d23660 [.] 0x000000a7d23660
0.86% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] ____strtold_l_internal
0.85% perf /usr/lib/libz.so.1.2.3.3 [.] 0x0000000000eef2
0.83% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] __GI_strcmp
0.74% perf /home/penberg/bin/jato [.] zalloc
0.69% perf [kernel] [k] scsi_dispatch_cmd
0.66% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] getsubopt
0.56% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] __realpath
0.50% perf /usr/lib/libzip.so.1.0.0 [.] _zip_get_name
penberg@penberg-laptop:~/src/linux/tools/perf$ git log|head -10
commit d1fa7782b090a3ab0f55c9003d7315b5f0f5e9d6
Merge: e93673b... daac07b...
Author: Ingo Molnar <mingo@elte.hu>
Date: Thu Aug 13 10:37:33 2009 +0200
Merge branch 'perfcounters/urgent'
commit daac07b2e6b77f1bd44104aa2f0593e5505f27d4
Author: Frederic Weisbecker <fweisbec@gmail.com>
Date: Thu Aug 13 10:27:19 2009 +0200
Pekka
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PROBLEM] perf report is broken in latest linus git
2009-08-13 12:02 ` Pekka Enberg
@ 2009-08-13 12:24 ` Pekka Enberg
0 siblings, 0 replies; 10+ messages in thread
From: Pekka Enberg @ 2009-08-13 12:24 UTC (permalink / raw)
To: Peter Zijlstra
Cc: Ingo Molnar, Arnaldo Carvalho de Melo, paulus, linux-kernel
On Thu, 2009-08-13 at 15:02 +0300, Pekka Enberg wrote:
> On Thu, 2009-08-13 at 13:33 +0200, Peter Zijlstra wrote:
> > > > Perhaps it's this commit:
> > > >
> > > > 4d1e00a: perf symbol: Fix symbol parsing in certain cases: use the build-id as a symlink
> > > >
> > > > it does not revert cleanly, so you might want to check out these two
> > > > commits:
> > > >
> > > > 4d1e00a
> > > > 4d1e00a~1
> > > >
> > > > and build perf on both, and check with your anomalous perf.data
> > > > (without changing it) whether the output makes most sense.
> > >
> > > The commit seems fine. Like I said, the perf.data file is busted even
> > > with 2.6.31-rc4 userspace so I think it's a kernel bug.
> >
> > Hrmm, does a -tip kernel work as expected? I'll go audit the kernel
> > changes between -rc4 and -rc5.
>
> tip/master seems to be broken too:
>
> penberg@penberg-laptop:~/testing/jato$ perf report
> # Samples: 65806
> #
> # Overhead Command Shared Object Symbol
> # ........ ....... ....................................... ......
> #
> 64.31% perf /home/penberg/bin/perf [.] strlist__load
> 3.10% perf /home/penberg/bin/jato [.] 0x0000000000c6e8
> 1.61% perf [kernel] [k] get_page_from_freelist
> 1.13% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] _int_malloc
> 1.11% perf /lib/tls/i686/cmov/libpthread-2.8.90.so [.] 0x00000000012532
> 1.08% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] _fitoa
> 0.96% perf a7d23660 [.] 0x000000a7d23660
> 0.86% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] ____strtold_l_internal
> 0.85% perf /usr/lib/libz.so.1.2.3.3 [.] 0x0000000000eef2
> 0.83% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] __GI_strcmp
> 0.74% perf /home/penberg/bin/jato [.] zalloc
> 0.69% perf [kernel] [k] scsi_dispatch_cmd
> 0.66% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] getsubopt
> 0.56% perf /lib/tls/i686/cmov/libc-2.8.90.so [.] __realpath
> 0.50% perf /usr/lib/libzip.so.1.0.0 [.] _zip_get_name
>
> penberg@penberg-laptop:~/src/linux/tools/perf$ git log|head -10
> commit d1fa7782b090a3ab0f55c9003d7315b5f0f5e9d6
> Merge: e93673b... daac07b...
> Author: Ingo Molnar <mingo@elte.hu>
> Date: Thu Aug 13 10:37:33 2009 +0200
>
> Merge branch 'perfcounters/urgent'
>
> commit daac07b2e6b77f1bd44104aa2f0593e5505f27d4
> Author: Frederic Weisbecker <fweisbec@gmail.com>
> Date: Thu Aug 13 10:27:19 2009 +0200
v2.6.31-rc5 is fine:
# Samples: 62768
#
# Overhead Command Shared Object Symbol
# ........ ....... ............................................. ......
#
68.45% jato /home/penberg/bin/jato [.] gc_map_init
2.08% jato /lib/tls/i686/cmov/libc-2.8.90.so [.] _int_malloc
1.79% jato /lib/tls/i686/cmov/libc-2.8.90.so [.] __GI_strcmp
1.49% jato [kernel] [k] get_page_from_freelist
1.33% jato /lib/tls/i686/cmov/libc-2.8.90.so [.] __GI___libc_malloc
1.11% jato /home/penberg/bin/jato [.] zalloc
1.04% jato a7c02842 [.] 0x000000a7c02842
0.92% jato /usr/lib/libzip.so.1.0.0 [.] _zip_get_name
0.76% jato /home/penberg/bin/jato [.] cafebabe_constant_info_utf8_compare
0.72% jato /lib/tls/i686/cmov/libpthread-2.8.90.so [.] 0x00000000007a2e
0.64% jato /usr/lib/libz.so.1.2.3.3 [.] 0x00000000001a0a
0.53% jato /home/penberg/bin/jato [.] allocate_registers
0.51% jato /home/penberg/bin/jato [.] analyze_liveness
0.51% jato /home/penberg/bin/jato [.] split_interval_at
^ permalink raw reply [flat|nested] 10+ messages in thread
* [PATCH] perf_counter: Report the cloning task as parent on perf_counter_fork()
2009-08-13 9:28 [PROBLEM] perf report is broken in latest linus git Pekka Enberg
2009-08-13 9:36 ` Ingo Molnar
@ 2009-08-13 14:14 ` Peter Zijlstra
2009-08-13 14:18 ` [tip:perfcounters/urgent] " tip-bot for Peter Zijlstra
2009-08-15 8:58 ` [PATCH] " Pekka Enberg
1 sibling, 2 replies; 10+ messages in thread
From: Peter Zijlstra @ 2009-08-13 14:14 UTC (permalink / raw)
To: Pekka Enberg
Cc: mingo, Arnaldo Carvalho de Melo, paulus, linux-kernel,
Anton Blanchard, Arjan van de Ven
A bug in (9f498cc: perf_counter: Full task tracing) makes profiling
multi-threaded apps it go belly up.
[ output as: (PID:TID):(PPID:PTID) ]
# ./perf report -D | grep FORK
0x4b0 [0x18]: PERF_EVENT_FORK: (3237:3237):(3236:3236)
0xa10 [0x18]: PERF_EVENT_FORK: (3237:3238):(3236:3236)
0xa70 [0x18]: PERF_EVENT_FORK: (3237:3239):(3236:3236)
0xad0 [0x18]: PERF_EVENT_FORK: (3237:3240):(3236:3236)
0xb18 [0x18]: PERF_EVENT_FORK: (3237:3241):(3236:3236)
Shows us that the test (27d028d perf report: Update for the new
FORK/EXIT events) in builtin-report.c:
/*
* A thread clone will have the same PID for both
* parent and child.
*/
if (thread == parent)
return 0;
Will clearly fail.
The problem is that perf_counter_fork() reports the actual parent,
instead of the cloning thread.
Fixing that (with the below patch), yields:
# ./perf report -D | grep FORK
0x4c8 [0x18]: PERF_EVENT_FORK: (1590:1590):(1589:1589)
0xbd8 [0x18]: PERF_EVENT_FORK: (1590:1591):(1590:1590)
0xc80 [0x18]: PERF_EVENT_FORK: (1590:1592):(1590:1590)
0x3338 [0x18]: PERF_EVENT_FORK: (1590:1593):(1590:1590)
0x66b0 [0x18]: PERF_EVENT_FORK: (1590:1594):(1590:1590)
Which both makes more sense and doesn't confuse perf report anymore.
Reported-by: Pekka Enberg <penberg@cs.helsinki.fi>
Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
perf_counter.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
Index: linux-2.6/kernel/perf_counter.c
===================================================================
--- linux-2.6.orig/kernel/perf_counter.c
+++ linux-2.6/kernel/perf_counter.c
@@ -3024,10 +3024,10 @@ static void perf_counter_task_output(str
return;
task_event->event.pid = perf_counter_pid(counter, task);
- task_event->event.ppid = perf_counter_pid(counter, task->real_parent);
+ task_event->event.ppid = perf_counter_pid(counter, current);
task_event->event.tid = perf_counter_tid(counter, task);
- task_event->event.ptid = perf_counter_tid(counter, task->real_parent);
+ task_event->event.ptid = perf_counter_tid(counter, current);
perf_output_put(&handle, task_event->event);
perf_output_end(&handle);
^ permalink raw reply [flat|nested] 10+ messages in thread
* [tip:perfcounters/urgent] perf_counter: Report the cloning task as parent on perf_counter_fork()
2009-08-13 14:14 ` [PATCH] perf_counter: Report the cloning task as parent on perf_counter_fork() Peter Zijlstra
@ 2009-08-13 14:18 ` tip-bot for Peter Zijlstra
2009-08-15 8:58 ` [PATCH] " Pekka Enberg
1 sibling, 0 replies; 10+ messages in thread
From: tip-bot for Peter Zijlstra @ 2009-08-13 14:18 UTC (permalink / raw)
To: linux-tip-commits
Cc: linux-kernel, anton, acme, hpa, mingo, a.p.zijlstra, penberg,
peterz, arjan, tglx, mingo
Commit-ID: 94d5d1b2d891f1fd5205f978246b7864d998b25c
Gitweb: http://git.kernel.org/tip/94d5d1b2d891f1fd5205f978246b7864d998b25c
Author: Peter Zijlstra <peterz@infradead.org>
AuthorDate: Thu, 13 Aug 2009 16:14:42 +0200
Committer: Ingo Molnar <mingo@elte.hu>
CommitDate: Thu, 13 Aug 2009 16:17:15 +0200
perf_counter: Report the cloning task as parent on perf_counter_fork()
A bug in (9f498cc: perf_counter: Full task tracing) makes
profiling multi-threaded apps it go belly up.
[ output as: (PID:TID):(PPID:PTID) ]
# ./perf report -D | grep FORK
0x4b0 [0x18]: PERF_EVENT_FORK: (3237:3237):(3236:3236)
0xa10 [0x18]: PERF_EVENT_FORK: (3237:3238):(3236:3236)
0xa70 [0x18]: PERF_EVENT_FORK: (3237:3239):(3236:3236)
0xad0 [0x18]: PERF_EVENT_FORK: (3237:3240):(3236:3236)
0xb18 [0x18]: PERF_EVENT_FORK: (3237:3241):(3236:3236)
Shows us that the test (27d028d perf report: Update for the new
FORK/EXIT events) in builtin-report.c:
/*
* A thread clone will have the same PID for both
* parent and child.
*/
if (thread == parent)
return 0;
Will clearly fail.
The problem is that perf_counter_fork() reports the actual
parent, instead of the cloning thread.
Fixing that (with the below patch), yields:
# ./perf report -D | grep FORK
0x4c8 [0x18]: PERF_EVENT_FORK: (1590:1590):(1589:1589)
0xbd8 [0x18]: PERF_EVENT_FORK: (1590:1591):(1590:1590)
0xc80 [0x18]: PERF_EVENT_FORK: (1590:1592):(1590:1590)
0x3338 [0x18]: PERF_EVENT_FORK: (1590:1593):(1590:1590)
0x66b0 [0x18]: PERF_EVENT_FORK: (1590:1594):(1590:1590)
Which both makes more sense and doesn't confuse perf report
anymore.
Reported-by: Pekka Enberg <penberg@cs.helsinki.fi>
Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: paulus@samba.org
Cc: Anton Blanchard <anton@samba.org>
Cc: Arjan van de Ven <arjan@infradead.org>
LKML-Reference: <1250172882.5241.62.camel@twins>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
kernel/perf_counter.c | 4 ++--
1 files changed, 2 insertions(+), 2 deletions(-)
diff --git a/kernel/perf_counter.c b/kernel/perf_counter.c
index 3f841be..534e20d 100644
--- a/kernel/perf_counter.c
+++ b/kernel/perf_counter.c
@@ -3028,10 +3028,10 @@ static void perf_counter_task_output(struct perf_counter *counter,
return;
task_event->event.pid = perf_counter_pid(counter, task);
- task_event->event.ppid = perf_counter_pid(counter, task->real_parent);
+ task_event->event.ppid = perf_counter_pid(counter, current);
task_event->event.tid = perf_counter_tid(counter, task);
- task_event->event.ptid = perf_counter_tid(counter, task->real_parent);
+ task_event->event.ptid = perf_counter_tid(counter, current);
perf_output_put(&handle, task_event->event);
perf_output_end(&handle);
^ permalink raw reply related [flat|nested] 10+ messages in thread
* Re: [PATCH] perf_counter: Report the cloning task as parent on perf_counter_fork()
2009-08-13 14:14 ` [PATCH] perf_counter: Report the cloning task as parent on perf_counter_fork() Peter Zijlstra
2009-08-13 14:18 ` [tip:perfcounters/urgent] " tip-bot for Peter Zijlstra
@ 2009-08-15 8:58 ` Pekka Enberg
2009-08-15 9:13 ` Ingo Molnar
1 sibling, 1 reply; 10+ messages in thread
From: Pekka Enberg @ 2009-08-15 8:58 UTC (permalink / raw)
To: Peter Zijlstra
Cc: mingo, Arnaldo Carvalho de Melo, paulus, linux-kernel,
Anton Blanchard, Arjan van de Ven
Peter Zijlstra wrote:
> A bug in (9f498cc: perf_counter: Full task tracing) makes profiling
> multi-threaded apps it go belly up.
Thanks!
Tested-by: Pekka Enberg <penberg@cs.helsinki.fi>
I hope the fix makes it to 2.6.31 final as perf is unusable for
multi-threaded applications.
Pekka
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH] perf_counter: Report the cloning task as parent on perf_counter_fork()
2009-08-15 8:58 ` [PATCH] " Pekka Enberg
@ 2009-08-15 9:13 ` Ingo Molnar
0 siblings, 0 replies; 10+ messages in thread
From: Ingo Molnar @ 2009-08-15 9:13 UTC (permalink / raw)
To: Pekka Enberg
Cc: Peter Zijlstra, Arnaldo Carvalho de Melo, paulus, linux-kernel,
Anton Blanchard, Arjan van de Ven
* Pekka Enberg <penberg@cs.helsinki.fi> wrote:
> Peter Zijlstra wrote:
>> A bug in (9f498cc: perf_counter: Full task tracing) makes profiling
>> multi-threaded apps it go belly up.
>
> Thanks!
>
> Tested-by: Pekka Enberg <penberg@cs.helsinki.fi>
>
> I hope the fix makes it to 2.6.31 final as perf is unusable for
> multi-threaded applications.
Yeah, the fix is already in -rc6.
Ingo
^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2009-08-15 9:13 UTC | newest]
Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2009-08-13 9:28 [PROBLEM] perf report is broken in latest linus git Pekka Enberg
2009-08-13 9:36 ` Ingo Molnar
2009-08-13 9:47 ` Pekka Enberg
2009-08-13 11:33 ` Peter Zijlstra
2009-08-13 12:02 ` Pekka Enberg
2009-08-13 12:24 ` Pekka Enberg
2009-08-13 14:14 ` [PATCH] perf_counter: Report the cloning task as parent on perf_counter_fork() Peter Zijlstra
2009-08-13 14:18 ` [tip:perfcounters/urgent] " tip-bot for Peter Zijlstra
2009-08-15 8:58 ` [PATCH] " Pekka Enberg
2009-08-15 9:13 ` Ingo Molnar
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).