lkml.org 
[lkml]   [2012]   [Oct]   [11]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: RCU NOHZ, tsc, and clock_gettime
On 10/11/2012 11:52 AM, Prarit Bhargava wrote:
> I've been tracking an odd bug that may involve the RCU NOHZ code and
> just want to know if you have any ideas on debugging and/or what might be
> wrong. Note the bug happens on *BOTH* upstream and the current RHEL6 tree.
> The data in this email is from running on RHEL6 because that's what I happen
> to be running ATM. The result, however, is _identical_ to that of linux.git
> latest.
>
> The attached program compares userspace TSC reads to the time returned from
> the REALTIME_CLOCK[1]. The test does the following
>
> read tsc1
> get REALTIME_CLOCK value
> read tsc2
>
> and then does a comparison between the tsc read and the REALTIME_CLOCK value
> to see if they are in sync with each other.
>
> [I'm leaving out the guts of the analysis here. It is sufficient to show
> examples of "good" data and "bad" data IMO.]
>
> On a good run, we see little variance in between the values:
>
> 0 144 0.1
> 1 138 1.8
> 2 147 -2.9
[snip]
> 29 144 -0.6
> n: 30, slope: 0.50 (1.99 GHz), dev: 1.1 ns, max: 2.9 ns
>
>
> On a bad run, there is a lot of variance between the values:
>
> 0 144 -346.0
> 1 138 1410.8
> 2 138 -806.9
> 3 141 4006.6
> 4 147 -3996.1
[snip]
> 29 141 -50.3
> n: 30, slope: 0.50 (1.99 GHz), dev: 1231.4 ns, max: 4006.6 ns


Do you see the same noisy variance when instead of doing:
rdtsc()
clock_gettime()
rdtsc()

you do:
clock_gettime()
clock_gettime()

And calculate the delta of the timestamp results?

Also does this behavior change if you select different clocksources on
the system?

> It was noted by the bug reporter that specifying "nohz=off" resolved the
> problem. I tested with "nohz=off" and AFAICT it fixes the issue. I started
> out debugging by assuming that delays in the c-state transitions were not being
> properly accounted for in the timing calculations.
>
> I ran a baseline test on an unmodified kernel (with no extra boot options) and
> confirmed that powertop shows the CPUs entering deep c-states while the test was
> running for 300 runs.
>
> I then instrumented the PM QoS and the power management code (specifically
> cpuidle). I put in a large # of printk's to monitor the CPU transitions, and
> monitored the power states via powertop in order to verify that the system was
> behaving correctly wrt PM QoS.
>
> If you modify the tstsc script to run 300 times with this modified kernel, and
> run powertop in the middle of the script, you will see that the processors do
> NOT enter deep c-states. **This means that PM QoS is doing its job correctly**.

So its not clear here, do you see the same noisier latencies when using
PM QoS to limit deep c-states?

Finally, how many cpus are on the machine you see this with? Does the
effect go away with maxcpus=1?

It looks like the TSC clocksource is being used, just because the
latencies are so low, but Is the same clocksource being used in all of
these cases?

One possibility is that if the cpu we're doing our timekeeping
accumulation on is different then the one running the test, we might go
into deeper idle for longer periods of time. Then when we accumulate
time, we have more then a single tick to accumulate and that might
require holding the timekeeper/xtime lock for longer times.

And the max 2.9ns variance seems particularly low, given that we do call
update_vsyscall every so often, and that should block clock_gettime()
callers while we update the vsyscall data. Could it be that the test is
too short to see the locking effect, so you're just getting lucky, and
that adding nohz is jostling the regularity of the execution so you then
see the lock wait times? If you increase the samples and sample loops
by 1000 does that change the behavior?

thanks
-john



\
 
 \ /
  Last update: 2012-10-11 22:41    [W:0.162 / U:0.068 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site