Re: RCU NOHZ, tsc, and clock_gettime

From: John Stultz
Date: Thu Oct 11 2012 - 15:55:00 EST

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

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/