linux-kernel - Re: One-shot high-resolution POSIX timer periodically late

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Message-ID: <45BF8290.6010602@free.fr>
Date:	Tue, 30 Jan 2007 18:38:24 +0100
From:	John <shill@...e.fr>
To:	linux-kernel@...r.kernel.org
CC:	tglx@...esys.com, mingo@...e.hu, johnstul@...ibm.com,
	akpm@...l.org, shill@...e.fr
Subject: Re: One-shot high-resolution POSIX timer periodically late

John Stultz wrote:

> Also do check the -rt tree as Ingo suggested. I mis-read your earlier
> email and thought you were running it.

I've been pulling my hair over a related issue for the past two days.

(I think I may be tickling a -hrt bug...)

I'm working with 2.6.18.6 + patch-2.6.18-rt7

I've built a minimal kernel. The attached dot.config contains only
the list of options that are set. I've also attached dmesg.

# cat /proc/cpuinfo
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 11
model name      : Intel(R) Pentium(R) III CPU - S         1266MHz
stepping        : 4
cpu MHz         : 1266.773
cache size      : 512 KB
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 2
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 sep mtrr pge mca
cmov pat pse36 mmx fxsr sse
bogomips        : 2535.13

I've set up two systems, A and B.

Every millisecond, system A sends one UDP datagram containing two struct
timespec: the deadline and the actual timestamp.

System B blocks indefinitely waiting for packets from A. When it
receives a packet, it reads several timestamps:

1. the CPU's TSC (time stamp counter)
2. clock_gettime(CLOCK_REALTIME)
3. clock_gettime(CLOCK_MONOTONIC)
4. the struct timeval provided by the kernel

I then compute the differences for consecutive packets.

They should all be (approximately) equal to 1 ms. I say approximately
because unpredictable system latencies might introduce a small error.
Also clock skew between the two systems means 1 ms on A might be seen as
0.99 ms on B.

Anyway... sometimes after a few minutes, and sometimes after several
hours, the one millisecond seen by A is seen as .950 ms on B, all of a
sudden, for several hundred packets in a row. However the TSC indicates
that 1 ms has actually gone by.

For example,

Packet N:
timestamp 3 = 6967.391882010
timestamp 1 = 26808296

Packet N+1:
timestamp 3 = 6967.392832017
timestamp 1 = 28074967

diff3 = 950007 ns
diff1 = 1266671 cycles = 1 ms

As far as all the timers in the system are concerned, only 950 µs have
gone by. But as far as the TSC is concerned, 1000 µs have gone by.
Logically, the TSC is right, and the other timers are wrong.

I've also seen the problem go the other way, i.e. the timers think 1050
µs have gone by instead of just 1000. However, in that case, the TSC
agrees with them! This might mean that the same problem has manifested
on the other system. I'll need to add code to check this condition on
the sender.

Have you ever seen something like this?

Does the kernel ever write to the TSC?

I am grasping at straws. Help :-(

(I can provide my test code if it helps.)

View attachment "dot.config" of type "text/plain" (3901 bytes)

View attachment "dmesg" of type "text/plain" (7683 bytes)