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

[Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca>]

* Peter Zijlstra (peterz@infradead.org) wrote:
> 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?

This is also my thinking: why are __entry->now and __entry->wtom needed
at all? Ftrace should be providing an accurate clock source for the
event already.

If we _really_ need to match the trace clock with the system
gettimeofday value (or monotonic time), then we can instrument the timer
tick update routine. e.g., from LTTng (not yet ported to TRACE_EVENT):

kernel/timer.c:

void do_timer(unsigned long ticks)
{
        jiffies_64 += ticks;
        update_times(ticks);
        trace_timer_update_time(&xtime, &wall_to_monotonic);
}

ltt/probes/kernel-trace.c:

void probe_timer_update_time(struct timespec *_xtime,
                struct timespec *_wall_to_monotonic)
{
        trace_mark_tp(kernel, timer_update_time, timer_update_time,
                probe_timer_update_time,
                "jiffies #8u%llu xtime_sec %ld xtime_nsec %ld "
                "walltomonotonic_sec %ld walltomonotonic_nsec %ld",
                (unsigned long long)jiffies_64, _xtime->tv_sec, _xtime->tv_nsec,
                _wall_to_monotonic->tv_sec, _wall_to_monotonic->tv_nsec);
}

Mathieu

> 
> 

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68