perf/report: [RFC] Handling OOM in perf report

PATCH In review Thomas Richter 2 participants 4 messages Apr 1, 2019 – Apr 15, 2019 perf events

Share & tools

Thomas Richter

author

2019-04-01 14:20 UTC #0 lore raw

PATCH 1/1 perf/report: [RFC] Handling OOM in perf report

A very strange -ENOMEM error which only when output
is displayed using the GTK GUI (I have copied the text from the GUI):

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

It always fails in the FINISHED_ROUND event, event number 68.

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 occured in the FINISHED_ROUND event when it has to process some 10000 entries and ran out of memory.

I understand that my perf.data file might just be too big, but I would like to see some error message indicating OOM error instead of processing failure of a unrelated event.

However this patch just does what the pr_debug() statement indicates, the event is skipped and processing continues.
But at least the root cause is indicated and also shows up in the GUI.

Signed-off-by Thomas Richter <[email protected]>

---
 tools/perf/builtin-report.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

tools/perf/builtin-report.c +6 -1

index 4054eb1f98ac..7a27b815f7a8 100644
@@ -283,8 +283,13 @@ static int process_sample_event(struct perf_tool *tool,
 		al.map->dso->hit = 1;
 
 	ret = hist_entry_iter__add(&iter, &al, rep->max_stack, rep);
-	if (ret < 0)
+	if (ret < 0) {
 		pr_debug("problem adding hist entry, skipping event\n");
+		if (ret == -ENOMEM) {
+			pr_err("Running out of memory\n");
+			ret = 0;
+		}
+	}
 out_put:
 	addr_location__put(&al);
 	return ret;

Signature · 1 line

2.16.4

Jiri Olsa

2019-04-09 10:42 UTC #1 lore raw

On Mon, Apr 01, 2019 at 04:20:00PM +0200, Thomas Richter wrote:

SNIP

Quoted 8 lines

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;

Quoted 8 lines

}
This occured in the FINISHED_ROUND event when it has to process some 10000 entries and ran out of memory.
I understand that my perf.data file might just be too big, but I would like to see some error message indicating OOM error instead of processing failure of a unrelated event.

you can limit the size of the report queue via ~/.perfconfig file:

[report]
queue-size=1M

above should use only 1M for the queue management data the data for sample still get allocated thought.. but it could help

Quoted 17 lines

However this patch just does what the pr_debug() statement indicates, the event is skipped and processing continues.
But at least the root cause is indicated and also shows up in the GUI.
Signed-off-by Thomas Richter <[email protected]>
---
 tools/perf/builtin-report.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)
tools/perf/builtin-report.c +0 -0
index 4054eb1f98ac..7a27b815f7a8 100644
@@ -283,8 +283,13 @@ static int process_sample_event(struct perf_tool *tool,
 		al.map->dso->hit = 1;

tools/perf/builtin-report.c static int process_sample_event(struct perf_tool *tool, · line 292

Quoted 10 lines

tools/perf/builtin-report.c +6 -1

 
 	ret = hist_entry_iter__add(&iter, &al, rep->max_stack, rep);
-	if (ret < 0)
+	if (ret < 0) {
 		pr_debug("problem adding hist entry, skipping event\n");
+		if (ret == -ENOMEM) {
+			pr_err("Running out of memory\n");
+			ret = 0;
+		}
+	}

I think we can propagate the error completely (like below), and even warn about ENOMEM specificaly

but I think we should bail out in case of ENOMEM, because the data are incomplete and misleading

jirka

---

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

index b17f1c9bc965..eea247a26ad8 100644
@@ -1933,7 +1933,7 @@ reader__process_events(struct reader *rd, struct perf_session *session,
 		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
 		       file_offset + head, event->header.size,
 		       event->header.type);
-		err = -EINVAL;
+		err = skip;
 		goto out;
 	}

Thomas-Mich Richter

author

2019-04-10 07:17 UTC #2 lore raw

Quoted 74 lines · Jiri Olsa

On Mon, Apr 01, 2019 at 04:20:00PM +0200, Thomas Richter wrote:
SNIP
Quoted 8 lines
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;
Quoted 8 lines
}
This occured in the FINISHED_ROUND event when it has to process some 10000 entries and ran out of memory.
I understand that my perf.data file might just be too big, but I would like to see some error message indicating OOM error instead of processing failure of a unrelated event.
you can limit the size of the report queue via ~/.perfconfig file:
[report]
queue-size=1M
above should use only 1M for the queue management data the data for sample still get allocated thought.. but it could help
Quoted 17 lines
However this patch just does what the pr_debug() statement indicates, the event is skipped and processing continues.
But at least the root cause is indicated and also shows up in the GUI.
Signed-off-by Thomas Richter <[email protected]>
---
 tools/perf/builtin-report.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)
tools/perf/builtin-report.c +0 -0
index 4054eb1f98ac..7a27b815f7a8 100644
@@ -283,8 +283,13 @@ static int process_sample_event(struct perf_tool *tool,
 		al.map->dso->hit = 1;
tools/perf/builtin-report.c static int process_sample_event(struct perf_tool *tool, · line 292
Quoted 10 lines
tools/perf/builtin-report.c +6 -1
 
 	ret = hist_entry_iter__add(&iter, &al, rep->max_stack, rep);
-	if (ret < 0)
+	if (ret < 0) {
 		pr_debug("problem adding hist entry, skipping event\n");
+		if (ret == -ENOMEM) {
+			pr_err("Running out of memory\n");
+			ret = 0;
+		}
+	}
I think we can propagate the error completely (like below), and even warn about ENOMEM specificaly
but I think we should bail out in case of ENOMEM, because the data are incomplete and misleading
jirka
---
tools/perf/util/session.c +0 -0
index b17f1c9bc965..eea247a26ad8 100644

tools/perf/util/session.c reader__process_events(struct reader *rd, struct perf_session *session, · line 1939

Quoted 8 lines

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

@@ -1933,7 +1933,7 @@ reader__process_events(struct reader *rd, struct perf_session *session,
 		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
 		       file_offset + head, event->header.size,
 		       event->header.type);
-		err = -EINVAL;
+		err = skip;
 		goto out;
 	}

Above patch does not help, you simply return -ENOMEM instead of -EINVAL and processing stops with no indication that perf ran out of memory. Bailing out in this case is ok.

I am fine with your patch, as long as it gives a reason why processing stopped. In the GUI it shows on the bottom line the reason:

0xf4198 [0x8]: failed to process type: 68 [Cannot allocate memory]

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;
        }

[root@m35lp76 perf]#

Signature · 5 lines

Thomas Richter, Dept 3252, IBM s390 Linux Development, Boeblingen, Germany
--
Vorsitzender des Aufsichtsrats: Matthias Hartmann
Geschäftsführung: Dirk Wittkopp
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294

Jiri Olsa

2019-04-15 08:28 UTC #3 lore raw

On Wed, Apr 10, 2019 at 09:17:30AM +0200, Thomas-Mich Richter wrote:

SNIP

Quoted 21 lines

Quoted 9 lines
---
tools/perf/util/session.c +0 -0
index b17f1c9bc965..eea247a26ad8 100644
tools/perf/util/session.c reader__process_events(struct reader *rd, struct perf_session *session, · line 1939
Quoted 8 lines
tools/perf/util/session.c +1 -1
@@ -1933,7 +1933,7 @@ reader__process_events(struct reader *rd, struct perf_session *session,
 		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
 		       file_offset + head, event->header.size,
 		       event->header.type);
-		err = -EINVAL;
+		err = skip;
 		goto out;
 	}
 
Above patch does not help, you simply return -ENOMEM instead of -EINVAL and processing stops with no indication that perf ran out of memory. Bailing out in this case is ok.

Quoted 4 lines

I am fine with your patch, as long as it gives a reason why processing stopped. In the GUI it shows on the bottom line the reason:
0xf4198 [0x8]: failed to process type: 68 [Cannot allocate memory]

looks good, please post the full patch

thanks,
jirka

Quoted 28 lines

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;
        }

[root@m35lp76 perf]#

Signature · 5 lines

Thomas Richter, Dept 3252, IBM s390 Linux Development, Boeblingen, Germany
--
Vorsitzender des Aufsichtsrats: Matthias Hartmann
Geschäftsführung: Dirk Wittkopp
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294