perf report is broken in latest linus git

PROBLEM In review Pekka Enberg 3 participants 10 messages Aug 13, 2009 – Aug 15, 2009

Share & tools

Pekka Enberg

author

2009-08-13 09:28 UTC #0 lore raw

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

Ingo Molnar

2009-08-13 09:37 UTC #1 lore raw

Quoted 12 lines · Pekka Enberg

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
  # ........  .......  .......................................  ......
  #

Quoted 6 lines

[ 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

Pekka Enberg

author

2009-08-13 09:47 UTC #2 lore raw

Hi Ingo,

Quoted 25 lines · Ingo Molnar

Quoted 12 lines · Pekka Enberg
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
  # ........  .......  .......................................  ......
  #
Quoted 6 lines
[ 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

Quoted 8 lines

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

Peter Zijlstra

2009-08-13 11:34 UTC #3 lore raw

Quoted 31 lines · Pekka Enberg

Hi Ingo,
Quoted 28 lines · Ingo Molnar
Quoted 12 lines · Pekka Enberg
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
  # ........  .......  .......................................  ......
  #
Quoted 6 lines
[ 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:

Quoted 8 lines

Quoted 5 lines
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.

Pekka Enberg

author

2009-08-13 12:02 UTC #4 lore raw

Quoted 10 lines · Peter Zijlstra

Quoted 10 lines
Quoted 10 lines
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

Quoted 8 lines

Quoted 5 lines
Quoted 2 lines
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 <[email protected]>
Date:   Thu Aug 13 10:37:33 2009 +0200

Merge branch 'perfcounters/urgent'

commit daac07b2e6b77f1bd44104aa2f0593e5505f27d4

Author: Frederic Weisbecker <[email protected]>
Date:   Thu Aug 13 10:27:19 2009 +0200

Pekka

Pekka Enberg

author

2009-08-13 12:24 UTC #5 lore raw

Quoted 50 lines · Pekka Enberg

Quoted 10 lines · Peter Zijlstra

Quoted 10 lines
Quoted 10 lines
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

Quoted 8 lines

Quoted 5 lines
Quoted 2 lines
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 <[email protected]>
Date:   Thu Aug 13 10:37:33 2009 +0200

Quoted 5 lines

Merge branch 'perfcounters/urgent'
commit daac07b2e6b77f1bd44104aa2f0593e5505f27d4
Author: Frederic Weisbecker <[email protected]>
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

Peter Zijlstra

2009-08-13 14:15 UTC #6 lore raw

PATCH 1/1 perf_counter: Report the cloning task as parent on perf_counter_fork()

In reply to Pekka Enberg

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 <[email protected]>

Signed-off-by Peter Zijlstra <[email protected]>

---
 perf_counter.c |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

kernel/perf_counter.c +2 -2

Index: 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);

tip-bot for Peter Zijlstra

2009-08-13 14:19 UTC #7 lore raw

[tip:perfcounters/urgent] perf_counter: Report the cloning task as parent on perf_counter_fork()

Commit-ID:  94d5d1b2d891f1fd5205f978246b7864d998b25c
Gitweb:     http://git.kernel.org/tip/94d5d1b2d891f1fd5205f978246b7864d998b25c
Author:     Peter Zijlstra <[email protected]>
AuthorDate: Thu, 13 Aug 2009 16:14:42 +0200
Committer:  Ingo Molnar <[email protected]>
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 <[email protected]>

Signed-off-by Peter Zijlstra <[email protected]>

Cc Arnaldo Carvalho de Melo <[email protected]>

Cc [email protected]

Cc Anton Blanchard <[email protected]>

Cc Arjan van de Ven <[email protected]>

LKML-Reference: <1250172882.5241.62.camel@twins>

Signed-off-by Ingo Molnar <[email protected]>

---
 kernel/perf_counter.c |    4 ++--
 1 files changed, 2 insertions(+), 2 deletions(-)

kernel/perf_counter.c +2 -2

index 3f841be..534e20d 100644
@@ -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);

Pekka Enberg

author Tested-by on v1 1/1

2009-08-15 08:59 UTC #8 lore raw

Re: [PATCH] perf_counter: Report the cloning task as parent on perf_counter_fork()

In reply to Peter Zijlstra

Quoted 2 lines · Peter Zijlstra

A bug in (9f498cc: perf_counter: Full task tracing) makes profiling multi-threaded apps it go belly up.

Thanks!

Tested-by Pekka Enberg <[email protected]>

I hope the fix makes it to 2.6.31 final as perf is unusable for multi-threaded applications.

Pekka

Ingo Molnar

2009-08-15 09:13 UTC #9 lore raw

Re: [PATCH] perf_counter: Report the cloning task as parent on perf_counter_fork()

Quoted 10 lines · Pekka Enberg

Quoted 2 lines · Peter Zijlstra
A bug in (9f498cc: perf_counter: Full task tracing) makes profiling multi-threaded apps it go belly up.
Thanks!
Tested-by Pekka Enberg <[email protected]>
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