On Thu, 3 Jul 2014 18:59:31 +0530 Viresh Kumar viresh.kumar@linaro.org wrote:
Hi Thomas et al,
I was analyzing few traces with 'trace-cmd' and realized that timings weren't matching properly. For example consider this trace:
1 cat-1867 [000] d.h1 149.750891: hrtimer_expire_entry: hrtimer=ee7b3740 function=tick_sched_timer now=149740008694 2 cat-1867 [000] d.h1 149.750900: softirq_raise: vec=1 [action=TIMER] 3 cat-1867 [000] d.h1 149.750905: softirq_raise: vec=9 [action=RCU] 4 cat-1867 [000] d.h2 149.750910: sched_stat_runtime: comm=cat pid=1867 runtime=1463250 [ns] vruntime=4777557704 [ns] 5 cat-1867 [000] d.h1 149.750914: softirq_raise: vec=7 [action=SCHED] 6 cat-1867 [000] d.h1 149.750919: hrtimer_expire_exit: hrtimer=ee7b3740 7 cat-1867 [000] d.h2 149.750922: hrtimer_start: hrtimer=ee7b3740 function=tick_sched_timer expires=149745000000 softexpires=149745000000
Line 1: now=149.740008694 and trace-time: 149.750891. diff 10ms (consistently) Line 7: trace-time: 149.750922 and expires: 149.745000000, diff 5ms
So, either there is a mismatch of trace-times and required to be fixed? (@Steven)
Unless you changed clocks, the default timing of the trace is done by trace_clock_local() which basically just calls sched_clock(). Not much to be fixed there.
I would be interested in seeing another hrtimer_expire_entry to see if that is off by anything else other than 10ms. As that event is the only one shown to show what hrtimer thinks "now" is.
Also, I'm not really seeing what is wrong with the above. The expire_entry means the timer is being triggered and it raised the softirq. The hrtimer_start is a new setting to go off at 149.745. Since you noticed that the trace time stamp is 10ms ahead, that would state that the hrtimer would go off around trace timestamp 149.755.
The trace timer stamp uses a different clock than hrtimers does. Do not confuse them as the same clock. The best you can do is reference that "now" value to get the difference between the two and use that as a reference for what the time stamp of the trace should be when the hrtimer goes off again.
-- Steve