Re: [PATCH 2/2] tracing, sched: Add a new tracepoint for sleeptime

[Andrey Vagin <avagin@openvz.org>]

>
> +#ifdef CREATE_TRACE_POINTS
> +static inline u64 trace_get_sleeptime(struct task_struct *tsk)
> +{
> +#ifdef CONFIG_SCHEDSTATS
> +	u64 block, sleep;
> +
> +	block = tsk->se.statistics.block_start;
> +	sleep = tsk->se.statistics.sleep_start;
Arun, probably you have missed one of my comments.
block_start and sleep_start should be zeroized here.

tsk->se.statistics.block_start = 0;
tsk->se.statistics.sleep_start = 0;

The following program provokes this problem:

#include<unistd.h>
#include<time.h>
#include<sys/select.h>

int main()
{
           struct timespec ts1;
           struct timeval tv1;
           int i;
           long s;


           for (i = 0; i<  1000; i++) {
                   ts1.tv_sec = 0;
                   ts1.tv_nsec = 1000000;
                   nanosleep(&ts1, NULL);

                   tv1.tv_sec = 0;
                   tv1.tv_usec = 4000;
                   select(0, NULL, NULL, NULL,&tv1);
                   if (i % 100 == 0) {
                         s = time(NULL);
                         while (time(NULL) - s < 4);
                   }
           }
         return 1;
}

> +
> +	return block ? block : sleep ? sleep : 0;
> +#else
> +	return 0;
> +#endif
> +}
> +#endif
> +
> +/*
> + * Tracepoint for accounting sleeptime (time the task is sleeping
> + * or waiting for I/O).
> + */
> +TRACE_EVENT(sched_stat_sleeptime,
> +
> +	TP_PROTO(struct task_struct *tsk, u64 now),
> +
> +	TP_ARGS(tsk, now),
> +
> +	TP_STRUCT__entry(
> +		__array( char,	comm,	TASK_COMM_LEN	)
> +		__field( pid_t,	pid			)
> +		__field( u64,	sleeptime		)
> +	),
> +
> +	TP_fast_assign(
> +		memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN);
> +		__entry->pid		= tsk->pid;
> +		__entry->sleeptime = trace_get_sleeptime(tsk);
> +		__entry->sleeptime = __entry->sleeptime ?
> +				now - __entry->sleeptime : 0;
> +	)
> +	TP_perf_assign(
> +		__perf_count(__entry->sleeptime);
> +	),
> +
> +	TP_printk("comm=%s pid=%d sleeptime=%Lu [ns]",
> +			__entry->comm, __entry->pid,
> +			(unsigned long long)__entry->sleeptime)
> +);
> +
>   /*
>    * Tracepoint for showing priority inheritance modifying a tasks
>    * priority.
> diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> index ca8fd44..172e6ee 100644
> --- a/kernel/sched/core.c
> +++ b/kernel/sched/core.c
> @@ -1899,6 +1899,7 @@ static void finish_task_switch(struct rq *rq, struct task_struct *prev)
>   	local_irq_enable();
>   #endif /* __ARCH_WANT_INTERRUPTS_ON_CTXSW */
>   	finish_lock_switch(rq, prev);
> +	trace_sched_stat_sleeptime(current, rq->clock);
>
>   	fire_sched_in_preempt_notifiers(current);
>   	if (mm)