perf tool sort: Use default sort if evlist is empty

PATCH In review David Carrillo-Cisneros 4 participants 7 messages Jul 21, 2017 – Jul 26, 2017 perf events

Share & tools

David Carrillo-Cisneros

author

2017-07-21 05:13 UTC #0 lore raw

PATCH 1/1 perf tool sort: Use default sort if evlist is empty

Fixes bug noted by Jiri in https://lkml.org/lkml/2017/6/13/755 and caused by commit d49dadea7862 ("perf tools: Make 'trace' or 'trace_fields' sort
key default for tracepoint events")
not taking into account that evlist is empty in pipe-mode.

Before this commit, pipe mode will only show bogus "100.00% N/A" instead of correct output as follows:

  $ perf record -o - sleep 1 | perf report -i -
  # To display the perf.data header info, please use --header/--header-only options.
  #
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.000 MB - ]
  #
  # Total Lost Samples: 0
  #
  # Samples: 8  of event 'cycles:ppH'
  # Event count (approx.): 145658
  #
  # Overhead  Trace output
  # ........  ............
  #
     100.00%  N/A

Correct output, after patch:

  $ perf record -o - sleep 1 | perf report -i -
  # To display the perf.data header info, please use --header/--header-only options.
  #
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.000 MB - ]
  #
  # Total Lost Samples: 0
  #
  # Samples: 8  of event 'cycles:ppH'
  # Event count (approx.): 191331
  #
  # Overhead  Command  Shared Object      Symbol
  # ........  .......  .................  .................................
  #
      81.63%  sleep    libc-2.19.so       [.] _exit
      13.58%  sleep    ld-2.19.so         [.] do_lookup_x
       2.34%  sleep    [kernel.kallsyms]  [k] context_switch
       2.34%  sleep    libc-2.19.so       [.] __GI___libc_nanosleep
       0.11%  perf     [kernel.kallsyms]  [k] __intel_pmu_enable_a

Signed-off-by David Carrillo-Cisneros <[email protected]>

---
 tools/perf/util/evlist.h | 5 +++++
 tools/perf/util/sort.c   | 2 +-
 2 files changed, 6 insertions(+), 1 deletion(-)

tools/perf/util/evlist.h +5 -0

index 0843746bc389..bf2c4936e35f 100644
@@ -265,6 +265,11 @@ bool perf_evlist__valid_read_format(struct perf_evlist *evlist);
 void perf_evlist__splice_list_tail(struct perf_evlist *evlist,
 				   struct list_head *list);
 
+static inline bool perf_evlist__empty(struct perf_evlist *evlist)
+{
+	return list_empty(&evlist->entries);
+}
+
 static inline struct perf_evsel *perf_evlist__first(struct perf_evlist *evlist)
 {
 	return list_entry(evlist->entries.next, struct perf_evsel, node);

tools/perf/util/sort.c +1 -1

index 8b327c955a4f..12359bd986db 100644
@@ -2563,7 +2563,7 @@ static const char *get_default_sort_order(struct perf_evlist *evlist)
 
 	BUG_ON(sort__mode >= ARRAY_SIZE(default_sort_orders));
 
-	if (evlist == NULL)
+	if (evlist == NULL || perf_evlist__empty(evlist))
 		goto out_no_evlist;
 
 	evlist__for_each_entry(evlist, evsel) {

Signature · 1 line

2.14.0.rc0.284.gd933b75aa4-goog

Jiri Olsa

2017-07-21 07:44 UTC #1 lore raw

Quoted 37 lines · David Carrillo-Cisneros

Fixes bug noted by Jiri in https://lkml.org/lkml/2017/6/13/755 and caused by commit d49dadea7862 ("perf tools: Make 'trace' or 'trace_fields' sort
key default for tracepoint events")
not taking into account that evlist is empty in pipe-mode.
Before this commit, pipe mode will only show bogus "100.00% N/A" instead of correct output as follows:
  $ perf record -o - sleep 1 | perf report -i -
  # To display the perf.data header info, please use --header/--header-only options.
  #
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.000 MB - ]
  #
  # Total Lost Samples: 0
  #
  # Samples: 8  of event 'cycles:ppH'
  # Event count (approx.): 145658
  #
  # Overhead  Trace output
  # ........  ............
  #
     100.00%  N/A
Correct output, after patch:
  $ perf record -o - sleep 1 | perf report -i -
  # To display the perf.data header info, please use --header/--header-only options.
  #
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.000 MB - ]
  #
  # Total Lost Samples: 0
  #
  # Samples: 8  of event 'cycles:ppH'
  # Event count (approx.): 191331
  #

Quoted 9 lines

  # Overhead  Command  Shared Object      Symbol
  # ........  .......  .................  .................................
  #
      81.63%  sleep    libc-2.19.so       [.] _exit
      13.58%  sleep    ld-2.19.so         [.] do_lookup_x
       2.34%  sleep    [kernel.kallsyms]  [k] context_switch
       2.34%  sleep    libc-2.19.so       [.] __GI___libc_nanosleep
       0.11%  perf     [kernel.kallsyms]  [k] __intel_pmu_enable_a

I wonder we could reinit the sortorder once we know what events we have in pipe, and recognize the tracepoint output properly:

	[root@krava perf]# ./perf record -e 'sched:sched_switch' sleep 1 |  ./perf report
	# To display the perf.data header info, please use --header/--header-only options.

	SNIP

	#
	# Overhead  Command  Shared Object      Symbol        
	# ........  .......  .................  ..............
	#
	   100.00%  sleep    [kernel.kallsyms]  [k] __schedule

also I've got another crash for (added -a option for above example):

[root@krava perf]# ./perf record -e 'sched:sched_switch' -a sleep 1 | ./perf report # To display the perf.data header info, please use --header/--header-only options. #
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.000 MB (null) ]
Segmentation fault (core dumped)

catchsegv got:

	/home/jolsa/kernel/linux-perf/tools/perf/util/ordered-events.c:85(free_dup_event)[0x51a6a5]
	./perf(ordered_events__free+0x5c)[0x51b0b7]
	/home/jolsa/kernel/linux-perf/tools/perf/util/session.c:1751(__perf_session__process_pipe_events)[0x518abb]
	./perf(perf_session__process_events+0x91)[0x5190f0]
	/home/jolsa/kernel/linux-perf/tools/perf/builtin-report.c:598(__cmd_report)[0x443a91]
	./perf(cmd_report+0x169b)[0x4455a3]
	/home/jolsa/kernel/linux-perf/tools/perf/perf.c:296(run_builtin)[0x4be1b0]
	/home/jolsa/kernel/linux-perf/tools/perf/perf.c:348(handle_internal_command)[0x4be41d]
	/home/jolsa/kernel/linux-perf/tools/perf/perf.c:395(run_argv)[0x4be56f]
	./perf(main+0x2d6)[0x4be949]
	/lib64/libc.so.6(__libc_start_main+0xf1)[0x7f3de8a10401]
	./perf(_start+0x2a)[0x42831a]

looks like some mem corruption.. will try to follow up on this later if nobody beats me to it ;-)

thanks,
jirka

David Carrillo-Cisneros

author

2017-07-21 20:02 UTC #2 lore raw

Quoted 48 lines · Jiri Olsa

Quoted 37 lines · David Carrillo-Cisneros

Fixes bug noted by Jiri in https://lkml.org/lkml/2017/6/13/755 and caused by commit d49dadea7862 ("perf tools: Make 'trace' or 'trace_fields' sort
key default for tracepoint events")
not taking into account that evlist is empty in pipe-mode.
Before this commit, pipe mode will only show bogus "100.00% N/A" instead of correct output as follows:
  $ perf record -o - sleep 1 | perf report -i -
  # To display the perf.data header info, please use --header/--header-only options.
  #
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.000 MB - ]
  #
  # Total Lost Samples: 0
  #
  # Samples: 8  of event 'cycles:ppH'
  # Event count (approx.): 145658
  #
  # Overhead  Trace output
  # ........  ............
  #
     100.00%  N/A
Correct output, after patch:
  $ perf record -o - sleep 1 | perf report -i -
  # To display the perf.data header info, please use --header/--header-only options.
  #
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.000 MB - ]
  #
  # Total Lost Samples: 0
  #
  # Samples: 8  of event 'cycles:ppH'
  # Event count (approx.): 191331
  #

Quoted 9 lines

  # Overhead  Command  Shared Object      Symbol
  # ........  .......  .................  .................................
  #
      81.63%  sleep    libc-2.19.so       [.] _exit
      13.58%  sleep    ld-2.19.so         [.] do_lookup_x
       2.34%  sleep    [kernel.kallsyms]  [k] context_switch
       2.34%  sleep    libc-2.19.so       [.] __GI___libc_nanosleep
       0.11%  perf     [kernel.kallsyms]  [k] __intel_pmu_enable_a

Quoted 3 lines

I wonder we could reinit the sortorder once we know what events we have in pipe, and recognize the tracepoint output properly:

I see this hard to do since, at any given point while traversing the pipe's content, the best we can do is guess that we've seen all event types. Then we'd need to fall back and redo the output whenever a new sample refutes our last guess.

Quoted 36 lines

        [root@krava perf]# ./perf record -e 'sched:sched_switch' sleep 1 |  ./perf report
        # To display the perf.data header info, please use --header/--header-only options.

        SNIP

        #
        # Overhead  Command  Shared Object      Symbol
        # ........  .......  .................  ..............
        #
           100.00%  sleep    [kernel.kallsyms]  [k] __schedule

also I've got another crash for (added -a option for above example):

catchsegv got:

        /home/jolsa/kernel/linux-perf/tools/perf/util/ordered-events.c:85(free_dup_event)[0x51a6a5]
        ./perf(ordered_events__free+0x5c)[0x51b0b7]
        /home/jolsa/kernel/linux-perf/tools/perf/util/session.c:1751(__perf_session__process_pipe_events)[0x518abb]
        ./perf(perf_session__process_events+0x91)[0x5190f0]
        /home/jolsa/kernel/linux-perf/tools/perf/builtin-report.c:598(__cmd_report)[0x443a91]
        ./perf(cmd_report+0x169b)[0x4455a3]
        /home/jolsa/kernel/linux-perf/tools/perf/perf.c:296(run_builtin)[0x4be1b0]
        /home/jolsa/kernel/linux-perf/tools/perf/perf.c:348(handle_internal_command)[0x4be41d]
        /home/jolsa/kernel/linux-perf/tools/perf/perf.c:395(run_argv)[0x4be56f]
        ./perf(main+0x2d6)[0x4be949]
        /lib64/libc.so.6(__libc_start_main+0xf1)[0x7f3de8a10401]
        ./perf(_start+0x2a)[0x42831a]

Quoted 2 lines

looks like some mem corruption.. will try to follow up on this later if nobody beats me to it ;-)

Cannot reproduce it in acme's perf/core building the tool with
make NO_LIBPYTHON=1 LDFLAGS=-static

If you have a file with the perf record output causing perf report's crash, I'd like to take a look.

Thanks,
David

Namhyung Kim

maintainer

2017-07-22 23:10 UTC #3 lore raw

Quoted 49 lines · David Carrillo-Cisneros

Quoted 48 lines · Jiri Olsa

Quoted 46 lines · David Carrillo-Cisneros

Before this commit, pipe mode will only show bogus "100.00% N/A" instead of correct output as follows:

  $ perf record -o - sleep 1 | perf report -i -
  # To display the perf.data header info, please use --header/--header-only options.
  #
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.000 MB - ]
  #
  # Total Lost Samples: 0
  #
  # Samples: 8  of event 'cycles:ppH'
  # Event count (approx.): 145658
  #
  # Overhead  Trace output
  # ........  ............
  #
     100.00%  N/A

Correct output, after patch:

  $ perf record -o - sleep 1 | perf report -i -
  # To display the perf.data header info, please use --header/--header-only options.
  #
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.000 MB - ]
  #
  # Total Lost Samples: 0
  #
  # Samples: 8  of event 'cycles:ppH'
  # Event count (approx.): 191331
  #
  # Overhead  Command  Shared Object      Symbol
  # ........  .......  .................  .................................
  #
      81.63%  sleep    libc-2.19.so       [.] _exit
      13.58%  sleep    ld-2.19.so         [.] do_lookup_x
       2.34%  sleep    [kernel.kallsyms]  [k] context_switch
       2.34%  sleep    libc-2.19.so       [.] __GI___libc_nanosleep
       0.11%  perf     [kernel.kallsyms]  [k] __intel_pmu_enable_a

Quoted 8 lines

Quoted 3 lines
I wonder we could reinit the sortorder once we know what events we have in pipe, and recognize the tracepoint output properly:
I see this hard to do since, at any given point while traversing the pipe's content, the best we can do is guess that we've seen all event types. Then we'd need to fall back and redo the output whenever a new sample refutes our last guess.

After reading feature event, you could know the number of events, no?

Thanks,
Namhyung

Quoted 48 lines

Quoted 37 lines
        [root@krava perf]# ./perf record -e 'sched:sched_switch' sleep 1 |  ./perf report
        # To display the perf.data header info, please use --header/--header-only options.

        SNIP

        #
        # Overhead  Command  Shared Object      Symbol
        # ........  .......  .................  ..............
        #
           100.00%  sleep    [kernel.kallsyms]  [k] __schedule
also I've got another crash for (added -a option for above example):
[root@krava perf]# ./perf record -e 'sched:sched_switch' -a sleep 1 | ./perf report # To display the perf.data header info, please use --header/--header-only options. #
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.000 MB (null) ]
Segmentation fault (core dumped)
catchsegv got:
        /home/jolsa/kernel/linux-perf/tools/perf/util/ordered-events.c:85(free_dup_event)[0x51a6a5]
        ./perf(ordered_events__free+0x5c)[0x51b0b7]
        /home/jolsa/kernel/linux-perf/tools/perf/util/session.c:1751(__perf_session__process_pipe_events)[0x518abb]
        ./perf(perf_session__process_events+0x91)[0x5190f0]
        /home/jolsa/kernel/linux-perf/tools/perf/builtin-report.c:598(__cmd_report)[0x443a91]
        ./perf(cmd_report+0x169b)[0x4455a3]
        /home/jolsa/kernel/linux-perf/tools/perf/perf.c:296(run_builtin)[0x4be1b0]
        /home/jolsa/kernel/linux-perf/tools/perf/perf.c:348(handle_internal_command)[0x4be41d]
        /home/jolsa/kernel/linux-perf/tools/perf/perf.c:395(run_argv)[0x4be56f]
        ./perf(main+0x2d6)[0x4be949]
        /lib64/libc.so.6(__libc_start_main+0xf1)[0x7f3de8a10401]
        ./perf(_start+0x2a)[0x42831a]
Quoted 2 lines
looks like some mem corruption.. will try to follow up on this later if nobody beats me to it ;-)
Cannot reproduce it in acme's perf/core building the tool with
make NO_LIBPYTHON=1 LDFLAGS=-static
If you have a file with the perf record output causing perf report's crash, I'd like to take a look.
Thanks,
David

Jiri Olsa

2017-07-24 07:47 UTC #4 lore raw

On Sun, Jul 23, 2017 at 08:09:49AM +0900, Namhyung Kim wrote:

SNIP

Quoted 23 lines

Quoted 23 lines
Quoted 23 lines
also I've got another crash for (added -a option for above example):
[root@krava perf]# ./perf record -e 'sched:sched_switch' -a sleep 1 | ./perf report # To display the perf.data header info, please use --header/--header-only options. #
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.000 MB (null) ]
Segmentation fault (core dumped)
catchsegv got:
        /home/jolsa/kernel/linux-perf/tools/perf/util/ordered-events.c:85(free_dup_event)[0x51a6a5]
        ./perf(ordered_events__free+0x5c)[0x51b0b7]
        /home/jolsa/kernel/linux-perf/tools/perf/util/session.c:1751(__perf_session__process_pipe_events)[0x518abb]
        ./perf(perf_session__process_events+0x91)[0x5190f0]
        /home/jolsa/kernel/linux-perf/tools/perf/builtin-report.c:598(__cmd_report)[0x443a91]
        ./perf(cmd_report+0x169b)[0x4455a3]
        /home/jolsa/kernel/linux-perf/tools/perf/perf.c:296(run_builtin)[0x4be1b0]
        /home/jolsa/kernel/linux-perf/tools/perf/perf.c:348(handle_internal_command)[0x4be41d]
        /home/jolsa/kernel/linux-perf/tools/perf/perf.c:395(run_argv)[0x4be56f]
        ./perf(main+0x2d6)[0x4be949]
        /lib64/libc.so.6(__libc_start_main+0xf1)[0x7f3de8a10401]
        ./perf(_start+0x2a)[0x42831a]

Quoted 8 lines

Quoted 8 lines
Quoted 2 lines
looks like some mem corruption.. will try to follow up on this later if nobody beats me to it ;-)
Cannot reproduce it in acme's perf/core building the tool with
make NO_LIBPYTHON=1 LDFLAGS=-static
If you have a file with the perf record output causing perf report's crash, I'd like to take a look.

hm, I can't reproduce any longer.. :-\

jirka

David Carrillo-Cisneros

author

2017-07-24 10:43 UTC #5 lore raw

In reply to Namhyung Kim

Quoted 54 lines · Namhyung Kim

Quoted 53 lines · David Carrillo-Cisneros
Quoted 51 lines · Jiri Olsa
Quoted 37 lines · David Carrillo-Cisneros
Fixes bug noted by Jiri in https://lkml.org/lkml/2017/6/13/755 and caused by commit d49dadea7862 ("perf tools: Make 'trace' or 'trace_fields' sort
key default for tracepoint events")
not taking into account that evlist is empty in pipe-mode.
Before this commit, pipe mode will only show bogus "100.00% N/A" instead of correct output as follows:
  $ perf record -o - sleep 1 | perf report -i -
  # To display the perf.data header info, please use --header/--header-only options.
  #
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.000 MB - ]
  #
  # Total Lost Samples: 0
  #
  # Samples: 8  of event 'cycles:ppH'
  # Event count (approx.): 145658
  #
  # Overhead  Trace output
  # ........  ............
  #
     100.00%  N/A
Correct output, after patch:
  $ perf record -o - sleep 1 | perf report -i -
  # To display the perf.data header info, please use --header/--header-only options.
  #
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.000 MB - ]
  #
  # Total Lost Samples: 0
  #
  # Samples: 8  of event 'cycles:ppH'
  # Event count (approx.): 191331
  #
Quoted 9 lines
  # Overhead  Command  Shared Object      Symbol
  # ........  .......  .................  .................................
  #
      81.63%  sleep    libc-2.19.so       [.] _exit
      13.58%  sleep    ld-2.19.so         [.] do_lookup_x
       2.34%  sleep    [kernel.kallsyms]  [k] context_switch
       2.34%  sleep    libc-2.19.so       [.] __GI___libc_nanosleep
       0.11%  perf     [kernel.kallsyms]  [k] __intel_pmu_enable_a
I wonder we could reinit the sortorder once we know what events we have in pipe, and recognize the tracepoint output properly:

Quoted 6 lines

Quoted 4 lines
I see this hard to do since, at any given point while traversing the pipe's content, the best we can do is guess that we've seen all event types. Then we'd need to fall back and redo the output whenever a new sample refutes our last guess.
After reading feature event, you could know the number of events, no?

True. Also the tool could extract the events from HEADER_EVENT_DESC feature event and adjust output accordingly. That'd be a nice to have feature.

Thanks,
David

Arnaldo Carvalho de Melo

maintainer

2017-07-26 20:03 UTC #6 lore raw

In reply to David Carrillo-Cisneros

Em Thu, Jul 20, 2017 at 10:11:57PM -0700, David Carrillo-Cisneros escreveu:

Quoted 8 lines

Fixes bug noted by Jiri in https://lkml.org/lkml/2017/6/13/755 and caused by commit d49dadea7862 ("perf tools: Make 'trace' or 'trace_fields' sort
key default for tracepoint events")
not taking into account that evlist is empty in pipe-mode.
Before this commit, pipe mode will only show bogus "100.00% N/A" instead of correct output as follows:

Thanks, tested and applied.

- Arnaldo