Date: Mon, 13 Jun 2011 18:44:10 +0200 From: Fabian Keil <freebsd-listen@fabiankeil.de> To: freebsd-current@FreeBSD.org Subject: Time keeping Issues with the low-resolution TSC timecounter Message-ID: <20110613184410.4f6e2b81@fabiankeil.de>
next in thread | raw e-mail | index | archive | help
--Sig_/Q5.DZKN9ebGlbu4agRwWgob
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: quoted-printable
I'm experiencing time-related issues that seem to be caused by
the low-resolution TSC timecounter (r222866).
The problem I noticed first is that it takes unusually long until a
key press is repeated. With the default eventtimer (HPET) it seems
to take about 4s, which can be slightly improved by switching to
i8254.
The "error beep" seems to take longer than usual, too,
and the system "feels sluggish" in general.
An effect that is easier to measure is that the system is unable
to properly keep the time. Again the problem is less severe when
using i8254 instead of HPET:
fk@r500 ~ $sudo sysctl kern.eventtimer.timer=3DHPET
kern.eventtimer.timer: i8254 -> HPET
fk@r500 ~ $while sudo /etc/rc.d/ntpdate onestart; do sleep 1; done
Setting date via ntp.
13 Jun 14:30:34 ntpdate[4161]: step time server 72.14.179.211 offset 47.463=
608 sec
Setting date via ntp.
13 Jun 14:30:52 ntpdate[4172]: step time server 178.26.114.66 offset 14.867=
148 sec
Setting date via ntp.
13 Jun 14:31:12 ntpdate[4183]: step time server 178.26.114.66 offset 17.472=
867 sec
Setting date via ntp.
13 Jun 14:31:37 ntpdate[4194]: step time server 72.14.179.211 offset 22.477=
665 sec
Setting date via ntp.
13 Jun 14:31:51 ntpdate[4205]: step time server 178.26.114.66 offset 10.956=
637 sec
Setting date via ntp.
13 Jun 14:32:11 ntpdate[4216]: step time server 178.26.114.66 offset 16.548=
800 sec
^C
fk@r500 ~ $sudo sysctl kern.eventtimer.timer=3Di8254
kern.eventtimer.timer: HPET -> i8254
fk@r500 ~ $while sudo /etc/rc.d/ntpdate onestart; do sleep 1; done
Setting date via ntp.
13 Jun 14:32:23 ntpdate[4240]: step time server 178.26.114.66 offset 8.7136=
38 sec
Setting date via ntp.
13 Jun 14:32:28 ntpdate[4251]: step time server 178.26.114.66 offset 1.6306=
54 sec
Setting date via ntp.
13 Jun 14:32:33 ntpdate[4262]: step time server 178.26.114.66 offset 2.3171=
75 sec
Setting date via ntp.
13 Jun 14:32:38 ntpdate[4273]: step time server 178.26.114.66 offset 2.1742=
20 sec
Setting date via ntp.
13 Jun 14:32:43 ntpdate[4284]: step time server 178.26.114.66 offset 1.7752=
81 sec
Setting date via ntp.
13 Jun 14:32:49 ntpdate[4295]: step time server 178.26.114.66 offset 2.2236=
60 sec
Setting date via ntp.
13 Jun 14:32:54 ntpdate[4306]: step time server 208.52.173.46 offset 1.9009=
42 sec
^C
fk@r500 ~ $sudo sysctl kern.eventtimer.timer=3DHPET
kern.eventtimer.timer: i8254 -> HPET
fk@r500 ~ $while sudo /etc/rc.d/ntpdate onestart; do sleep 1; done
Setting date via ntp.
13 Jun 14:33:08 ntpdate[4319]: step time server 108.71.253.20 offset 9.7408=
12 sec
Setting date via ntp.
13 Jun 14:33:30 ntpdate[4330]: step time server 108.71.253.20 offset 19.046=
164 sec
Setting date via ntp.
13 Jun 14:33:51 ntpdate[4341]: step time server 108.71.253.20 offset 18.489=
062 sec
Setting date via ntp.
13 Jun 14:34:03 ntpdate[4352]: step time server 69.65.40.29 offset 8.659389=
sec
Setting date via ntp.
13 Jun 14:34:09 ntpdate[4363]: step time server 108.71.253.20 offset 2.8686=
11 sec
Setting date via ntp.
13 Jun 14:34:23 ntpdate[4374]: step time server 108.71.253.20 offset 10.798=
129 sec
Setting date via ntp.
13 Jun 14:34:33 ntpdate[4407]: step time server 108.71.253.20 offset 6.9197=
64 sec
Setting date via ntp.
13 Jun 14:34:43 ntpdate[4422]: step time server 108.71.253.20 offset 7.1358=
78 sec
^C
fk@r500 ~ $sudo sysctl kern.eventtimer.timer=3Di8254
kern.eventtimer.timer: HPET -> i8254
fk@r500 ~ $while sudo /etc/rc.d/ntpdate onestart; do sleep 1; done
Setting date via ntp.
13 Jun 14:34:56 ntpdate[4435]: step time server 108.71.253.20 offset 9.5964=
63 sec
Setting date via ntp.
13 Jun 14:35:02 ntpdate[4446]: step time server 108.71.253.20 offset 2.1375=
92 sec
Setting date via ntp.
13 Jun 14:35:07 ntpdate[4457]: step time server 108.71.253.20 offset 2.4350=
11 sec
Setting date via ntp.
13 Jun 14:35:13 ntpdate[4468]: step time server 108.71.253.20 offset 2.6312=
90 sec
Setting date via ntp.
13 Jun 14:35:18 ntpdate[4479]: step time server 108.71.253.20 offset 1.9095=
70 sec
Setting date via ntp.
13 Jun 14:35:24 ntpdate[4490]: step time server 108.71.253.20 offset 2.3985=
83 sec
Setting date via ntp.
13 Jun 14:35:29 ntpdate[4501]: step time server 108.71.253.20 offset 2.2647=
60 sec
Setting date via ntp.
13 Jun 14:35:34 ntpdate[4512]: step time server 108.71.253.20 offset 1.8080=
83 sec
Setting date via ntp.
HPET1 to HPET3 seem to behave similar to HPET or at least
the difference isn't significant enough to be obvious without
running proper benchmarks.
The cpu is:
Calibrating TSC clock ... TSC clock: 1995043420 Hz
CPU: Intel(R) Core(TM)2 Duo CPU T5870 @ 2.00GHz (1995.04-MHz K8-class =
CPU)
Origin =3D "GenuineIntel" Id =3D 0x6fd Family =3D 6 Model =3D f Stepp=
ing =3D 13
Features=3D0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PG=
E,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
Features2=3D0xe39d<SSE3,DTES64,MON,DS_CPL,EST,TM2,SSSE3,CX16,xTPR,PDCM>
AMD Features=3D0x20100800<SYSCALL,NX,LM>
AMD Features2=3D0x1<LAHF>
TSC: P-state invariant, performance statistics
With r222866, I get the message: "TSC timecounter discards lower 7 bit(s)"
I'm using powerd, but killing it doesn't solve the issue.
fk@r500 ~ $sysctl kern.eventtimer
kern.eventtimer.choice: HPET(450) HPET1(440) HPET2(440) HPET3(440) i8254(10=
0)
kern.eventtimer.et.i8254.flags: 1
kern.eventtimer.et.i8254.frequency: 1193182
kern.eventtimer.et.i8254.quality: 100
kern.eventtimer.et.HPET.flags: 3
kern.eventtimer.et.HPET.frequency: 14318180
kern.eventtimer.et.HPET.quality: 450
kern.eventtimer.et.HPET1.flags: 3
kern.eventtimer.et.HPET1.frequency: 14318180
kern.eventtimer.et.HPET1.quality: 440
kern.eventtimer.et.HPET2.flags: 3
kern.eventtimer.et.HPET2.frequency: 14318180
kern.eventtimer.et.HPET2.quality: 440
kern.eventtimer.et.HPET3.flags: 3
kern.eventtimer.et.HPET3.frequency: 14318180
kern.eventtimer.et.HPET3.quality: 440
kern.eventtimer.periodic: 0
kern.eventtimer.timer: HPET
kern.eventtimer.idletick: 0
kern.eventtimer.singlemul: 2
Things improve quite a bit with this patch:
commit 4e7d41a5438a502f754d0e4b02c8eba5d0ae15a2
Author: Fabian Keil <fk@fabiankeil.de>
Date: Mon Jun 13 17:07:46 2011 +0200
Do not mess with smp_tsc in test_smp_tsc()
diff --git a/sys/x86/x86/tsc.c b/sys/x86/x86/tsc.c
index 83eab4d..7a70484 100644
--- a/sys/x86/x86/tsc.c
+++ b/sys/x86/x86/tsc.c
@@ -376,7 +376,8 @@ test_smp_tsc(void)
data =3D malloc(sizeof(*data) * size * N, M_TEMP, M_WAITOK);
for (i =3D 0, tsc =3D data; i < N; i++, tsc +=3D size)
smp_rendezvous(tsc_read_0, tsc_read_1, tsc_read_2, tsc);
- smp_tsc =3D 1; /* XXX */
+ if (bootverbose)
+ printf("SMP: Keeping smp_tsc at %d\n", smp_tsc);
smp_rendezvous(smp_no_rendevous_barrier, comp_smp_tsc,
smp_no_rendevous_barrier, data);
free(data, M_TEMP);
fk@r500 ~ $while sudo /etc/rc.d/ntpdate onestart; do sleep 1; done
Password:
Setting date via ntp.
13 Jun 17:29:56 ntpdate[3464]: step time server 131.234.137.23 offset 1.748=
995 sec
Setting date via ntp.
13 Jun 17:29:59 ntpdate[3475]: step time server 131.234.137.23 offset 0.001=
936 sec
Setting date via ntp.
13 Jun 17:30:02 ntpdate[3486]: step time server 80.153.14.198 offset 0.0231=
67 sec
Setting date via ntp.
13 Jun 17:30:07 ntpdate[3508]: step time server 80.153.14.198 offset -0.002=
901 sec
Setting date via ntp.
13 Jun 17:30:10 ntpdate[3519]: step time server 131.234.137.23 offset -0.02=
2134 sec
Setting date via ntp.
13 Jun 17:30:14 ntpdate[3530]: step time server 80.153.14.198 offset 0.0140=
18 sec
Setting date via ntp.
13 Jun 17:30:17 ntpdate[3541]: step time server 131.234.137.23 offset -0.01=
4088 sec
Setting date via ntp.
13 Jun 17:30:20 ntpdate[3552]: step time server 131.234.137.23 offset 0.000=
335 sec
Setting date via ntp.
13 Jun 17:30:24 ntpdate[3563]: step time server 131.234.137.23 offset 0.001=
874 sec
Setting date via ntp.
13 Jun 17:30:27 ntpdate[3574]: step time server 131.234.137.23 offset -0.00=
2200 sec
Setting date via ntp.
13 Jun 17:30:31 ntpdate[3585]: step time server 131.234.137.23 offset 0.000=
883 sec
Setting date via ntp.
13 Jun 17:30:34 ntpdate[3596]: step time server 131.234.137.23 offset 0.000=
910 sec
Setting date via ntp.
13 Jun 17:30:38 ntpdate[3607]: step time server 131.234.137.23 offset -0.00=
1278 sec
Setting date via ntp.
13 Jun 17:30:41 ntpdate[3618]: step time server 131.234.137.23 offset 0.001=
204 sec
Setting date via ntp.
13 Jun 17:30:45 ntpdate[3629]: step time server 131.234.137.23 offset -0.00=
1360 sec
Setting date via ntp.
13 Jun 17:30:49 ntpdate[3640]: step time server 131.234.137.23 offset -0.00=
0312 sec
Setting date via ntp.
13 Jun 17:30:52 ntpdate[3651]: step time server 131.234.137.23 offset 0.000=
123 sec
Setting date via ntp.
13 Jun 17:30:56 ntpdate[3662]: step time server 131.234.137.23 offset -0.00=
0025 sec
Setting date via ntp.
13 Jun 17:30:59 ntpdate[3673]: step time server 80.153.14.198 offset 0.0204=
60 sec
Setting date via ntp.
13 Jun 17:31:02 ntpdate[3684]: step time server 80.153.14.198 offset -0.009=
112 sec
Setting date via ntp.
13 Jun 17:31:06 ntpdate[3695]: step time server 131.234.137.23 offset -0.00=
9259 sec
Setting date via ntp.
13 Jun 17:31:09 ntpdate[3706]: step time server 80.153.14.198 offset 0.0260=
02 sec
^C
I get the impression that the offsets are still a bit larger on
average than with a kernel with sys/x86/x86/tsc.c from r222864,
but haven't done enough tests to be sure:
fk@r500 ~ $while sudo /etc/rc.d/ntpdate onestart; do sleep 1; done
Setting date via ntp.
13 Jun 18:37:56 ntpdate[4404]: step time server 212.112.228.242 offset -0.0=
03875 sec
Setting date via ntp.
13 Jun 18:37:59 ntpdate[4415]: step time server 79.143.177.46 offset 0.0032=
66 sec
Setting date via ntp.
13 Jun 18:38:03 ntpdate[4426]: step time server 212.112.228.242 offset -0.0=
03565 sec
Setting date via ntp.
13 Jun 18:38:06 ntpdate[4437]: step time server 212.112.228.242 offset -0.0=
00430 sec
Setting date via ntp.
13 Jun 18:38:10 ntpdate[4448]: step time server 79.143.177.46 offset 0.0040=
59 sec
Setting date via ntp.
13 Jun 18:38:13 ntpdate[4459]: step time server 79.143.177.46 offset 0.0006=
09 sec
Setting date via ntp.
13 Jun 18:38:17 ntpdate[4470]: step time server 212.112.228.242 offset -0.0=
03540 sec
Setting date via ntp.
13 Jun 18:38:20 ntpdate[4481]: step time server 79.143.177.46 offset 0.0037=
22 sec
Setting date via ntp.
13 Jun 18:38:23 ntpdate[4492]: step time server 79.143.177.46 offset -0.000=
707 sec
Setting date via ntp.
13 Jun 18:38:27 ntpdate[4503]: step time server 79.143.177.46 offset -0.000=
125 sec
Setting date via ntp.
13 Jun 18:38:30 ntpdate[4514]: step time server 212.112.228.242 offset -0.0=
03536 sec
Setting date via ntp.
Fabian
--Sig_/Q5.DZKN9ebGlbu4agRwWgob
Content-Type: application/pgp-signature; name=signature.asc
Content-Disposition: attachment; filename=signature.asc
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.17 (FreeBSD)
iEYEARECAAYFAk32PmIACgkQBYqIVf93VJ0jDQCgzUNXv+c5+c9glOAvRUjlRMoK
AxEAnAmCmJHEFeRtm/E69oisS7FhN/nl
=MQ0U
-----END PGP SIGNATURE-----
--Sig_/Q5.DZKN9ebGlbu4agRwWgob--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20110613184410.4f6e2b81>