perf tools: some 'perf script' fixes

Hi,

This patchset fixes various problems I hit while doing a run-through of the existing 'perf script' scripts.

Also, sometimes when running rwtop I get a 'failed to read event header' error, which this patch fixes:

https://lkml.org/lkml/2012/9/14/401

Not sure if that was meant to get picked up, but it fixed that particular problem here for me.

Thanks,

Tom

Tom Zanussi (4):
perf/tools: reinstate 'signed' field flag for tracepoints perf script: don't display trace info when invoking scripts perf tools: hook up perf_scripting_context->pevent perf script: remove workqueue-stats script

 tools/lib/traceevent/event-parse.c                 |   3 +-
 tools/perf/Documentation/perf-script-python.txt    |   2 -
 tools/perf/builtin-script.c                        |   3 +-
 tools/perf/scripts/perl/bin/workqueue-stats-record |   2 -
 tools/perf/scripts/perl/bin/workqueue-stats-report |   3 -
 tools/perf/scripts/perl/workqueue-stats.pl         | 129 ---------------------
 .../perf/util/scripting-engines/trace-event-perl.c |   1 +
 .../util/scripting-engines/trace-event-python.c    |   1 +
 8 files changed, 6 insertions(+), 138 deletions(-)
 delete mode 100644 tools/perf/scripts/perl/bin/workqueue-stats-record
 delete mode 100644 tools/perf/scripts/perl/bin/workqueue-stats-report
 delete mode 100644 tools/perf/scripts/perl/workqueue-stats.pl

1.7.11.4

For some reason the libtraceevent tracepoint-parsing code is missing the FIELD_IS_SIGNED flag-setting code, which causes problems for the Perl trace event binding at least, since it ends up unable to recognize negative numbers. Things like checking for negative return values therefore fail, causing scripts like rwtop to instead interpret the negative return value as a large positive value, which in turn get added to e.g. read totals with insanely invalid results.

So set the FIELD_IS_SIGNED flag for tracepoint events that specify "signed:1".

Before:

  # perf script record rw-by-pid
  # perf script report rw-by-pid

read counts by pid:

pid comm # reads bytes_requested bytes_read

  ------  --------------------  -----------  ----------  ----------
     753  Xorg                          88      512000  7.74763251095801e+20
    1619  firefox                       42         462  2.58254417031934e+20
    1232  gnome-shell                   11         176  1.10680464442257e+20
    1471  gnome-terminal                 3       16366  18446744073709551615
    1408  libsocialweb-co                2          32  18446744073709551613

After:

  # perf script report rw-by-pid

read counts by pid:

pid comm # reads bytes_requested bytes_read

  ------  --------------------  -----------  ----------  ----------
     753  Xorg                          88      512000        2764
    1619  firefox                       42         462         126
    1232  gnome-shell                   11         176          40
    1471  gnome-terminal                 3       16366          10
    1408  libsocialweb-co                2          32           8

---
 tools/lib/traceevent/event-parse.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

index 5a824e3..cbb48e4 100644
@@ -1463,7 +1463,8 @@ static int event_read_fields(struct event_format *event, struct format_field **f
 			if (read_expect_type(EVENT_ITEM, &token))
 				goto fail;
 
-			/* add signed type */
+			if (strtoul(token, NULL, 0))
+				field->flags |= FIELD_IS_SIGNED;
 
 			free_token(token);
 			if (read_expected(EVENT_OP, ";") < 0)

1.7.11.4

Commit-ID:  10ee9fa3b92dece36209a3786d7bd558d459635f
Gitweb:     http://git.kernel.org/tip/10ee9fa3b92dece36209a3786d7bd558d459635f
Author:     Tom Zanussi <[email protected]>
AuthorDate: Fri, 18 Jan 2013 13:51:25 -0600
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Thu, 24 Jan 2013 16:40:52 -0300

perf tools: Reinstate 'signed' field flag for tracepoints

For some reason the libtraceevent tracepoint-parsing code is missing the FIELD_IS_SIGNED flag-setting code, which causes problems for the Perl trace event binding at least, since it ends up unable to recognize negative numbers.

Things like checking for negative return values therefore fail, causing scripts like rwtop to instead interpret the negative return value as a large positive value, which in turn get added to e.g. read totals with insanely invalid results.

So set the FIELD_IS_SIGNED flag for tracepoint events that specify "signed:1".

Before:

  # perf script record rw-by-pid
  # perf script report rw-by-pid

read counts by pid:

pid comm # reads bytes_requested bytes_read

  ------  --------------------  -----------  ----------  ----------
     753  Xorg                          88      512000  7.74763251095801e+20
    1619  firefox                       42         462  2.58254417031934e+20
    1232  gnome-shell                   11         176  1.10680464442257e+20
    1471  gnome-terminal                 3       16366  18446744073709551615
    1408  libsocialweb-co                2          32  18446744073709551613

After:

  # perf script report rw-by-pid

read counts by pid:

pid comm # reads bytes_requested bytes_read

  ------  --------------------  -----------  ----------  ----------
     753  Xorg                          88      512000        2764
    1619  firefox                       42         462         126
    1232  gnome-shell                   11         176          40
    1471  gnome-terminal                 3       16366          10
    1408  libsocialweb-co                2          32           8

---
 tools/lib/traceevent/event-parse.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

index f504619..bb8b3db 100644
@@ -1462,7 +1462,8 @@ static int event_read_fields(struct event_format *event, struct format_field **f
 			if (read_expect_type(EVENT_ITEM, &token))
 				goto fail;
 
-			/* add signed type */
+			if (strtoul(token, NULL, 0))
+				field->flags |= FIELD_IS_SIGNED;
 
 			free_token(token);
 			if (read_expected(EVENT_OP, ";") < 0)

Only display the trace info if using the default event display. When invoking scripts we assume they have complete control of what's displayed so we shouldn't unconditionally display the trace info, and when generating scripts we don't expect to see trace info obscuring the output message.

---
 tools/perf/builtin-script.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

index b363e7b..1bb305c 100644
@@ -1487,7 +1487,8 @@ int cmd_script(int argc, const char **argv, const char *prefix __maybe_unused)
 			return -1;
 	}
 
-	perf_session__fprintf_info(session, stdout, show_full_info);
+	if (!script_name && !generate_script_lang)
+		perf_session__fprintf_info(session, stdout, show_full_info);
 
 	if (!no_callchain)
 		symbol_conf.use_callchain = true;

1.7.11.4

Commit-ID:  bdb71db29d50b61f45459b8facfb876768e8cacc
Gitweb:     http://git.kernel.org/tip/bdb71db29d50b61f45459b8facfb876768e8cacc
Author:     Tom Zanussi <[email protected]>
AuthorDate: Fri, 18 Jan 2013 13:51:26 -0600
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Thu, 24 Jan 2013 16:40:52 -0300

perf script: Don't display trace info when invoking scripts

Only display the trace info if using the default event display. When invoking scripts we assume they have complete control of what's displayed so we shouldn't unconditionally display the trace info, and when generating scripts we don't expect to see trace info obscuring the output message.

---
 tools/perf/builtin-script.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

index fee4c9a..92d4658 100644
@@ -1475,7 +1475,8 @@ int cmd_script(int argc, const char **argv, const char *prefix __maybe_unused)
 			return -1;
 	}
 
-	perf_session__fprintf_info(session, stdout, show_full_info);
+	if (!script_name && !generate_script_lang)
+		perf_session__fprintf_info(session, stdout, show_full_info);
 
 	if (!no_callchain)
 		symbol_conf.use_callchain = true;

Running the check-perf-trace scripts causes segfaults in both the Perl and Python cases:

  # perf script record check-perf-trace
  # perf script -s libexec/perf-core/scripts/python/check-perf-trace.py
  trace_begin
  Segmentation fault (core dumped)

The reason is that the 'pevent' field was added to perf_scripting_context but it wasn't hooked up with an actual pevent in either case, so when one of the 'common' fields is accessed (in util/trace-event-parse.c:get_common_fields()), pevent->events tries to dereference a NULL pointer.

This sets the pevent field when the scripting context is set up.

---
 tools/perf/util/scripting-engines/trace-event-perl.c   | 1 +
 tools/perf/util/scripting-engines/trace-event-python.c | 1 +
 2 files changed, 2 insertions(+)

index f80605e..eacec85 100644
@@ -292,6 +292,7 @@ static void perl_process_tracepoint(union perf_event *perf_event __maybe_unused,
 	ns = nsecs - s * NSECS_PER_SEC;
 
 	scripting_context->event_data = data;
+	scripting_context->pevent = evsel->tp_format->pevent;
 
 	ENTER;
 	SAVETMPS;

index 14683df..e87aa5d 100644
@@ -265,6 +265,7 @@ static void python_process_tracepoint(union perf_event *perf_event
 	ns = nsecs - s * NSECS_PER_SEC;
 
 	scripting_context->event_data = data;
+	scripting_context->pevent = evsel->tp_format->pevent;
 
 	context = PyCObject_FromVoidPtr(scripting_context, NULL);
 

1.7.11.4

Commit-ID:  2de9533d6d61d3086a7079bf142d2bfa374e664e
Gitweb:     http://git.kernel.org/tip/2de9533d6d61d3086a7079bf142d2bfa374e664e
Author:     Tom Zanussi <[email protected]>
AuthorDate: Fri, 18 Jan 2013 13:51:27 -0600
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Thu, 24 Jan 2013 16:40:52 -0300

perf script: hook up perf_scripting_context->pevent

Running the check-perf-trace scripts causes segfaults in both the Perl and Python cases:

  # perf script record check-perf-trace
  # perf script -s libexec/perf-core/scripts/python/check-perf-trace.py
  trace_begin
  Segmentation fault (core dumped)

The reason is that the 'pevent' field was added to perf_scripting_context but it wasn't hooked up with an actual pevent in either case, so when one of the 'common' fields is accessed (in util/trace-event-parse.c:get_common_fields()), pevent->events tries to dereference a NULL pointer.

This sets the pevent field when the scripting context is set up.

---
 tools/perf/util/scripting-engines/trace-event-perl.c   | 1 +
 tools/perf/util/scripting-engines/trace-event-python.c | 1 +
 2 files changed, 2 insertions(+)

index f80605e..eacec85 100644
@@ -292,6 +292,7 @@ static void perl_process_tracepoint(union perf_event *perf_event __maybe_unused,
 	ns = nsecs - s * NSECS_PER_SEC;
 
 	scripting_context->event_data = data;
+	scripting_context->pevent = evsel->tp_format->pevent;
 
 	ENTER;
 	SAVETMPS;

index 14683df..e87aa5d 100644
@@ -265,6 +265,7 @@ static void python_process_tracepoint(union perf_event *perf_event
 	ns = nsecs - s * NSECS_PER_SEC;
 
 	scripting_context->event_data = data;
+	scripting_context->pevent = evsel->tp_format->pevent;
 
 	context = PyCObject_FromVoidPtr(scripting_context, NULL);
 

The tracepoints used by the workqueue-stats script no longer exist so trying to run the script results in:

  # perf script record workqueue-stats
  invalid or unsupported event: 'workqueue:workqueue_creation'
  Run 'perf list' for a list of valid events

So remove the script until it can be reworked using the new workqueue tracepoints.

---
 tools/perf/Documentation/perf-script-python.txt    |   2 -
 tools/perf/scripts/perl/bin/workqueue-stats-record |   2 -
 tools/perf/scripts/perl/bin/workqueue-stats-report |   3 -
 tools/perf/scripts/perl/workqueue-stats.pl         | 129 ---------------------
 4 files changed, 136 deletions(-)
 delete mode 100644 tools/perf/scripts/perl/bin/workqueue-stats-record
 delete mode 100644 tools/perf/scripts/perl/bin/workqueue-stats-report
 delete mode 100644 tools/perf/scripts/perl/workqueue-stats.pl

index a4027f2..9f1f054 100644
@@ -336,7 +336,6 @@ scripts listed by the 'perf script -l' command e.g.:
 ----
 root@tropicana:~# perf script -l
 List of available trace scripts:
-  workqueue-stats                      workqueue stats (ins/exe/create/destroy)
   wakeup-latency                       system-wide min/max/avg wakeup latency
   rw-by-file <comm>                    r/w activity for a program, by file
   rw-by-pid                            system-wide r/w activity

@@ -402,7 +401,6 @@ should show a new entry for your script:
 ----
 root@tropicana:~# perf script -l
 List of available trace scripts:
-  workqueue-stats                      workqueue stats (ins/exe/create/destroy)
   wakeup-latency                       system-wide min/max/avg wakeup latency
   rw-by-file <comm>                    r/w activity for a program, by file
   rw-by-pid                            system-wide r/w activity

deleted file mode 100644
index 8edda90..0000000
@@ -1,2 +0,0 @@
-#!/bin/bash
-perf record -e workqueue:workqueue_creation -e workqueue:workqueue_destruction -e workqueue:workqueue_execution -e workqueue:workqueue_insertion $@

deleted file mode 100644
index 6d91411..0000000
@@ -1,3 +0,0 @@
-#!/bin/bash
-# description: workqueue stats (ins/exe/create/destroy)
-perf script $@ -s "$PERF_EXEC_PATH"/scripts/perl/workqueue-stats.pl

1.7.11.4

Commit-ID:  1de7b7e89d16e3daf32fb3b6f214d038ab2ed879
Gitweb:     http://git.kernel.org/tip/1de7b7e89d16e3daf32fb3b6f214d038ab2ed879
Author:     Tom Zanussi <[email protected]>
AuthorDate: Fri, 18 Jan 2013 13:51:28 -0600
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Thu, 24 Jan 2013 16:40:53 -0300

perf script: Remove workqueue-stats script

The tracepoints used by the workqueue-stats script no longer exist so trying to run the script results in:

  # perf script record workqueue-stats
  invalid or unsupported event: 'workqueue:workqueue_creation'
  Run 'perf list' for a list of valid events

So remove the script until it can be reworked using the new workqueue tracepoints.

---
 tools/perf/Documentation/perf-script-python.txt    |   2 -
 tools/perf/scripts/perl/bin/workqueue-stats-record |   2 -
 tools/perf/scripts/perl/bin/workqueue-stats-report |   3 -
 tools/perf/scripts/perl/workqueue-stats.pl         | 129 ---------------------
 4 files changed, 136 deletions(-)

index a4027f2..9f1f054 100644
@@ -336,7 +336,6 @@ scripts listed by the 'perf script -l' command e.g.:
 ----
 root@tropicana:~# perf script -l
 List of available trace scripts:
-  workqueue-stats                      workqueue stats (ins/exe/create/destroy)
   wakeup-latency                       system-wide min/max/avg wakeup latency
   rw-by-file <comm>                    r/w activity for a program, by file
   rw-by-pid                            system-wide r/w activity

@@ -402,7 +401,6 @@ should show a new entry for your script:
 ----
 root@tropicana:~# perf script -l
 List of available trace scripts:
-  workqueue-stats                      workqueue stats (ins/exe/create/destroy)
   wakeup-latency                       system-wide min/max/avg wakeup latency
   rw-by-file <comm>                    r/w activity for a program, by file
   rw-by-pid                            system-wide r/w activity

deleted file mode 100644
index 8edda90..0000000
@@ -1,2 +0,0 @@
-#!/bin/bash
-perf record -e workqueue:workqueue_creation -e workqueue:workqueue_destruction -e workqueue:workqueue_execution -e workqueue:workqueue_insertion $@

deleted file mode 100644
index 6d91411..0000000
@@ -1,3 +0,0 @@
-#!/bin/bash
-# description: workqueue stats (ins/exe/create/destroy)
-perf script $@ -s "$PERF_EXEC_PATH"/scripts/perl/workqueue-stats.pl

Em Fri, Jan 18, 2013 at 01:51:24PM -0600, Tom Zanussi escreveu:

David, can you please resubmit it with an explanation in the commit message?

Tom, can I add a Tested-by: you to such patch?

Thanks, applied to my perf/core branch at:

git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux

- Arnaldo

As part of other perf related activities I have noticed that readn is used in some places that we will want it to return immediately -- e.g., evsel.c. So, this might not be the proper fix for all use cases.

David

Yeah, sure.

Thanks,

Tom

Em Thu, Jan 24, 2013 at 02:33:53PM -0600, Tom Zanussi escreveu:

David, perhaps you should just add a local readn variant for 'script' till we find a more general solution, at least it fixes script's case.

- Arnaldo