Skip to contentSkip to conversation

perf/report: Report OOM in perf report status line

PATCH Applied Thomas Richter 4 participants 7 messages Apr 23, 2019 – May 3, 2019 perf events

v1 of 2 Applied Latest is v2 →

lore
Share & tools
lore

Thomas Richter

author
#0 lore raw

PATCH 1/1 perf/report: Report OOM in perf report status line

An -ENOMEM error is not reported in the GTK GUI.
Instead this error message pops up on the screen:

[root@m35lp76 perf]# ./perf report -i perf.data.error68-1

	Processing events... [974K/3M]
	Error:failed to process sample

	0xf4198 [0x8]: failed to process type: 68

However when I use the same perf.data file with --stdio it works:

[root@m35lp76 perf]# ./perf  report -i perf.data.error68-1 --stdio \
		| head -12

# Total Lost Samples: 0
#
# Samples: 76K of event 'cycles'
# Event count (approx.): 99056160000
#

  # Overhead  Command          Shared Object      Symbol
  # ........  ...............  .................  .........
  #
     8.81%  find             [kernel.kallsyms]  [k] ftrace_likely_update
     8.74%  swapper          [kernel.kallsyms]  [k] ftrace_likely_update
     8.34%  sshd             [kernel.kallsyms]  [k] ftrace_likely_update
     2.19%  kworker/u512:1-  [kernel.kallsyms]  [k] ftrace_likely_update

The sample precentage is a bit low.....

The GUI always fails in the FINISHED_ROUND event (68) and does not indicate the reason why.

When happened is the following. Perf report calls a lot of functions and down deep when a FINISHED_ROUND event is processed, these functions are called:

perf_session__process_event()
+ perf_session__process_user_event()
+ process_finished_round()
+ ordered_events__flush()
+ __ordered_events__flush()
+ do_flush()
+ ordered_events__deliver_event()
+ perf_session__deliver_event()
+ machine__deliver_event()
+ perf_evlist__deliver_event()
+ process_sample_event()
+ hist_entry_iter_add() --> only called in GUI case!!!
+ hist_iter__report__callback()
+ symbol__inc_addr_sample()

Now this functions runs out of memory and returns -ENOMEM. This is reported all the way up until function

perf_session__process_event() returns to its caller, where -ENOMEM is changed to -EINVAL and processing stops:

 if ((skip = perf_session__process_event(session, event, head)) < 0) {
      pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
	     head, event->header.size, event->header.type);
      err = -EINVAL;
      goto out_err;

}

This occurred in the FINISHED_ROUND event when it has to process some 10000 entries and ran out of memory.

This patch indicates the root cause and displays it in the status line of ther perf report GUI.

Output before (on GUI status line):
0xf4198 [0x8]: failed to process type: 68

Output after:
0xf4198 [0x8]: failed to process type: 68 [not enough memory]

Signed-off-by Thomas Richter <[email protected]>
Reviewed-by Jiri Olsa <[email protected]>
Reviewed-by Hendrik Brueckner <[email protected]>
---
 tools/perf/util/session.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)
tools/perf/util/session.c +3 -3
index b17f1c9bc965..e89716175588 100644
@@ -1930,10 +1930,10 @@ reader__process_events(struct reader *rd, struct perf_session *session,
 
 	if (size < sizeof(struct perf_event_header) ||
 	    (skip = rd->process(session, event, file_pos)) < 0) {
-		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
+		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d [%s]\n",
 		       file_offset + head, event->header.size,
-		       event->header.type);
-		err = -EINVAL;
+		       event->header.type, strerror(-skip));
+		err = skip;
 		goto out;
 	}
Signature · 1 line
2.16.4
Applied
#1 lore raw

Em Tue, Apr 23, 2019 at 12:53:03PM +0200, Thomas Richter escreveu:

Quoted 9 lines

An -ENOMEM error is not reported in the GTK GUI.
Instead this error message pops up on the screen:

[root@m35lp76 perf]# ./perf report -i perf.data.error68-1

	Processing events... [974K/3M]
	Error:failed to process sample

	0xf4198 [0x8]: failed to process type: 68

Thanks, applied to perf/urgent.

- Arnaldo

#2 lore raw

Em Fri, Apr 26, 2019 at 11:09:07AM -0300, Arnaldo Carvalho de Melo escreveu:

Quoted 4 lines

Em Tue, Apr 23, 2019 at 12:53:03PM +0200, Thomas Richter escreveu:

Quoted 3 lines

An -ENOMEM error is not reported in the GTK GUI.
Instead this error message pops up on the screen:

Quoted 8 lines
Quoted 6 lines

[root@m35lp76 perf]# ./perf report -i perf.data.error68-1

	Processing events... [974K/3M]
	Error:failed to process sample

	0xf4198 [0x8]: failed to process type: 68

Thanks, applied to perf/urgent.

Well, I tried to, now trying to fix this...

[acme@quaco perf]$ m
make: Entering directory '/home/acme/git/perf/tools/perf'

  BUILD:   Doing 'make -j8' parallel build
  INSTALL  GTK UI
  INSTALL  trace_plugins
  CC       /tmp/build/perf/util/session.o

util/session.c: In function ‘perf_session__process_events’:
util/session.c:1936:7: error: ‘skip’ may be used uninitialized in this function [-Werror=maybe-uninitialized]
err = skip;
~~~~^~~~~~
util/session.c:1874:6: note: ‘skip’ was declared here

  s64 skip;
      ^~~~

cc1: all warnings being treated as errors
mv: cannot stat '/tmp/build/perf/util/.session.o.tmp': No such file or directory make[4]: *** [/home/acme/git/perf/tools/build/Makefile.build:96: /tmp/build/perf/util/session.o] Error 1 make[3]: *** [/home/acme/git/perf/tools/build/Makefile.build:139: util] Error 2 make[2]: *** [Makefile.perf:559: /tmp/build/perf/perf-in.o] Error 2
make[1]: *** [Makefile.perf:215: sub-make] Error 2
make: *** [Makefile:110: install-bin] Error 2
make: Leaving directory '/home/acme/git/perf/tools/perf'

Performance counter stats for 'make -k O=/tmp/build/perf -C tools/perf install-bin':

     4,913,757,758      cycles:u
     7,432,572,002      instructions:u            #    1.51  insn per cycle

       1.345541349 seconds time elapsed

       1.412713000 seconds user
       0.572540000 seconds sys

[acme@quaco perf]$

#3 lore raw

Em Fri, Apr 26, 2019 at 11:10:32AM -0300, Arnaldo Carvalho de Melo escreveu:

Quoted 30 lines

Em Fri, Apr 26, 2019 at 11:09:07AM -0300, Arnaldo Carvalho de Melo escreveu:

Quoted 4 lines

Em Tue, Apr 23, 2019 at 12:53:03PM +0200, Thomas Richter escreveu:

Quoted 3 lines

An -ENOMEM error is not reported in the GTK GUI.
Instead this error message pops up on the screen:

Quoted 8 lines
Quoted 6 lines

[root@m35lp76 perf]# ./perf report -i perf.data.error68-1

	Processing events... [974K/3M]
	Error:failed to process sample

	0xf4198 [0x8]: failed to process type: 68

Thanks, applied to perf/urgent.

Well, I tried to, now trying to fix this...

[acme@quaco perf]$ m
make: Entering directory '/home/acme/git/perf/tools/perf'

  BUILD:   Doing 'make -j8' parallel build
  INSTALL  GTK UI
  INSTALL  trace_plugins
  CC       /tmp/build/perf/util/session.o
util/session.c: In function ‘perf_session__process_events’:
util/session.c:1936:7: error: ‘skip’ may be used uninitialized in this function [-Werror=maybe-uninitialized]
   err = skip;
   ~~~~^~~~~~
util/session.c:1874:6: note: ‘skip’ was declared here
  s64 skip;
      ^~~~
Quoted 8 lines

cc1: all warnings being treated as errors
mv: cannot stat '/tmp/build/perf/util/.session.o.tmp': No such file or directory make[4]: *** [/home/acme/git/perf/tools/build/Makefile.build:96: /tmp/build/perf/util/session.o] Error 1 make[3]: *** [/home/acme/git/perf/tools/build/Makefile.build:139: util] Error 2 make[2]: *** [Makefile.perf:559: /tmp/build/perf/perf-in.o] Error 2
make[1]: *** [Makefile.perf:215: sub-make] Error 2
make: *** [Makefile:110: install-bin] Error 2
make: Leaving directory '/home/acme/git/perf/tools/perf'

So, here is your patch:

tools/perf/util/session.c +3 -3
index b17f1c9bc965..e89716175588 100644
@@ -1930,10 +1930,10 @@ reader__process_events(struct reader *rd, struct perf_session *session,
 
        if (size < sizeof(struct perf_event_header) ||
            (skip = rd->process(session, event, file_pos)) < 0) {
-               pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
+               pr_err("%#" PRIx64 " [%#x]: failed to process type: %d [%s]\n",
                       file_offset + head, event->header.size,
-                      event->header.type);
-               err = -EINVAL;
+                      event->header.type, strerror(-skip));
+               err = skip;
                goto out;
        }

[acme@quaco perf]$

What happens if (size < sizeof(struct perf_event_header)) is true? size will have an undefined value, so the right thing is to have this patch on top of yours, so that err get, as before, set to -EINVAL when the size is less than the perf_event_header sizeof:

tools/perf/util/session.c +2 -0
index e89716175588..bad5f87ae001 100644
@@ -1928,6 +1928,8 @@ reader__process_events(struct reader *rd, struct perf_session *session,
 
 	size = event->header.size;
 
+	skip = -EINVAL;
+
 	if (size < sizeof(struct perf_event_header) ||
 	    (skip = rd->process(session, event, file_pos)) < 0) {
 		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d [%s]\n",

---

With two Reviewed-by tags, I jumped to quickly at applying, please compile test next time guys ;-) :-)

- Arnaldo

#4 lore raw

On Fri, Apr 26, 2019 at 11:16:07AM -0300, Arnaldo Carvalho de Melo wrote:

SNIP

Quoted 38 lines
Quoted 7 lines

util/session.c: In function ‘perf_session__process_events’:
util/session.c:1936:7: error: ‘skip’ may be used uninitialized in this function [-Werror=maybe-uninitialized]

   err = skip;
   ~~~~^~~~~~
util/session.c:1874:6: note: ‘skip’ was declared here
  s64 skip;
      ^~~~
Quoted 8 lines

cc1: all warnings being treated as errors
mv: cannot stat '/tmp/build/perf/util/.session.o.tmp': No such file or directory make[4]: *** [/home/acme/git/perf/tools/build/Makefile.build:96: /tmp/build/perf/util/session.o] Error 1 make[3]: *** [/home/acme/git/perf/tools/build/Makefile.build:139: util] Error 2 make[2]: *** [Makefile.perf:559: /tmp/build/perf/perf-in.o] Error 2
make[1]: *** [Makefile.perf:215: sub-make] Error 2
make: *** [Makefile:110: install-bin] Error 2
make: Leaving directory '/home/acme/git/perf/tools/perf'

So, here is your patch:

tools/perf/util/session.c +3 -3
index b17f1c9bc965..e89716175588 100644
@@ -1930,10 +1930,10 @@ reader__process_events(struct reader *rd, struct perf_session *session,
 
        if (size < sizeof(struct perf_event_header) ||
            (skip = rd->process(session, event, file_pos)) < 0) {
-               pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
+               pr_err("%#" PRIx64 " [%#x]: failed to process type: %d [%s]\n",
                       file_offset + head, event->header.size,
-                      event->header.type);
-               err = -EINVAL;
+                      event->header.type, strerror(-skip));
+               err = skip;
                goto out;
        }

[acme@quaco perf]$

Quoted 4 lines

What happens if (size < sizeof(struct perf_event_header)) is true? size will have an undefined value, so the right thing is to have this patch on top of yours, so that err get, as before, set to -EINVAL when the size is less than the perf_event_header sizeof:

I'd think you need to squash your change with the original patch for the bisecting sake, right?

Quoted 17 lines
tools/perf/util/session.c +2 -1
index e89716175588..bad5f87ae001 100644
@@ -1928,6 +1928,8 @@ reader__process_events(struct reader *rd, struct perf_session *session,
 
 	size = event->header.size;
 
+	skip = -EINVAL;
+
 	if (size < sizeof(struct perf_event_header) ||
 	    (skip = rd->process(session, event, file_pos)) < 0) {
 		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d [%s]\n",
 
---
Quoted 2 lines

With two Reviewed-by tags, I jumped to quickly at applying, please compile test next time guys ;-) :-)

ugh.. need to slow down, this is happening too often now :-\

jirka

#5 lore raw

Em Fri, Apr 26, 2019 at 04:44:06PM +0200, Jiri Olsa escreveu:

Quoted 42 lines · Arnaldo Carvalho de Melo

SNIP

Quoted 38 lines
Quoted 7 lines

util/session.c: In function ‘perf_session__process_events’:
util/session.c:1936:7: error: ‘skip’ may be used uninitialized in this function [-Werror=maybe-uninitialized]

   err = skip;
   ~~~~^~~~~~
util/session.c:1874:6: note: ‘skip’ was declared here
  s64 skip;
      ^~~~
Quoted 8 lines

cc1: all warnings being treated as errors
mv: cannot stat '/tmp/build/perf/util/.session.o.tmp': No such file or directory make[4]: *** [/home/acme/git/perf/tools/build/Makefile.build:96: /tmp/build/perf/util/session.o] Error 1 make[3]: *** [/home/acme/git/perf/tools/build/Makefile.build:139: util] Error 2 make[2]: *** [Makefile.perf:559: /tmp/build/perf/perf-in.o] Error 2
make[1]: *** [Makefile.perf:215: sub-make] Error 2
make: *** [Makefile:110: install-bin] Error 2
make: Leaving directory '/home/acme/git/perf/tools/perf'

So, here is your patch:

tools/perf/util/session.c +3 -3
index b17f1c9bc965..e89716175588 100644
@@ -1930,10 +1930,10 @@ reader__process_events(struct reader *rd, struct perf_session *session,
 
        if (size < sizeof(struct perf_event_header) ||
            (skip = rd->process(session, event, file_pos)) < 0) {
-               pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
+               pr_err("%#" PRIx64 " [%#x]: failed to process type: %d [%s]\n",
                       file_offset + head, event->header.size,
-                      event->header.type);
-               err = -EINVAL;
+                      event->header.type, strerror(-skip));
+               err = skip;
                goto out;
        }

[acme@quaco perf]$

Quoted 7 lines
Quoted 4 lines

What happens if (size < sizeof(struct perf_event_header)) is true? size will have an undefined value, so the right thing is to have this patch on top of yours, so that err get, as before, set to -EINVAL when the size is less than the perf_event_header sizeof:

I'd think you need to squash your change with the original patch for the bisecting sake, right?

Yes, that is what I did.

Quoted 11 lines
Quoted 11 lines

+++ b/tools/perf/util/session.c

tools/perf/util/session.c +2 -0
@@ -1928,6 +1928,8 @@ reader__process_events(struct reader *rd, struct perf_session *session,
 
 	size = event->header.size;
 
+	skip = -EINVAL;
+
 	if (size < sizeof(struct perf_event_header) ||
 	    (skip = rd->process(session, event, file_pos)) < 0) {
 		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d [%s]\n",
Quoted 6 lines
Quoted 4 lines

---

With two Reviewed-by tags, I jumped to quickly at applying, please compile test next time guys ;-) :-)

ugh.. need to slow down, this is happening too often now :-\

Right, I'll test build everything, and I do like reviewers, who don't? Its just that when I see reviewed-by tags I end up relaxing a bit :-)

- Arnaldo

merge bot
#6 lore raw

[tip:perf/urgent] perf report: Report OOM in status line in the GTK UI

In reply to Thomas Richter
perf report: Report OOM in status line in the GTK UI
Commit-ID:  167e418fa0871c083e2c74508d73012abb01e6f7
Gitweb:     https://git.kernel.org/tip/167e418fa0871c083e2c74508d73012abb01e6f7
Author:     Thomas Richter <[email protected]>
AuthorDate: Tue, 23 Apr 2019 12:53:03 +0200
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Thu, 2 May 2019 16:00:20 -0400

perf report: Report OOM in status line in the GTK UI

An -ENOMEM error is not reported in the GTK GUI. Instead this error message pops up on the screen:

[root@m35lp76 perf]# ./perf report -i perf.data.error68-1

	Processing events... [974K/3M]
	Error:failed to process sample

	0xf4198 [0x8]: failed to process type: 68

However when I use the same perf.data file with --stdio it works:

[root@m35lp76 perf]# ./perf  report -i perf.data.error68-1 --stdio \
		| head -12

# Total Lost Samples: 0
#
# Samples: 76K of event 'cycles'
# Event count (approx.): 99056160000
#

  # Overhead  Command          Shared Object      Symbol
  # ........  ...............  .................  .........
  #
     8.81%  find             [kernel.kallsyms]  [k] ftrace_likely_update
     8.74%  swapper          [kernel.kallsyms]  [k] ftrace_likely_update
     8.34%  sshd             [kernel.kallsyms]  [k] ftrace_likely_update
     2.19%  kworker/u512:1-  [kernel.kallsyms]  [k] ftrace_likely_update

The sample precentage is a bit low.....

The GUI always fails in the FINISHED_ROUND event (68) and does not indicate the reason why.

When happened is the following. Perf report calls a lot of functions and down deep when a FINISHED_ROUND event is processed, these functions are called:

perf_session__process_event()
+ perf_session__process_user_event()
+ process_finished_round()
+ ordered_events__flush()
+ __ordered_events__flush()
+ do_flush()
+ ordered_events__deliver_event()
+ perf_session__deliver_event()
+ machine__deliver_event()
+ perf_evlist__deliver_event()
+ process_sample_event()
+ hist_entry_iter_add() --> only called in GUI case!!!
+ hist_iter__report__callback()
+ symbol__inc_addr_sample()

Now this functions runs out of memory and returns -ENOMEM. This is reported all the way up until function

perf_session__process_event() returns to its caller, where -ENOMEM is changed to -EINVAL and processing stops:

 if ((skip = perf_session__process_event(session, event, head)) < 0) {
      pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
	     head, event->header.size, event->header.type);
      err = -EINVAL;
      goto out_err;

}

This occurred in the FINISHED_ROUND event when it has to process some 10000 entries and ran out of memory.

This patch indicates the root cause and displays it in the status line of ther perf report GUI.

Output before (on GUI status line):

0xf4198 [0x8]: failed to process type: 68

Output after:

0xf4198 [0x8]: failed to process type: 68 [not enough memory]

Committer notes:

the 'skip' variable needs to be initialized to -EINVAL, so that when the size is less than sizeof(struct perf_event_attr) we avoid this valid compiler warning:

util/session.c: In function ‘perf_session__process_events’:
util/session.c:1936:7: error: ‘skip’ may be used uninitialized in this function [-Werror=maybe-uninitialized]

     err = skip;
     ~~~~^~~~~~
  util/session.c:1874:6: note: ‘skip’ was declared here
    s64 skip;
        ^~~~

cc1: all warnings being treated as errors

Signed-off-by Thomas Richter <[email protected]>
Reviewed-by Hendrik Brueckner <[email protected]>
Reviewed-by Jiri Olsa <[email protected]>
Cc Heiko Carstens <[email protected]>
Cc Martin Schwidefsky <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Arnaldo Carvalho de Melo <[email protected]>
---
 tools/perf/util/session.c | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)
tools/perf/util/session.c +5 -3
index b17f1c9bc965..bad5f87ae001 100644
@@ -1928,12 +1928,14 @@ more:
 
 	size = event->header.size;
 
+	skip = -EINVAL;
+
 	if (size < sizeof(struct perf_event_header) ||
 	    (skip = rd->process(session, event, file_pos)) < 0) {
-		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
+		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d [%s]\n",
 		       file_offset + head, event->header.size,
-		       event->header.type);
-		err = -EINVAL;
+		       event->header.type, strerror(-skip));
+		err = skip;
 		goto out;
 	}