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

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

[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

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

[Jiri Olsa]

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

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

[Thomas-Mich Richter]

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

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

[Jiri Olsa]

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
>