linux-kernel - Re: [Query/tick] Are we enqueing 'tick-sched' hrtimers in past ?

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:	Thu, 3 Jul 2014 09:59:22 -0400
From:	Steven Rostedt <rostedt@...dmis.org>
To:	Viresh Kumar <viresh.kumar@...aro.org>
Cc:	Thomas Gleixner <tglx@...utronix.de>,
	Frédéric Weisbecker <fweisbec@...il.com>,
	Preeti U Murthy <preeti@...ux.vnet.ibm.com>,
	Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
	Lists linaro-kernel <linaro-kernel@...ts.linaro.org>,
	Linaro Networking <linaro-networking@...aro.org>,
	Kevin Hilman <khilman@...aro.org>
Subject: Re: [Query/tick] Are we enqueing 'tick-sched' hrtimers in past ?

On Thu, 3 Jul 2014 18:59:31 +0530
Viresh Kumar <viresh.kumar@...aro.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
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/