Re: Profiling sleep times?

[Peter Zijlstra <peterz@infradead.org>]

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:

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.