* [PATCH] perf/report: [RFC] Handling OOM in perf report @ 2019-04-01 14:20 Thomas Richter 2019-04-09 10:42 ` Jiri Olsa 0 siblings, 1 reply; 4+ messages in thread From: Thomas Richter @ 2019-04-01 14:20 UTC (permalink / raw) To: linux-kernel, linux-perf-users, acme Cc: brueckner, schwidefsky, heiko.carstens, Thomas Richter 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 <tmricht@linux.ibm.com> --- tools/perf/builtin-report.c | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c index 4054eb1f98ac..7a27b815f7a8 100644 --- a/tools/perf/builtin-report.c +++ b/tools/perf/builtin-report.c @@ -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; -- 2.16.4 ^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: [PATCH] perf/report: [RFC] Handling OOM in perf report 2019-04-01 14:20 [PATCH] perf/report: [RFC] Handling OOM in perf report Thomas Richter @ 2019-04-09 10:42 ` Jiri Olsa 2019-04-10 7:17 ` Thomas-Mich Richter 0 siblings, 1 reply; 4+ messages in thread From: Jiri Olsa @ 2019-04-09 10:42 UTC (permalink / raw) To: Thomas Richter Cc: linux-kernel, linux-perf-users, acme, brueckner, schwidefsky, heiko.carstens On Mon, Apr 01, 2019 at 04:20:00PM +0200, Thomas Richter wrote: SNIP > 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. 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 > > 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 <tmricht@linux.ibm.com> > --- > tools/perf/builtin-report.c | 7 ++++++- > 1 file changed, 6 insertions(+), 1 deletion(-) > > diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c > index 4054eb1f98ac..7a27b815f7a8 100644 > --- a/tools/perf/builtin-report.c > +++ b/tools/perf/builtin-report.c > @@ -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; > + } > + } 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 --- diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c index b17f1c9bc965..eea247a26ad8 100644 --- a/tools/perf/util/session.c +++ b/tools/perf/util/session.c @@ -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; } ^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: [PATCH] perf/report: [RFC] Handling OOM in perf report 2019-04-09 10:42 ` Jiri Olsa @ 2019-04-10 7:17 ` Thomas-Mich Richter 2019-04-15 8:28 ` Jiri Olsa 0 siblings, 1 reply; 4+ messages in thread From: Thomas-Mich Richter @ 2019-04-10 7:17 UTC (permalink / raw) To: Jiri Olsa Cc: linux-kernel, linux-perf-users, acme, brueckner, schwidefsky, heiko.carstens On 4/9/19 12:42 PM, Jiri Olsa wrote: > On Mon, Apr 01, 2019 at 04:20:00PM +0200, Thomas Richter wrote: > > SNIP > >> 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. > > 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 > >> >> 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 <tmricht@linux.ibm.com> >> --- >> tools/perf/builtin-report.c | 7 ++++++- >> 1 file changed, 6 insertions(+), 1 deletion(-) >> >> diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c >> index 4054eb1f98ac..7a27b815f7a8 100644 >> --- a/tools/perf/builtin-report.c >> +++ b/tools/perf/builtin-report.c >> @@ -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; >> + } >> + } > > > 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 > > > --- > diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c > index b17f1c9bc965..eea247a26ad8 100644 > --- a/tools/perf/util/session.c > +++ b/tools/perf/util/session.c > @@ -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] diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c index b17f1c9bc965..e89716175588 100644 --- a/tools/perf/util/session.c +++ b/tools/perf/util/session.c @@ -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]# -- 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 ^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: [PATCH] perf/report: [RFC] Handling OOM in perf report 2019-04-10 7:17 ` Thomas-Mich Richter @ 2019-04-15 8:28 ` Jiri Olsa 0 siblings, 0 replies; 4+ messages in thread From: Jiri Olsa @ 2019-04-15 8:28 UTC (permalink / raw) To: Thomas-Mich Richter Cc: linux-kernel, linux-perf-users, acme, brueckner, schwidefsky, heiko.carstens On Wed, Apr 10, 2019 at 09:17:30AM +0200, Thomas-Mich Richter wrote: SNIP > > > > > > --- > > diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c > > index b17f1c9bc965..eea247a26ad8 100644 > > --- a/tools/perf/util/session.c > > +++ b/tools/perf/util/session.c > > @@ -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] looks good, please post the full patch thanks, jirka > > > diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c > index b17f1c9bc965..e89716175588 100644 > --- a/tools/perf/util/session.c > +++ b/tools/perf/util/session.c > @@ -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]# > -- > 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 > ^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2019-04-15 8:28 UTC | newest] Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2019-04-01 14:20 [PATCH] perf/report: [RFC] Handling OOM in perf report Thomas Richter 2019-04-09 10:42 ` Jiri Olsa 2019-04-10 7:17 ` Thomas-Mich Richter 2019-04-15 8:28 ` Jiri Olsa
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).