Re: [PATCH v3 3/4] ftrace: add tracepoint for hrtimer

[Peter Zijlstra <peterz@infradead.org>]

On Wed, 2009-07-22 at 17:36 +0800, Xiao Guangrong wrote:
> 
> Peter Zijlstra wrote:
> 
> > Ah, but you don't get those anyway, I'd argue the whole expire thing is
> > broken. The only expiry you get is the hardware interrupt firing.
> > Anything after that is a free-for-all.
> > 
> > Look at that loop in hrtimer_interrupt(), with your tracepoint, they'd
> > all expire at the same time, regardless of how long previous callback's
> > took to complete.
> > 
> > Also, the whole loop can be re-tried, updating 'now' expiring a whole
> > new set of timers without expiry event.
> > 
> 
> Yes, the expire time that got by _expire() is incorrect and thanks for
> your point out.
> 
> > The best you can get is a tracepoint when the hrtimer interrupt happens,
> > and the IRQ tracepoint already give you that.
> > 
> 
> I'm trying to fix it address your comment, but meet some problems,
> the time of ftrace output can't solve everything, because:
> 
> 1: the time unit of ftrace output is microsecond, but hrtimer's unit
>    is nanosecond, it's not exact for us
> 
> 2: the time of ftrace ouput is the time after system boot, but we need
>    xtime and wall_to_monotonic to calculate latency of hrtimer,
>    for example:
>    insmod-3821  [001]  3192.239335: hrtimer_start: timer=d08a1480  expires=1245162841000000000 ns
>    <idle>-0     [001]  3201.506127: hrtimer_expire: timer=d08a1480
>    
>   we expect the timer expire at 1245162841000000000 ns, this is base on
>   xtime, but we don't know the interval running that we are expect hrtimer
>   to run if we don't know the xtime at hrtimer_start or hrtimer_expire.
> 
> But it's hard for hrtime's TRACE_EVENT to get xtime and wall_to_monotonic
> since it's a fast patch, if we have to do this, the code maybe like below:
> 
> TRACE_EVENT(hrtimer_expire,
> 
> 	......
> 
> 	TP_STRUCT__entry(
> 		__field( void *,	timer	)
> 		__field( s64,		now	)
> 		__field( s64, 		offset	)
> 	),
> 
> 	TP_fast_assign(
> 		__entry->timer	= timer;
> 		__entry->now	= ktime_get().tv64;
> 		__entry->wtom 	= timespec_to_ktime(wall_to_monotonic).tv64;
> 	),
> 
> 	TP_printk("timer=%p now=%llu ns wtom=%llu", __entry->timer,
> 		 (unsigned long long)__entry->now, (unsigned long long)__entry->wtom)
> );
> 
> We need cooperate with trace_hrtimer_init() to get hrtimer's clockid.
> 
> That make trace_hrtimer_expire() slow.
> 
> Though the original patch get expire time not exactly, but It harm system's 
> performance very little.

OK, so what you want to measure is the time of the actual callback
happening (hrtimer_entry) vs that where you would have expected it to
happen (hrtimer_start + delay), right?

So what's wrong with printing the expected expiration time in the
hrtimer_start tracepoint in the cheap clock units?