Re: [PATCH RFC] timekeeping: Fix clock stability with nohz

From: Richard Cochran
Date: Tue Nov 19 2013 - 09:13:30 EST

On Mon, Nov 18, 2013 at 01:28:07PM -0800, John Stultz wrote:

> Also, just for clarity's sake, when you're seeing things "broken",
> curious how/what you are measuring?

Here is the background for this issue. The linuxptp stack has a
program called phc2sys whose purpose is to synchronize the Linux
system clock with a PTP hardware clock typically residing on a PCIe
card. This program uses the PTP_SYS_OFFSET ioctl to read the clocks.

One user on the list was complaining that the reported time and
frequency errors were unacceptably large. After vainly trying
different PI weights, we found out that the poor performance is
due to the nohz setting in the kernel.

See below for example logs.

> Also is this brokenness something that has been around for awhile for
> you or more recently cropped up? I'm wondering as nohz idle has been
> around for quite a few years and I've not seen too many complaints. So
> I'm wondering if I'm looking in the right places, or if something has
> regressed recently, or if its just that accuracy expectations have gone up?

I have always avoided nohz like the plague. IIRC, it would not even
compile on ARM for the longest time. In any case, I really don't know
when this issue appeared. At some point, nohz became the Kconfig
default, and I did not notice, and so now I had it enabled by
accident.

Here are two sample runs of phc2sys. The PHC is an Intel i210 PCIe
card. I simply set the PHC time to the Linux system time (using
testptp -s), and then let PHC clock run free. During the test, the
phc2sys program is the only active program, and the system is
otherwise idle.

In this test, the update rate is once per second. When using longer
intervals, the problem becomes worse.

In the listings, "sys offset" is measured in nanosecond using the
PTP_SYS_OFFSET ioctl, "freq" is the PI servo output in ppb, and
"delay" is the time it took to read the two clocks in nanoseconds.

* Periodic Case

CONFIG_HZ_PERIODIC=y
CONFIG_NO_HZ=y
CONFIG_HZ_1000=y

Here we observe a time error of about 100 nanoseconds peak to peak
and a frequency error within about .2 PPM.

sudo ./phc2sys -s eth3 -m -q -l7 -O0
phc2sys[5050.678]: PI servo: sync interval 1.000 kp 0.700 ki 0.300000
phc2sys[5051.678]: sys offset 287239 s0 freq +0 delay 5164
phc2sys[5052.678]: sys offset 303841 s1 freq +16600 delay 5161
phc2sys[5053.679]: sys offset 11 s2 freq +16611 delay 5184
phc2sys[5054.679]: sys offset -6 s2 freq +16597 delay 5191
phc2sys[5055.679]: sys offset -6 s2 freq +16595 delay 5121
phc2sys[5056.679]: sys offset -32 s2 freq +16567 delay 5184
phc2sys[5057.679]: sys offset -6 s2 freq +16584 delay 5197
phc2sys[5058.679]: sys offset 10 s2 freq +16598 delay 5186
phc2sys[5059.679]: sys offset 14 s2 freq +16605 delay 5162
phc2sys[5060.680]: sys offset -12 s2 freq +16583 delay 5212
phc2sys[5061.680]: sys offset -15 s2 freq +16576 delay 5196
phc2sys[5062.680]: sys offset -4 s2 freq +16583 delay 5186
phc2sys[5063.680]: sys offset 21 s2 freq +16607 delay 5187
phc2sys[5064.680]: sys offset 5 s2 freq +16597 delay 5196
phc2sys[5065.680]: sys offset -1 s2 freq +16593 delay 5192
phc2sys[5066.680]: sys offset 13 s2 freq +16606 delay 5177
phc2sys[5067.680]: sys offset 5 s2 freq +16602 delay 5212
phc2sys[5068.681]: sys offset 11 s2 freq +16610 delay 5191
phc2sys[5069.681]: sys offset -19 s2 freq +16583 delay 5203
phc2sys[5070.681]: sys offset -3 s2 freq +16593 delay 5185
phc2sys[5071.681]: sys offset 9 s2 freq +16604 delay 5197
phc2sys[5072.681]: sys offset 4 s2 freq +16602 delay 5176
phc2sys[5073.681]: sys offset 7 s2 freq +16606 delay 5196
phc2sys[5074.681]: sys offset -6 s2 freq +16595 delay 5186
phc2sys[5075.681]: sys offset -28 s2 freq +16572 delay 5192
phc2sys[5076.682]: sys offset 48 s2 freq +16639 delay 5214

* NO_HZ

CONFIG_NO_HZ_COMMON=y
CONFIG_NO_HZ_IDLE=y
CONFIG_NO_HZ=y
CONFIG_RCU_FAST_NO_HZ=y
CONFIG_HZ_250=y

Here we observe a time error of about 3 microseconds peak to peak
and a frequency error within about 3 PPM.

cori@cher1293:~/git/linuxptp$ sudo ./phc2sys -s eth3 -m -q -l7 -O0
phc2sys[105.837]: PI servo: sync interval 1.000 kp 0.700 ki 0.300000
phc2sys[106.837]: sys offset 135052 s0 freq +0 delay 5189
phc2sys[107.837]: sys offset 151449 s1 freq +16394 delay 5174
phc2sys[108.837]: sys offset 246 s2 freq +16640 delay 5179
phc2sys[109.838]: sys offset -185 s2 freq +16283 delay 5171
phc2sys[110.838]: sys offset -552 s2 freq +15860 delay 5192
phc2sys[111.838]: sys offset 1383 s2 freq +17630 delay 5179
phc2sys[112.838]: sys offset -737 s2 freq +15925 delay 5158
phc2sys[113.838]: sys offset 1147 s2 freq +17587 delay 5171
phc2sys[114.839]: sys offset -1593 s2 freq +15192 delay 5186
phc2sys[115.839]: sys offset -1006 s2 freq +15301 delay 5161
phc2sys[116.839]: sys offset 1157 s2 freq +17162 delay 5191
phc2sys[117.839]: sys offset 410 s2 freq +16762 delay 5179
phc2sys[118.839]: sys offset 0 s2 freq +16475 delay 5184
phc2sys[119.839]: sys offset 20 s2 freq +16495 delay 5159
phc2sys[120.840]: sys offset 473 s2 freq +16954 delay 5172
phc2sys[121.840]: sys offset -690 s2 freq +15933 delay 5186
phc2sys[122.840]: sys offset -437 s2 freq +15979 delay 5186
phc2sys[123.840]: sys offset -229 s2 freq +16056 delay 5179
phc2sys[124.840]: sys offset 357 s2 freq +16573 delay 5179
phc2sys[125.840]: sys offset 285 s2 freq +16608 delay 5121
phc2sys[126.841]: sys offset 512 s2 freq +16921 delay 5179
phc2sys[127.841]: sys offset -944 s2 freq +15618 delay 5179
phc2sys[128.841]: sys offset 338 s2 freq +16617 delay 5158
phc2sys[129.841]: sys offset 1275 s2 freq +17655 delay 5171
phc2sys[130.841]: sys offset -198 s2 freq +16565 delay 5339
phc2sys[131.841]: sys offset -702 s2 freq +16002 delay 5179
phc2sys[132.842]: sys offset -664 s2 freq +15829 delay 5101
phc2sys[133.842]: sys offset -38 s2 freq +16256 delay 5184
phc2sys[134.842]: sys offset 663 s2 freq +16945 delay 5164
phc2sys[135.842]: sys offset -1066 s2 freq +15415 delay 5187
phc2sys[136.842]: sys offset 1202 s2 freq +17363 delay 5172
phc2sys[137.842]: sys offset 289 s2 freq +16811 delay 5161
phc2sys[138.843]: sys offset -1495 s2 freq +15114 delay 5154
phc2sys[139.843]: sys offset 877 s2 freq +17037 delay 5179
phc2sys[140.843]: sys offset -311 s2 freq +16112 delay 5186
phc2sys[141.843]: sys offset 1509 s2 freq +17839 delay 5179

Thanks,
Richard
--
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/