Re: Profiling sleep times?

["avagin@gmail.com" <avagin@gmail.com>]

On 10/07/2011 05:30 AM, Peter Zijlstra wrote:
> On Thu, 2011-10-06 at 14:56 -0700, Arun Sharma wrote:
>>             foo 15516 [006]  2291.187831: sched_stat_sleep: comm=foo
>> pid=15516 delay=4054262 [ns]
>>                foo 15516 [006]  2291.187832: sched_stat_sleep: comm=foo
>> pid=15516 delay=4054262 [ns]
>>                foo 15516 [006]  2291.188895: sched_stat_sleep: comm=foo
>> pid=15516 delay=1053565 [ns]
>>                foo 15516 [006]  2291.188896: sched_stat_sleep: comm=foo
>> pid=15516 delay=1053565 [ns]
>>                foo 15516 [006]  2291.188897: sched_stat_sleep: comm=foo
>> pid=15516 delay=1053565 [ns]
>
> But the idea of the __perf_count() thing:
__perf_count() doesn't work now and I have sent the patch, which fixes 
it. Could you commit it? It's subject:
[PATCH 1/4] perf: fix counter of ftrace events

but it's not all.
By default perf doesn't use SAMPLE_PERIOD, it bases on events count.
Each "trace" event is divided on some "perf" events in 
perf_swevent_overflow().

The number of perf events should be proportional __perf_count(), but the 
number of perf events restricted by sysctl_perf_event_sample_rate / HZ. 
In my case it's 100 events.

....
if (hwc->interrupts != MAX_INTERRUPTS) {
     hwc->interrupts++;
     if (HZ * hwc->interrupts > (u64)sysctl_perf_event_sample_rate) {
....


So Arun Sharma probably has perf.data which contains packages of events 
and each package contains 100 events irrespective of "delay".

>
> DECLARE_EVENT_CLASS(sched_stat_template,
>
> 	TP_PROTO(struct task_struct *tsk, u64 delay),
>
> 	TP_ARGS(tsk, delay),
>
> 	TP_STRUCT__entry(
> 		__array( char,	comm,	TASK_COMM_LEN	)
> 		__field( pid_t,	pid			)
> 		__field( u64,	delay			)
> 	),
>
> 	TP_fast_assign(
> 		memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN);
> 		__entry->pid	= tsk->pid;
> 		__entry->delay	= delay;
> 	)
> 	TP_perf_assign(
> 		__perf_count(delay);
> 	),
>
> 	TP_printk("comm=%s pid=%d delay=%Lu [ns]",
> 			__entry->comm, __entry->pid,
> 			(unsigned long long)__entry->delay)
> );
>
>
> is that the counter is incremented with the delay, so the event should
> get weighted right.
>
> So having to get the delay out of the raw tracepoint data shouldn't be
> needed.