Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1487754 > unrolled thread

[BUG] perf report --pid not reporting correctly

Back to article view | Back to linux.kernel

Contents

  [BUG] perf report --pid not reporting correctly Stephane Eranian <eranian@google.com> - 2016-09-21 03:40 +0200
    Re: [BUG] perf report --pid not reporting correctly Arnaldo Carvalho de Melo <acme@redhat.com> - 2016-09-21 17:40 +0200
      Re: [BUG] perf report --pid not reporting correctly Jiri Olsa <jolsa@redhat.com> - 2016-09-21 18:40 +0200
        Re: [BUG] perf report --pid not reporting correctly Stephane Eranian <eranian@google.com> - 2016-09-21 22:20 +0200
          Re: [BUG] perf report --pid not reporting correctly Namhyung Kim <namhyung@kernel.org> - 2016-09-22 03:40 +0200
            Re: [BUG] perf report --pid not reporting correctly Stephane Eranian <eranian@google.com> - 2016-09-22 04:30 +0200
              Re: [BUG] perf report --pid not reporting correctly Namhyung Kim <namhyung@kernel.org> - 2016-09-22 05:30 +0200
            Re: [BUG] perf report --pid not reporting correctly Jiri Olsa <jolsa@redhat.com> - 2016-09-22 15:40 +0200
              Re: [BUG] perf report --pid not reporting correctly Namhyung Kim <namhyung@kernel.org> - 2016-09-23 05:40 +0200
      Re: [BUG] perf report --pid not reporting correctly Namhyung Kim <namhyung@kernel.org> - 2016-09-22 02:20 +0200
        Re: [BUG] perf report --pid not reporting correctly Andi Kleen <ak@linux.intel.com> - 2016-09-22 17:00 +0200

#1487754 — [BUG] perf report --pid not reporting correctly

Hi Arnaldo,

I ran into an issue trying to use the --pid filtering option of perf report.

I do a system-wide collection and then I want to narrow down the
reporting to a specific process:

$ perf record -a -e cycles:pp sleep 10
$ perf report --sort cpu,comm --pid X

Where X is a process sampled during the run (easy to catch with perf report -D)
If you do it this way, it works, but if you do:

$ perf report --sort cpu --pid X

Then you get an empty output.

I suspect it has to do with the way hist entries are added to the
histogram and aggregated. If the first event for a sort criteria is
not coming from pid X, it will
still be added in the histogram. if pid X aggregates to the same
sample criteria, then you will lose the pid information. And then
later when you try to apply the filter,
it will mark the hist entry as FILTERED because it does not have a matching pid
and nothing will be printed.
I suspect you want to apply the filtering upfront for pid. It will
only add to the histograms matching samples. It changes the
percentages you will see. They will
only report the breakdown for the pid.

I have a quick hack to do upfront filtering which does something as
follows but I am not sure this is the correct way of doing this.

Let me know what you think.
Thanks.


diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
index 715467d..c24de6e 100644
--- a/tools/perf/util/hist.c
+++ b/tools/perf/util/hist.c
@@ -1020,6 +1020,9 @@ int hist_entry_iter__add(struct hist_entry_iter
*iter, struct addr_location *al,
 {
        int err, err2;

+       if (thread__is_filtered(al->thread))
+               return 0;
+
        err = sample__resolve_callchain(iter->sample,
&callchain_cursor, &iter->parent,
                                       iter->evsel, al, max_stack_depth);
        if (err)

[toc] | [next] | [standalone]

#1488194

Em Tue, Sep 20, 2016 at 06:29:59PM -0700, Stephane Eranian escreveu:
> Hi Arnaldo,
> 
> I ran into an issue trying to use the --pid filtering option of perf report.
> 
> I do a system-wide collection and then I want to narrow down the
> reporting to a specific process:
> 
> $ perf record -a -e cycles:pp sleep 10
> $ perf report --sort cpu,comm --pid X
> 
> Where X is a process sampled during the run (easy to catch with perf report -D)
> If you do it this way, it works, but if you do:
> 
> $ perf report --sort cpu --pid X
> 
> Then you get an empty output.
> 
> I suspect it has to do with the way hist entries are added to the
> histogram and aggregated. If the first event for a sort criteria is
> not coming from pid X, it will
> still be added in the histogram. if pid X aggregates to the same
> sample criteria, then you will lose the pid information. And then
> later when you try to apply the filter,
> it will mark the hist entry as FILTERED because it does not have a matching pid
> and nothing will be printed.
> I suspect you want to apply the filtering upfront for pid. It will
> only add to the histograms matching samples. It changes the
> percentages you will see. They will
> only report the breakdown for the pid.
> 
> I have a quick hack to do upfront filtering which does something as
> follows but I am not sure this is the correct way of doing this.
> 
> Let me know what you think.

From a first look I think this makes sense, i.e. we should do the first
round of filtering, one that trows away stuff, for things in the command
line, when creating the histogram entries.

Later, as we have now, we can apply further filters for non-collapsed
fields of hist_entry.

Jiri, Namhyung, are you ok with this?

- Arnaldo

> Thanks.
> 
> 
> diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
> index 715467d..c24de6e 100644
> --- a/tools/perf/util/hist.c
> +++ b/tools/perf/util/hist.c
> @@ -1020,6 +1020,9 @@ int hist_entry_iter__add(struct hist_entry_iter
> *iter, struct addr_location *al,
>  {
>         int err, err2;
> 
> +       if (thread__is_filtered(al->thread))
> +               return 0;
> +
>         err = sample__resolve_callchain(iter->sample,
> &callchain_cursor, &iter->parent,
>                                        iter->evsel, al, max_stack_depth);
>         if (err)

[toc] | [prev] | [next] | [standalone]

#1488263

On Wed, Sep 21, 2016 at 12:37:53PM -0300, Arnaldo Carvalho de Melo wrote:
> Em Tue, Sep 20, 2016 at 06:29:59PM -0700, Stephane Eranian escreveu:
> > Hi Arnaldo,
> > 
> > I ran into an issue trying to use the --pid filtering option of perf report.
> > 
> > I do a system-wide collection and then I want to narrow down the
> > reporting to a specific process:
> > 
> > $ perf record -a -e cycles:pp sleep 10
> > $ perf report --sort cpu,comm --pid X
> > 
> > Where X is a process sampled during the run (easy to catch with perf report -D)
> > If you do it this way, it works, but if you do:
> > 
> > $ perf report --sort cpu --pid X
> > 
> > Then you get an empty output.
> > 
> > I suspect it has to do with the way hist entries are added to the
> > histogram and aggregated. If the first event for a sort criteria is
> > not coming from pid X, it will
> > still be added in the histogram. if pid X aggregates to the same
> > sample criteria, then you will lose the pid information. And then
> > later when you try to apply the filter,
> > it will mark the hist entry as FILTERED because it does not have a matching pid
> > and nothing will be printed.
> > I suspect you want to apply the filtering upfront for pid. It will
> > only add to the histograms matching samples. It changes the
> > percentages you will see. They will
> > only report the breakdown for the pid.
> > 
> > I have a quick hack to do upfront filtering which does something as
> > follows but I am not sure this is the correct way of doing this.
> > 
> > Let me know what you think.
> 
> From a first look I think this makes sense, i.e. we should do the first
> round of filtering, one that trows away stuff, for things in the command
> line, when creating the histogram entries.
> 
> Later, as we have now, we can apply further filters for non-collapsed
> fields of hist_entry.
> 
> Jiri, Namhyung, are you ok with this?

Stephan is correct with analysis, but I think we need to add both non/filtered
entries in, because we provide that 'F' key for non/filtered counts switch in tui 

how about something like below

thanks,
jirka

---
diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
index b02992efb513..659e0357be68 100644
--- a/tools/perf/util/hist.c
+++ b/tools/perf/util/hist.c
@@ -536,6 +536,14 @@ static struct hist_entry *hists__findnew_entry(struct hists *hists,
 				map__put(he->ms.map);
 				he->ms.map = map__get(entry->ms.map);
 			}
+
+			/*
+			 * We have at least one entry in which is not
+			 * filtered, we want to display the entry.
+			 */
+			if (he->filtered && !entry->filtered)
+				he->filtered = 0;
+
 			goto out;
 		}
 

[toc] | [prev] | [next] | [standalone]

#1488375

On Wed, Sep 21, 2016 at 9:34 AM, Jiri Olsa <jolsa@redhat.com> wrote:
> On Wed, Sep 21, 2016 at 12:37:53PM -0300, Arnaldo Carvalho de Melo wrote:
>> Em Tue, Sep 20, 2016 at 06:29:59PM -0700, Stephane Eranian escreveu:
>> > Hi Arnaldo,
>> >
>> > I ran into an issue trying to use the --pid filtering option of perf report.
>> >
>> > I do a system-wide collection and then I want to narrow down the
>> > reporting to a specific process:
>> >
>> > $ perf record -a -e cycles:pp sleep 10
>> > $ perf report --sort cpu,comm --pid X
>> >
>> > Where X is a process sampled during the run (easy to catch with perf report -D)
>> > If you do it this way, it works, but if you do:
>> >
>> > $ perf report --sort cpu --pid X
>> >
>> > Then you get an empty output.
>> >
>> > I suspect it has to do with the way hist entries are added to the
>> > histogram and aggregated. If the first event for a sort criteria is
>> > not coming from pid X, it will
>> > still be added in the histogram. if pid X aggregates to the same
>> > sample criteria, then you will lose the pid information. And then
>> > later when you try to apply the filter,
>> > it will mark the hist entry as FILTERED because it does not have a matching pid
>> > and nothing will be printed.
>> > I suspect you want to apply the filtering upfront for pid. It will
>> > only add to the histograms matching samples. It changes the
>> > percentages you will see. They will
>> > only report the breakdown for the pid.
>> >
>> > I have a quick hack to do upfront filtering which does something as
>> > follows but I am not sure this is the correct way of doing this.
>> >
>> > Let me know what you think.
>>
>> From a first look I think this makes sense, i.e. we should do the first
>> round of filtering, one that trows away stuff, for things in the command
>> line, when creating the histogram entries.
>>
>> Later, as we have now, we can apply further filters for non-collapsed
>> fields of hist_entry.
>>
>> Jiri, Namhyung, are you ok with this?
>
> Stephan is correct with analysis, but I think we need to add both non/filtered
> entries in, because we provide that 'F' key for non/filtered counts switch in tui
>
> how about something like below
>
> thanks,
> jirka
>
> ---
> diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
> index b02992efb513..659e0357be68 100644
> --- a/tools/perf/util/hist.c
> +++ b/tools/perf/util/hist.c
> @@ -536,6 +536,14 @@ static struct hist_entry *hists__findnew_entry(struct hists *hists,
>                                 map__put(he->ms.map);
>                                 he->ms.map = map__get(entry->ms.map);
>                         }
> +
> +                       /*
> +                        * We have at least one entry in which is not
> +                        * filtered, we want to display the entry.
> +                        */
> +                       if (he->filtered && !entry->filtered)
> +                               he->filtered = 0;
> +
>                         goto out;
>                 }
>
Works for me. So with this approach the % shown with --pid still
represents % of total samples and not just for that pid.
I think this is okay as long as this is documented and understood by users.
Thanks.

[toc] | [prev] | [next] | [standalone]

#1488500

On Wed, Sep 21, 2016 at 01:18:52PM -0700, Stephane Eranian wrote:
> On Wed, Sep 21, 2016 at 9:34 AM, Jiri Olsa <jolsa@redhat.com> wrote:
> > On Wed, Sep 21, 2016 at 12:37:53PM -0300, Arnaldo Carvalho de Melo wrote:
> >> Em Tue, Sep 20, 2016 at 06:29:59PM -0700, Stephane Eranian escreveu:
> >> > Hi Arnaldo,
> >> >
> >> > I ran into an issue trying to use the --pid filtering option of perf report.
> >> >
> >> > I do a system-wide collection and then I want to narrow down the
> >> > reporting to a specific process:
> >> >
> >> > $ perf record -a -e cycles:pp sleep 10
> >> > $ perf report --sort cpu,comm --pid X
> >> >
> >> > Where X is a process sampled during the run (easy to catch with perf report -D)
> >> > If you do it this way, it works, but if you do:
> >> >
> >> > $ perf report --sort cpu --pid X
> >> >
> >> > Then you get an empty output.
> >> >
> >> > I suspect it has to do with the way hist entries are added to the
> >> > histogram and aggregated. If the first event for a sort criteria is
> >> > not coming from pid X, it will
> >> > still be added in the histogram. if pid X aggregates to the same
> >> > sample criteria, then you will lose the pid information. And then
> >> > later when you try to apply the filter,
> >> > it will mark the hist entry as FILTERED because it does not have a matching pid
> >> > and nothing will be printed.
> >> > I suspect you want to apply the filtering upfront for pid. It will
> >> > only add to the histograms matching samples. It changes the
> >> > percentages you will see. They will
> >> > only report the breakdown for the pid.
> >> >
> >> > I have a quick hack to do upfront filtering which does something as
> >> > follows but I am not sure this is the correct way of doing this.
> >> >
> >> > Let me know what you think.
> >>
> >> From a first look I think this makes sense, i.e. we should do the first
> >> round of filtering, one that trows away stuff, for things in the command
> >> line, when creating the histogram entries.
> >>
> >> Later, as we have now, we can apply further filters for non-collapsed
> >> fields of hist_entry.
> >>
> >> Jiri, Namhyung, are you ok with this?
> >
> > Stephan is correct with analysis, but I think we need to add both non/filtered
> > entries in, because we provide that 'F' key for non/filtered counts switch in tui
> >
> > how about something like below
> >
> > thanks,
> > jirka
> >
> > ---
> > diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
> > index b02992efb513..659e0357be68 100644
> > --- a/tools/perf/util/hist.c
> > +++ b/tools/perf/util/hist.c
> > @@ -536,6 +536,14 @@ static struct hist_entry *hists__findnew_entry(struct hists *hists,
> >                                 map__put(he->ms.map);
> >                                 he->ms.map = map__get(entry->ms.map);
> >                         }
> > +
> > +                       /*
> > +                        * We have at least one entry in which is not
> > +                        * filtered, we want to display the entry.
> > +                        */
> > +                       if (he->filtered && !entry->filtered)
> > +                               he->filtered = 0;
> > +
> >                         goto out;
> >                 }
> >
> Works for me. So with this approach the % shown with --pid still
> represents % of total samples and not just for that pid.
> I think this is okay as long as this is documented and understood by users.
> Thanks.

I think we should show correct value depending on the --percentage
option.   I wrote a patch to implement it by addding a
total_early_filtered_period stat to hists.  Following is the result:


  $ perf report -s cpu,comm --pid 0 --stdio
  #
  # Overhead  CPU  Command
  # ........  ...  .......
  #
      12.16%  000  swapper
       3.09%  001  swapper
       2.76%  002  swapper
       2.23%  003  swapper
       1.65%  007  swapper
       1.65%  008  swapper
       1.52%  009  swapper
       1.51%  006  swapper
       1.46%  004  swapper
       1.34%  005  swapper
       0.94%  010  swapper
       0.90%  011  swapper
  
  $ perf report -s cpu --pid 0 --stdio
  #
  # Overhead  CPU
  # ........  ...
  #
      12.16%  000
       3.09%  001
       2.76%  002
       2.23%  003
       1.65%  007
       1.65%  008
       1.52%  009
       1.51%  006
       1.46%  004
       1.34%  005
       0.94%  010
       0.90%  011
  
  $ perf report -s cpu --pid 0 --stdio --percentage relative
  #
  # Overhead  CPU
  # ........  ...
  #
      38.95%  000
       9.92%  001
       8.84%  002
       7.16%  003
       5.30%  007
       5.28%  008
       4.87%  009
       4.83%  006
       4.66%  004
       4.30%  005
       3.00%  010
       2.89%  011
  
  
  Note that the --hierarchy option provides groups rather than filtering
  but shows similar result..
  
  $ perf report -s pid,cpu --stdio --hierarchy
  #
  #    Overhead  Pid:Command / CPU
  # ...........  .......................
  #
      31.21%     0:swapper        
         12.16%     000
          3.09%     001
          2.76%     002
          2.23%     003
          1.65%     007
          1.65%     008
          1.52%     009
          1.51%     006
          1.46%     004
          1.34%     005
          0.94%     010
          0.90%     011
      19.15%     8618:getmail        
         ...





-----------------------8<-------------------------------
diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
index 8d363d5e65a2..42b1bfd29ef8 100644
--- a/tools/perf/util/event.h
+++ b/tools/perf/util/event.h
@@ -262,6 +262,7 @@ enum auxtrace_error_type {
  */
 struct events_stats {
 	u64 total_period;
+	u64 total_early_filtered_period;
 	u64 total_non_filtered_period;
 	u64 total_lost;
 	u64 total_lost_samples;
diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
index 37a08f20730a..c7045411cce2 100644
--- a/tools/perf/util/hist.c
+++ b/tools/perf/util/hist.c
@@ -1017,12 +1017,21 @@ int hist_entry_iter__add(struct hist_entry_iter *iter, struct addr_location *al,
 			 int max_stack_depth, void *arg)
 {
 	int err, err2;
+	struct hists *hists = evsel__hists(iter->evsel);
 
 	err = sample__resolve_callchain(iter->sample, &callchain_cursor, &iter->parent,
 					iter->evsel, al, max_stack_depth);
 	if (err)
 		return err;
 
+	if (symbol__parent_filter(iter->parent))
+		al->filtered |= symbol__parent_filter(iter->parent);
+
+	if (al->filtered) {
+		hists->stats.total_early_filtered_period += iter->sample->period;
+		return 0;
+	}
+
 	iter->max_stack = max_stack_depth;
 
 	err = iter->ops->prepare_entry(iter, al);
@@ -1503,7 +1512,7 @@ static void hists__reset_filter_stats(struct hists *hists)
 void hists__reset_stats(struct hists *hists)
 {
 	hists->nr_entries = 0;
-	hists->stats.total_period = 0;
+	hists->stats.total_period = hists->stats.total_early_filtered_period;
 
 	hists__reset_filter_stats(hists);
 }
@@ -1530,7 +1539,7 @@ static void hierarchy_recalc_total_periods(struct hists *hists)
 
 	node = rb_first(&hists->entries);
 
-	hists->stats.total_period = 0;
+	hists->stats.total_period = hists->stats.total_early_filtered_period;
 	hists->stats.total_non_filtered_period = 0;
 
 	/*

[toc] | [prev] | [next] | [standalone]

#1488505

On Wed, Sep 21, 2016 at 6:34 PM, Namhyung Kim <namhyung@kernel.org> wrote:
> On Wed, Sep 21, 2016 at 01:18:52PM -0700, Stephane Eranian wrote:
>> On Wed, Sep 21, 2016 at 9:34 AM, Jiri Olsa <jolsa@redhat.com> wrote:
>> > On Wed, Sep 21, 2016 at 12:37:53PM -0300, Arnaldo Carvalho de Melo wrote:
>> >> Em Tue, Sep 20, 2016 at 06:29:59PM -0700, Stephane Eranian escreveu:
>> >> > Hi Arnaldo,
>> >> >
>> >> > I ran into an issue trying to use the --pid filtering option of perf report.
>> >> >
>> >> > I do a system-wide collection and then I want to narrow down the
>> >> > reporting to a specific process:
>> >> >
>> >> > $ perf record -a -e cycles:pp sleep 10
>> >> > $ perf report --sort cpu,comm --pid X
>> >> >
>> >> > Where X is a process sampled during the run (easy to catch with perf report -D)
>> >> > If you do it this way, it works, but if you do:
>> >> >
>> >> > $ perf report --sort cpu --pid X
>> >> >
>> >> > Then you get an empty output.
>> >> >
>> >> > I suspect it has to do with the way hist entries are added to the
>> >> > histogram and aggregated. If the first event for a sort criteria is
>> >> > not coming from pid X, it will
>> >> > still be added in the histogram. if pid X aggregates to the same
>> >> > sample criteria, then you will lose the pid information. And then
>> >> > later when you try to apply the filter,
>> >> > it will mark the hist entry as FILTERED because it does not have a matching pid
>> >> > and nothing will be printed.
>> >> > I suspect you want to apply the filtering upfront for pid. It will
>> >> > only add to the histograms matching samples. It changes the
>> >> > percentages you will see. They will
>> >> > only report the breakdown for the pid.
>> >> >
>> >> > I have a quick hack to do upfront filtering which does something as
>> >> > follows but I am not sure this is the correct way of doing this.
>> >> >
>> >> > Let me know what you think.
>> >>
>> >> From a first look I think this makes sense, i.e. we should do the first
>> >> round of filtering, one that trows away stuff, for things in the command
>> >> line, when creating the histogram entries.
>> >>
>> >> Later, as we have now, we can apply further filters for non-collapsed
>> >> fields of hist_entry.
>> >>
>> >> Jiri, Namhyung, are you ok with this?
>> >
>> > Stephan is correct with analysis, but I think we need to add both non/filtered
>> > entries in, because we provide that 'F' key for non/filtered counts switch in tui
>> >
>> > how about something like below
>> >
>> > thanks,
>> > jirka
>> >
>> > ---
>> > diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
>> > index b02992efb513..659e0357be68 100644
>> > --- a/tools/perf/util/hist.c
>> > +++ b/tools/perf/util/hist.c
>> > @@ -536,6 +536,14 @@ static struct hist_entry *hists__findnew_entry(struct hists *hists,
>> >                                 map__put(he->ms.map);
>> >                                 he->ms.map = map__get(entry->ms.map);
>> >                         }
>> > +
>> > +                       /*
>> > +                        * We have at least one entry in which is not
>> > +                        * filtered, we want to display the entry.
>> > +                        */
>> > +                       if (he->filtered && !entry->filtered)
>> > +                               he->filtered = 0;
>> > +
>> >                         goto out;
>> >                 }
>> >
>> Works for me. So with this approach the % shown with --pid still
>> represents % of total samples and not just for that pid.
>> I think this is okay as long as this is documented and understood by users.
>> Thanks.
>
> I think we should show correct value depending on the --percentage
> option.   I wrote a patch to implement it by addding a
> total_early_filtered_period stat to hists.  Following is the result:
>
>
>   $ perf report -s cpu,comm --pid 0 --stdio
>   #
>   # Overhead  CPU  Command
>   # ........  ...  .......
>   #
>       12.16%  000  swapper
>        3.09%  001  swapper
>        2.76%  002  swapper
>        2.23%  003  swapper
>        1.65%  007  swapper
>        1.65%  008  swapper
>        1.52%  009  swapper
>        1.51%  006  swapper
>        1.46%  004  swapper
>        1.34%  005  swapper
>        0.94%  010  swapper
>        0.90%  011  swapper
>
So how do I interpret this?

Is this that 12.16% of all samples comes from  pid 0 (swapper) running on CPU0?

>   $ perf report -s cpu --pid 0 --stdio
>   #
>   # Overhead  CPU
>   # ........  ...
>   #
>       12.16%  000
>        3.09%  001
>        2.76%  002
>        2.23%  003
>        1.65%  007
>        1.65%  008
>        1.52%  009
>        1.51%  006
>        1.46%  004
>        1.34%  005
>        0.94%  010
>        0.90%  011
>
12.16% of all the samples collected come from pid 0 (swapper) running CPU0?


>   $ perf report -s cpu --pid 0 --stdio --percentage relative
>   #
>   # Overhead  CPU
>   # ........  ...
>   #
>       38.95%  000
>        9.92%  001
>        8.84%  002
>        7.16%  003
>        5.30%  007
>        5.28%  008
>        4.87%  009
>        4.83%  006
>        4.66%  004
>        4.30%  005
>        3.00%  010
>        2.89%  011
>
Ok, so now I am guessing 38.95% of the samples of pid 0 are on CPU0?

>
>   Note that the --hierarchy option provides groups rather than filtering
>   but shows similar result..
>
>   $ perf report -s pid,cpu --stdio --hierarchy
>   #
>   #    Overhead  Pid:Command / CPU
>   # ...........  .......................
>   #
>       31.21%     0:swapper
>          12.16%     000
>           3.09%     001
>           2.76%     002
>           2.23%     003
>           1.65%     007
>           1.65%     008
>           1.52%     009
>           1.51%     006
>           1.46%     004
>           1.34%     005
>           0.94%     010
>           0.90%     011
>       19.15%     8618:getmail
>          ...
>
31.21% of total samples come from pid 0 (swapper) and decompose
to 12.16% for CPU0, 3.09% for CPU1, ....

Is that right?

>
>
>
>
> -----------------------8<-------------------------------
> diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
> index 8d363d5e65a2..42b1bfd29ef8 100644
> --- a/tools/perf/util/event.h
> +++ b/tools/perf/util/event.h
> @@ -262,6 +262,7 @@ enum auxtrace_error_type {
>   */
>  struct events_stats {
>         u64 total_period;
> +       u64 total_early_filtered_period;
>         u64 total_non_filtered_period;
>         u64 total_lost;
>         u64 total_lost_samples;
> diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
> index 37a08f20730a..c7045411cce2 100644
> --- a/tools/perf/util/hist.c
> +++ b/tools/perf/util/hist.c
> @@ -1017,12 +1017,21 @@ int hist_entry_iter__add(struct hist_entry_iter *iter, struct addr_location *al,
>                          int max_stack_depth, void *arg)
>  {
>         int err, err2;
> +       struct hists *hists = evsel__hists(iter->evsel);
>
>         err = sample__resolve_callchain(iter->sample, &callchain_cursor, &iter->parent,
>                                         iter->evsel, al, max_stack_depth);
>         if (err)
>                 return err;
>
> +       if (symbol__parent_filter(iter->parent))
> +               al->filtered |= symbol__parent_filter(iter->parent);
> +
> +       if (al->filtered) {
> +               hists->stats.total_early_filtered_period += iter->sample->period;
> +               return 0;
> +       }
> +
>         iter->max_stack = max_stack_depth;
>
>         err = iter->ops->prepare_entry(iter, al);
> @@ -1503,7 +1512,7 @@ static void hists__reset_filter_stats(struct hists *hists)
>  void hists__reset_stats(struct hists *hists)
>  {
>         hists->nr_entries = 0;
> -       hists->stats.total_period = 0;
> +       hists->stats.total_period = hists->stats.total_early_filtered_period;
>
>         hists__reset_filter_stats(hists);
>  }
> @@ -1530,7 +1539,7 @@ static void hierarchy_recalc_total_periods(struct hists *hists)
>
>         node = rb_first(&hists->entries);
>
> -       hists->stats.total_period = 0;
> +       hists->stats.total_period = hists->stats.total_early_filtered_period;
>         hists->stats.total_non_filtered_period = 0;
>
>         /*

[toc] | [prev] | [next] | [standalone]

#1488518

On Wed, Sep 21, 2016 at 07:22:29PM -0700, Stephane Eranian wrote:
> On Wed, Sep 21, 2016 at 6:34 PM, Namhyung Kim <namhyung@kernel.org> wrote:
> > On Wed, Sep 21, 2016 at 01:18:52PM -0700, Stephane Eranian wrote:
> >> On Wed, Sep 21, 2016 at 9:34 AM, Jiri Olsa <jolsa@redhat.com> wrote:
> >> > On Wed, Sep 21, 2016 at 12:37:53PM -0300, Arnaldo Carvalho de Melo wrote:
> >> >> Em Tue, Sep 20, 2016 at 06:29:59PM -0700, Stephane Eranian escreveu:
> >> >> > Hi Arnaldo,
> >> >> >
> >> >> > I ran into an issue trying to use the --pid filtering option of perf report.
> >> >> >
> >> >> > I do a system-wide collection and then I want to narrow down the
> >> >> > reporting to a specific process:
> >> >> >
> >> >> > $ perf record -a -e cycles:pp sleep 10
> >> >> > $ perf report --sort cpu,comm --pid X
> >> >> >
> >> >> > Where X is a process sampled during the run (easy to catch with perf report -D)
> >> >> > If you do it this way, it works, but if you do:
> >> >> >
> >> >> > $ perf report --sort cpu --pid X
> >> >> >
> >> >> > Then you get an empty output.
> >> >> >
> >> >> > I suspect it has to do with the way hist entries are added to the
> >> >> > histogram and aggregated. If the first event for a sort criteria is
> >> >> > not coming from pid X, it will
> >> >> > still be added in the histogram. if pid X aggregates to the same
> >> >> > sample criteria, then you will lose the pid information. And then
> >> >> > later when you try to apply the filter,
> >> >> > it will mark the hist entry as FILTERED because it does not have a matching pid
> >> >> > and nothing will be printed.
> >> >> > I suspect you want to apply the filtering upfront for pid. It will
> >> >> > only add to the histograms matching samples. It changes the
> >> >> > percentages you will see. They will
> >> >> > only report the breakdown for the pid.
> >> >> >
> >> >> > I have a quick hack to do upfront filtering which does something as
> >> >> > follows but I am not sure this is the correct way of doing this.
> >> >> >
> >> >> > Let me know what you think.
> >> >>
> >> >> From a first look I think this makes sense, i.e. we should do the first
> >> >> round of filtering, one that trows away stuff, for things in the command
> >> >> line, when creating the histogram entries.
> >> >>
> >> >> Later, as we have now, we can apply further filters for non-collapsed
> >> >> fields of hist_entry.
> >> >>
> >> >> Jiri, Namhyung, are you ok with this?
> >> >
> >> > Stephan is correct with analysis, but I think we need to add both non/filtered
> >> > entries in, because we provide that 'F' key for non/filtered counts switch in tui
> >> >
> >> > how about something like below
> >> >
> >> > thanks,
> >> > jirka
> >> >
> >> > ---
> >> > diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
> >> > index b02992efb513..659e0357be68 100644
> >> > --- a/tools/perf/util/hist.c
> >> > +++ b/tools/perf/util/hist.c
> >> > @@ -536,6 +536,14 @@ static struct hist_entry *hists__findnew_entry(struct hists *hists,
> >> >                                 map__put(he->ms.map);
> >> >                                 he->ms.map = map__get(entry->ms.map);
> >> >                         }
> >> > +
> >> > +                       /*
> >> > +                        * We have at least one entry in which is not
> >> > +                        * filtered, we want to display the entry.
> >> > +                        */
> >> > +                       if (he->filtered && !entry->filtered)
> >> > +                               he->filtered = 0;
> >> > +
> >> >                         goto out;
> >> >                 }
> >> >
> >> Works for me. So with this approach the % shown with --pid still
> >> represents % of total samples and not just for that pid.
> >> I think this is okay as long as this is documented and understood by users.
> >> Thanks.
> >
> > I think we should show correct value depending on the --percentage
> > option.   I wrote a patch to implement it by addding a
> > total_early_filtered_period stat to hists.  Following is the result:
> >
> >
> >   $ perf report -s cpu,comm --pid 0 --stdio
> >   #
> >   # Overhead  CPU  Command
> >   # ........  ...  .......
> >   #
> >       12.16%  000  swapper
> >        3.09%  001  swapper
> >        2.76%  002  swapper
> >        2.23%  003  swapper
> >        1.65%  007  swapper
> >        1.65%  008  swapper
> >        1.52%  009  swapper
> >        1.51%  006  swapper
> >        1.46%  004  swapper
> >        1.34%  005  swapper
> >        0.94%  010  swapper
> >        0.90%  011  swapper
> >
> So how do I interpret this?
> 
> Is this that 12.16% of all samples comes from  pid 0 (swapper) running on CPU0?

Yep, it's same when no filter used.

  $ perf report -s cpu,comm | grep swapper
      12.16%  000  swapper        
       3.09%  001  swapper        
       2.76%  002  swapper        
       2.23%  003  swapper        
       1.65%  007  swapper        
       1.65%  008  swapper        
       1.52%  009  swapper        
       1.51%  006  swapper        
       1.46%  004  swapper        
       1.34%  005  swapper        
       0.94%  010  swapper        
       0.90%  011  swapper        

> 
> >   $ perf report -s cpu --pid 0 --stdio
> >   #
> >   # Overhead  CPU
> >   # ........  ...
> >   #
> >       12.16%  000
> >        3.09%  001
> >        2.76%  002
> >        2.23%  003
> >        1.65%  007
> >        1.65%  008
> >        1.52%  009
> >        1.51%  006
> >        1.46%  004
> >        1.34%  005
> >        0.94%  010
> >        0.90%  011
> >
> 12.16% of all the samples collected come from pid 0 (swapper) running CPU0?

Yes, I showed it just for verification, when --pid filter is used
without the comm sort key it works same as having the comm sort key.

> 
> 
> >   $ perf report -s cpu --pid 0 --stdio --percentage relative
> >   #
> >   # Overhead  CPU
> >   # ........  ...
> >   #
> >       38.95%  000
> >        9.92%  001
> >        8.84%  002
> >        7.16%  003
> >        5.30%  007
> >        5.28%  008
> >        4.87%  009
> >        4.83%  006
> >        4.66%  004
> >        4.30%  005
> >        3.00%  010
> >        2.89%  011
> >
> Ok, so now I am guessing 38.95% of the samples of pid 0 are on CPU0?

Yep, sum of the relative percentage is always 100% and it's all from
the pid 0 in this case.

> 
> >
> >   Note that the --hierarchy option provides groups rather than filtering
> >   but shows similar result..
> >
> >   $ perf report -s pid,cpu --stdio --hierarchy
> >   #
> >   #    Overhead  Pid:Command / CPU
> >   # ...........  .......................
> >   #
> >       31.21%     0:swapper
> >          12.16%     000
> >           3.09%     001
> >           2.76%     002
> >           2.23%     003
> >           1.65%     007
> >           1.65%     008
> >           1.52%     009
> >           1.51%     006
> >           1.46%     004
> >           1.34%     005
> >           0.94%     010
> >           0.90%     011
> >       19.15%     8618:getmail
> >          ...
> >
> 31.21% of total samples come from pid 0 (swapper) and decompose
> to 12.16% for CPU0, 3.09% for CPU1, ....
> 
> Is that right?

Exactly.

Thanks,
Namhyung


> 
> >
> >
> >
> >
> > -----------------------8<-------------------------------
> > diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
> > index 8d363d5e65a2..42b1bfd29ef8 100644
> > --- a/tools/perf/util/event.h
> > +++ b/tools/perf/util/event.h
> > @@ -262,6 +262,7 @@ enum auxtrace_error_type {
> >   */
> >  struct events_stats {
> >         u64 total_period;
> > +       u64 total_early_filtered_period;
> >         u64 total_non_filtered_period;
> >         u64 total_lost;
> >         u64 total_lost_samples;
> > diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
> > index 37a08f20730a..c7045411cce2 100644
> > --- a/tools/perf/util/hist.c
> > +++ b/tools/perf/util/hist.c
> > @@ -1017,12 +1017,21 @@ int hist_entry_iter__add(struct hist_entry_iter *iter, struct addr_location *al,
> >                          int max_stack_depth, void *arg)
> >  {
> >         int err, err2;
> > +       struct hists *hists = evsel__hists(iter->evsel);
> >
> >         err = sample__resolve_callchain(iter->sample, &callchain_cursor, &iter->parent,
> >                                         iter->evsel, al, max_stack_depth);
> >         if (err)
> >                 return err;
> >
> > +       if (symbol__parent_filter(iter->parent))
> > +               al->filtered |= symbol__parent_filter(iter->parent);
> > +
> > +       if (al->filtered) {
> > +               hists->stats.total_early_filtered_period += iter->sample->period;
> > +               return 0;
> > +       }
> > +
> >         iter->max_stack = max_stack_depth;
> >
> >         err = iter->ops->prepare_entry(iter, al);
> > @@ -1503,7 +1512,7 @@ static void hists__reset_filter_stats(struct hists *hists)
> >  void hists__reset_stats(struct hists *hists)
> >  {
> >         hists->nr_entries = 0;
> > -       hists->stats.total_period = 0;
> > +       hists->stats.total_period = hists->stats.total_early_filtered_period;
> >
> >         hists__reset_filter_stats(hists);
> >  }
> > @@ -1530,7 +1539,7 @@ static void hierarchy_recalc_total_periods(struct hists *hists)
> >
> >         node = rb_first(&hists->entries);
> >
> > -       hists->stats.total_period = 0;
> > +       hists->stats.total_period = hists->stats.total_early_filtered_period;
> >         hists->stats.total_non_filtered_period = 0;
> >
> >         /*

[toc] | [prev] | [next] | [standalone]

#1488878

On Thu, Sep 22, 2016 at 10:34:57AM +0900, Namhyung Kim wrote:

SNIP

>   $ perf report -s pid,cpu --stdio --hierarchy
>   #
>   #    Overhead  Pid:Command / CPU
>   # ...........  .......................
>   #
>       31.21%     0:swapper        
>          12.16%     000
>           3.09%     001
>           2.76%     002
>           2.23%     003
>           1.65%     007
>           1.65%     008
>           1.52%     009
>           1.51%     006
>           1.46%     004
>           1.34%     005
>           0.94%     010
>           0.90%     011
>       19.15%     8618:getmail        
>          ...
> 
> 
> 
> 
> 
> -----------------------8<-------------------------------
> diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
> index 8d363d5e65a2..42b1bfd29ef8 100644
> --- a/tools/perf/util/event.h
> +++ b/tools/perf/util/event.h
> @@ -262,6 +262,7 @@ enum auxtrace_error_type {
>   */
>  struct events_stats {
>  	u64 total_period;
> +	u64 total_early_filtered_period;

looks good, but why the word early? wouldn't total_filtered_period be just fine?

thanks,
jirka

>  	u64 total_non_filtered_period;
>  	u64 total_lost;
>  	u64 total_lost_samples;
> diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
> index 37a08f20730a..c7045411cce2 100644
> --- a/tools/perf/util/hist.c
> +++ b/tools/perf/util/hist.c
> @@ -1017,12 +1017,21 @@ int hist_entry_iter__add(struct hist_entry_iter *iter, struct addr_location *al,
>  			 int max_stack_depth, void *arg)
>  {
>  	int err, err2;
> +	struct hists *hists = evsel__hists(iter->evsel);
>  
>  	err = sample__resolve_callchain(iter->sample, &callchain_cursor, &iter->parent,
>  					iter->evsel, al, max_stack_depth);
>  	if (err)
>  		return err;
>  
> +	if (symbol__parent_filter(iter->parent))
> +		al->filtered |= symbol__parent_filter(iter->parent);
> +
> +	if (al->filtered) {
> +		hists->stats.total_early_filtered_period += iter->sample->period;

SNIP

[toc] | [prev] | [next] | [standalone]

#1489735

Hi Jiri,

On Thu, Sep 22, 2016 at 10:36 PM, Jiri Olsa <jolsa@redhat.com> wrote:
> On Thu, Sep 22, 2016 at 10:34:57AM +0900, Namhyung Kim wrote:
>
> SNIP
>
>>   $ perf report -s pid,cpu --stdio --hierarchy
>>   #
>>   #    Overhead  Pid:Command / CPU
>>   # ...........  .......................
>>   #
>>       31.21%     0:swapper
>>          12.16%     000
>>           3.09%     001
>>           2.76%     002
>>           2.23%     003
>>           1.65%     007
>>           1.65%     008
>>           1.52%     009
>>           1.51%     006
>>           1.46%     004
>>           1.34%     005
>>           0.94%     010
>>           0.90%     011
>>       19.15%     8618:getmail
>>          ...
>>
>>
>>
>>
>>
>> -----------------------8<-------------------------------
>> diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
>> index 8d363d5e65a2..42b1bfd29ef8 100644
>> --- a/tools/perf/util/event.h
>> +++ b/tools/perf/util/event.h
>> @@ -262,6 +262,7 @@ enum auxtrace_error_type {
>>   */
>>  struct events_stats {
>>       u64 total_period;
>> +     u64 total_early_filtered_period;
>
> looks good, but why the word early? wouldn't total_filtered_period be just fine?

I worried about it'd be confused to (wrongly) match to
"total_non_filtered_period".  One might think that the sum of filtered
+ non_filtered period should be the total period, but it's not.

I named it 'early' since it's filtered at sample level before creating
hist entry.  Later we can also filter on hist entries
(hists__filter_by_XXX) but it cannot affect the ones filtered earlier.

Thanks,
Namhyung


>
> thanks,
> jirka
>
>>       u64 total_non_filtered_period;
>>       u64 total_lost;
>>       u64 total_lost_samples;
>> diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
>> index 37a08f20730a..c7045411cce2 100644
>> --- a/tools/perf/util/hist.c
>> +++ b/tools/perf/util/hist.c
>> @@ -1017,12 +1017,21 @@ int hist_entry_iter__add(struct hist_entry_iter *iter, struct addr_location *al,
>>                        int max_stack_depth, void *arg)
>>  {
>>       int err, err2;
>> +     struct hists *hists = evsel__hists(iter->evsel);
>>
>>       err = sample__resolve_callchain(iter->sample, &callchain_cursor, &iter->parent,
>>                                       iter->evsel, al, max_stack_depth);
>>       if (err)
>>               return err;
>>
>> +     if (symbol__parent_filter(iter->parent))
>> +             al->filtered |= symbol__parent_filter(iter->parent);
>> +
>> +     if (al->filtered) {
>> +             hists->stats.total_early_filtered_period += iter->sample->period;
>
> SNIP
>



-- 
Thanks,
Namhyung

[toc] | [prev] | [next] | [standalone]

#1488477

Hi Arnaldo and Stephane,

On Thu, Sep 22, 2016 at 12:37 AM, Arnaldo Carvalho de Melo
<acme@redhat.com> wrote:
> Em Tue, Sep 20, 2016 at 06:29:59PM -0700, Stephane Eranian escreveu:
>> Hi Arnaldo,
>>
>> I ran into an issue trying to use the --pid filtering option of perf report.
>>
>> I do a system-wide collection and then I want to narrow down the
>> reporting to a specific process:
>>
>> $ perf record -a -e cycles:pp sleep 10
>> $ perf report --sort cpu,comm --pid X
>>
>> Where X is a process sampled during the run (easy to catch with perf report -D)
>> If you do it this way, it works, but if you do:
>>
>> $ perf report --sort cpu --pid X
>>
>> Then you get an empty output.
>>
>> I suspect it has to do with the way hist entries are added to the
>> histogram and aggregated. If the first event for a sort criteria is
>> not coming from pid X, it will
>> still be added in the histogram. if pid X aggregates to the same
>> sample criteria, then you will lose the pid information. And then
>> later when you try to apply the filter,
>> it will mark the hist entry as FILTERED because it does not have a matching pid
>> and nothing will be printed.
>> I suspect you want to apply the filtering upfront for pid. It will
>> only add to the histograms matching samples. It changes the
>> percentages you will see. They will
>> only report the breakdown for the pid.
>>
>> I have a quick hack to do upfront filtering which does something as
>> follows but I am not sure this is the correct way of doing this.
>>
>> Let me know what you think.
>
> From a first look I think this makes sense, i.e. we should do the first
> round of filtering, one that trows away stuff, for things in the command
> line, when creating the histogram entries.
>
> Later, as we have now, we can apply further filters for non-collapsed
> fields of hist_entry.
>
> Jiri, Namhyung, are you ok with this?

I'm not sure it'd be good to allow filtering by something that is not
in the sort key.  As Stephane said, current filtering behavior (by
cpu, socket, comm, dso, pid, tid and symbol) only works correctly if
it's in the sort key AFAIK.

And the calculation of total period is based on periods of each hist
entry at the output resort stage.  So it needs to keep the entries
separately to calculate it correctly.  We have --percentage option to
show absolute/relative value when a filter applied.

I think it's a choice.  If we decide to support it, the logic
calculating the total period should be changed to consider the
early-filtered entries somehow.

If not, I suggest to use --hierarchy mode with including the sort key
as the first one.  In this case.  It'll still show absolute
percentages of global total period, but you can see the desired result
easily IMHO.  Please try something like this:

  $ perf report --hierarchy -s pid,cpu

Thanks,
Namhyung

>
> - Arnaldo
>
>> Thanks.
>>
>>
>> diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
>> index 715467d..c24de6e 100644
>> --- a/tools/perf/util/hist.c
>> +++ b/tools/perf/util/hist.c
>> @@ -1020,6 +1020,9 @@ int hist_entry_iter__add(struct hist_entry_iter
>> *iter, struct addr_location *al,
>>  {
>>         int err, err2;
>>
>> +       if (thread__is_filtered(al->thread))
>> +               return 0;
>> +
>>         err = sample__resolve_callchain(iter->sample,
>> &callchain_cursor, &iter->parent,
>>                                        iter->evsel, al, max_stack_depth);
>>         if (err)

[toc] | [prev] | [next] | [standalone]

#1488957

> If not, I suggest to use --hierarchy mode with including the sort key
> as the first one.  In this case.  It'll still show absolute
> percentages of global total period, but you can see the desired result
> easily IMHO.  Please try something like this:
> 
>   $ perf report --hierarchy -s pid,cpu

It would be nice if there was a way from scripts with a command line option
to ask hierarchy mode to only show a subset of the tree (e.g. with some
kind of pattern)

Then options like --pid could be obsoleted, but it would be far more
flexible and scale for all the sort keys which are supported, without
adding a lot of new command line options.

-Andi

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web