Re: RCU NOHZ, tsc, and clock_gettime

[Prarit Bhargava <prarit@redhat.com>]

On 10/11/2012 04:21 PM, Paul E. McKenney wrote:
> On Thu, Oct 11, 2012 at 12:51:44PM -0700, John Stultz wrote:
>> 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?

I do not see the noisy variance when comparing clock_gettime() to clock_gettime().

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

No, if the clocksource is the hpet, I still see the large variance. ie) the
behaviour does not change.

>>
>>> 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?

I see the same noisier latencies when using PM QoS to limit the deep c-state
transitions.

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


24 physical/48 logical, 2G/core RAM

The large variance is still there if maxcpus=1.

> 
> Also, what is the value of NR_CPUS?  And exactly which kernel.org kernel
> are you using?

NR_CPUS=4096

I'm using the "main" kernel.org tree,

git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git

as of commit 4f1cd91497774488ed16119ec3f54b3daf1561de

(I recompiled this morning and re-ran the tests and they still show a large
variance)

> 
> The effect of removing the two functions you noted (on 3.6 and earlier)
> is to prevent RCU from checking for dyntick-idle CPUs, likely incurring
> a cache miss for each CPU with interrupts disabled.  If you have a lot
> of CPUs (or even if NR_CPUS is large and you have a smaller number of
> CPUs), this can result in user-space-visible delays.
> 

Interesting.  I'll lower NR_CPUS and see if that shows an improvement.

> 							Thanx, Paul
> 
>> 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?


Yes, the TSC is always being used.

>>
>> 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?

That's a possiblity, although I suspect that this has more to do with not
executing the RCU NOHZ code given that we don't see a problem with the
clock_gettime() vs clock_gettime() test.  I wonder if not executing the RCU NOHZ
code somehow introduces a "regularity" with execution that results in the CPU
always being in C0/polling when the test is run?

P.