* [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