linux-kernel - Re: [PATCH 0/2] perf: add sort by inclusive time functionality (v2)

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <4F58FF47.6090504@fb.com>
Date:	Thu, 8 Mar 2012 10:49:43 -0800
From:	Arun Sharma <asharma@...com>
To:	Frederic Weisbecker <fweisbec@...il.com>
CC:	Ingo Molnar <mingo@...e.hu>, <linux-kernel@...r.kernel.org>,
	Arnaldo Carvalho de Melo <acme@...hat.com>,
	Mike Galbraith <efault@....de>,
	Paul Mackerras <paulus@...ba.org>,
	Peter Zijlstra <peterz@...radead.org>,
	Stephane Eranian <eranian@...gle.com>,
	Namhyung Kim <namhyung.kim@....com>,
	Tom Zanussi <tzanussi@...il.com>,
	<linux-perf-users@...r.kernel.org>
Subject: Re: [PATCH 0/2] perf: add sort by inclusive time functionality (v2)

On 3/8/12 7:31 AM, Frederic Weisbecker wrote:
> On Thu, Mar 08, 2012 at 08:29:01AM +0100, Ingo Molnar wrote:
>>
>> * Arun Sharma<asharma@...com>  wrote:
>>
>>> This patch series refactors existing code a bit and adds sort by
>>> inclusive time (time spent in the function + callees).
>>>
>>> Sample command lines:
>>>
>>> # perf record -ag -- sleep 1
>>> # perf report -g graph,0.5,callee -n -s inclusive
>>
>> So I tried this out with:
>>
>>    $ taskset 1 perf record -g git gc
>>
>> and got entries above 100% (in the TUI):
>>
>>    $ perf report -g graph,0.5,callee -n -s inclusive
>>
>>   +  321.11%        5628  [.] 0x392b609269
>>   +  142.27%        3774  [.] create_delta
>>   +  78.86%        1248  [.] lookup_object
>>   +  40.54%        1348  [k] system_call_fastpath
>>   [...]
>>
>> Is that expected?

Yes - this is the "known bug" I noted in the cover letter

The second column (samples) is still accurate and could be used for the 
analysis.

>
> I think this happens because of this:
>
> -               hists->stats.total_period += h->period;
> +               if (!h->inclusive)
> +                       hists->stats.total_period += h->period;
>
> Which I'm not sure why it is needed btw.

Suppose the perf.data file had 1000 samples each with a period of 1e6 
events. total_period would be 1e9 without -s inclusive. Further, let's 
say the callchains had an average length of 10.

Now, after adding extra entries to the histogram, total_period would be 
1e10, which screws up the percentages. I'd like to differentiate between 
the hist entries that were in the event stream vs the ones added for 
inclusive time computation. Desired end result: the total_period remains 
unchanged at 1e9.

This is done via:

+		if (i != 0)
+			he->inclusive = 1;
+		else
+			orig_he = he;

Either (i != 0) is not a good enough test, or the inclusive bit is not 
getting propagated properly after histogram collapsing/resorting. This 
is the part I need to better understand and debug.

I tried to explain this problem in my first RFC message as well:

http://thread.gmane.org/gmane.linux.kernel/1262289

The problem Ingo is running into (and I've reproduced it on my end as 
well) is that total_period is smaller than without -s inclusive i.e. 
h->inclusive is 1 when it shouldn't be.

  -Arun
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/