Timing bug somewhere-or-other

[ewx]

richard@araminta:~$ cat t.c
#include <stdio.h>
#include <time.h>
#include <sys/time.h>
#include <assert.h>
int main(void) {
  for(;;) {
    time_t t;
    struct timeval tv;

    assert(gettimeofday(&tv, NULL) == 0);
    assert(time(&t) != (time_t)-1);
    if(t < tv.tv_sec)
      return printf("%ld %ld.%06ld\n", t, tv.tv_sec, tv.tv_usec);
  }
}

richard@araminta:~$ gcc -o t t.c
richard@araminta:~$ ./t
1255784018 1255784019.000000

richard@araminta:~$ uname -a
Linux araminta 2.6.26-2-xen-amd64 #1 SMP Thu Aug 20 00:36:34 UTC 2009 x86_64 GNU/Linux
richard@araminta:~$ dpkg -l libc6\*|grep ^i
ii  libc6                                   2.7-18                     GNU C Library: Shared libraries
ii  libc6-dbg                               2.7-18                     GNU C Library: Libraries with debugging symb
ii  libc6-dev                               2.7-18                     GNU C Library: Development Libraries and Hea
ii  libc6-dev-i386                          2.7-18                     GNU C Library: 32bit development libraries f
ii  libc6-i386                              2.7-18                     GNU C Library: 32bit shared libraries for AM
ii  libc6-prof                              2.7-18                     GNU C Library: Profiling Libraries
richard@araminta:~$ cat /proc/cpuinfo 
processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 15
model name	: Intel(R) Core(TM)2 Quad CPU    Q6600  @ 2.40GHz
stepping	: 11
cpu MHz		: 2397.654
cache size	: 4096 KB
physical id	: 0
siblings	: 1
core id		: 0
cpu cores	: 1
apicid		: 0
initial apicid	: 0
fpu		: yes
fpu_exception	: yes
cpuid level	: 10
wp		: yes
flags		: fpu de tsc msr pae cx8 apic sep mtrr cmov pat clflush acpi mmx fxsr sse sse2 ss ht syscall nx lm constant_tsc rep_good pni ssse3 cx16 lahf_lm
bogomips	: 4801.28
clflush size	: 64
cache_alignment	: 64
address sizes	: 36 bits physical, 48 bits virtual
power management:
<etc etc etc>

Comments

[sweh.livejournal.com]

Does that happen quickly (within a second or so), or does it sometimes take a long time to run?

Interesting that tv_usec==0. I wonder if Xen jitters the clock so it may have stepped back a few msecs between gettimeofday() and time(). (If you can replicate on a non-Xen sytem them that'd take Xen out of the equation).

[sweh.livejournal.com]

If the clock _is_ jittering then two calls to gettimeofday() and reporting when the second one returns an earlier time than the first might expose it...

[ewx.livejournal.com]

Quickly each time I've tried it. Removing the return shows it continues to be wonky for up to a few ms after the start of each second. (And see below for replication on non-Xen systems.)

[sweh.livejournal.com]

Bizarre. I ran it for 3 minutes on my CentOS 5.3 system without any error
Intel(R) Core(TM)2 Quad CPU Q6600 @ 2.40GHz
Linux mercury 2.6.18-128.1.16.el5PAE #1 SMP Tue Jun 30 06:45:32 EDT 2009 i686 i686 i386 GNU/Linux

Also didn't fail on my CentOS 4.8 system
Intel(R) Pentium(R) D CPU 3.00GHz
Linux backup 2.6.9-78.0.22.ELsmp #1 SMP Thu Apr 30 19:14:39 EDT 2009 i686 i686 i386 GNU/Linux

I wonder if this is something introduced into newer kernels.

[ewx.livejournal.com]

I don't see it under Debian's 2.6.18 (in a Xen guest). So I think you're right about it being introduced later.

[ewx.livejournal.com]

...but 2.6.24 has the bug.

[spodlife]

$ ./t
1255795977 1255795978.000000

$ uname -a
Linux quicklime 2.6.28-15-generic #52-Ubuntu SMP Wed Sep 9 10:49:34 UTC 2009 i686 GNU/Linux

So, this happens on a real CPU too. Need more info?

[simont]

strace says it's happening in the kernel, so it is a real difference between the time and gettimeofday system calls.

kernel/time.c says that time is implemented by calling get_seconds(), which is in kernel/time/timekeeping.c and is a one-liner that returns a cached value; gettimeofday on the other hand is implemented by actually reading the clock source. I don't know why the code that reads the clock source doesn't also update the cache, which would seem like the obvious way to avoid this sort of problem.

[ewx.livejournal.com]

For that matter I'm not sure why time() is a separate syscall at all - why not instead use gettimeofday() and throw away part of the answer?

[simont]

The caching approach makes me think it would make sense if there was a noticeable time cost to reading the clock source, so that while gettimeofday() has no choice but to read it on every call because the answer will be different every time, time() can avoid wasting the effort.

I don't know if that's true, though.

[sweh.livejournal.com]

Hmm. 2.60.20 (something I happen to have hanging around) did call gettimeofday()

asmlinkage long sys_time(time_t __user * tloc)
{
        time_t i;
        struct timeval tv;

        do_gettimeofday(&tv);
        i = tv.tv_sec;

        if (tloc) {
                if (put_user(i,tloc))
                        i = -EFAULT;
        }
        return i;
}

2.6.28 is different and uses the caching mechanism you mentioned earlier.

[simont]

Aha, here we are.

commit f20bf6125605acbbc7eb8c9420d7221c91aa83eb
Author: Ingo Molnar <mingo@elte.hu>
Date:   Tue Oct 16 16:09:20 2007 +0200

    time: introduce xtime_seconds

    improve performance of sys_time(). sys_time() returns time in seconds,
    but it does so by calling do_gettimeofday() and then returning the
    tv_sec portion of the GTOD time. But the data structure "xtime", which
    is updated by every timer/scheduler tick, already offers HZ granularity
    time.

    the patch improves the sysbench oltp macrobenchmark by 4-5% on an AMD
    dual-core system:
    [...]

Looks as if the later commit 1001d0a9ee74a468077dfd4da0565174e88de26b added a few calls to update_xtime_cache() with the specific intention of restoring monotonicity; so I'd guess that that supports my original suggestion that the right answer is to put another of those update calls somewhere in the implementation of gettimeofday().

[ewx.livejournal.com]

richard@sfere:~$ ./t
1255814510 1255814511.000000
richard@sfere:~$ uname -a
Linux sfere 2.6.26-2-686 #1 SMP Wed Aug 19 06:06:52 UTC 2009 i686 GNU/Linux
richard@sfere:~$ cat /proc/cpuinfo 
processor	: 0
vendor_id	: AuthenticAMD
cpu family	: 6
model		: 10
model name	: AMD Athlon(tm) XP 3200+
stepping	: 0
cpu MHz		: 2209.997
cache size	: 512 KB
fdiv_bug	: no
hlt_bug		: no
f00f_bug	: no
coma_bug	: no
fpu		: yes
fpu_exception	: yes
cpuid level	: 1
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 mmx fxsr sse syscall mmxext 3dnowext 3dnow up
bogomips	: 4424.48
clflush size	: 32
power management: ts

...a uniprocessor, 32-bit, non-Xen system albeit with an SMP-capable kernel.

[3c66b.livejournal.com]

I can't trigger this on any of my lenny systems, either running the Debian kernel or later ones.

vulpecula:/home/mjh/c> ./t
^C
260.344u 0.192s 4:20.66 99.9% 0+0k 16+0io 0pf+0w
vulpecula:/home/mjh/c> uname -a
Linux vulpecula 2.6.26-2-amd64 #1 SMP Wed Aug 19 22:33:18 UTC 2009 x86_64 GNU/Linux
vulpecula:/home/mjh/c> head -24 /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 23
model name : Intel(R) Core(TM)2 Quad CPU Q9450 @ 2.66GHz
stepping : 7
cpu MHz : 1998.000
cache size : 6144 KB
physical id : 0
siblings : 4
core id : 0
cpu cores : 4
apicid : 0
initial apicid : 0
fpu : yes
fpu_exception : yes
cpuid level : 10
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm constant_tsc arch_perfmon pebs bts rep_good pni monitor ds_cpl vmx smx est tm2 ssse3 cx16 xtpr sse4_1 lahf_lm
bogomips : 5336.87
clflush size : 64
cache_alignment : 64
address sizes : 36 bits physical, 48 bits virtual
power management:


hydra:/home/mjh/c> ./t
^C
403.341u 0.000s 6:44.30 99.7% 0+0k 0+0io 0pf+0w
hydra:/home/mjh/c> uname -a
Linux hydra 2.6.30.5 #1 SMP Tue Aug 25 14:16:16 BST 2009 x86_64 GNU/Linux
hydra:/home/mjh/c> head -24 /proc/cpuinfo
processor : 0
vendor_id : AuthenticAMD
cpu family : 16
model : 4
model name : Quad-Core AMD Opteron(tm) Processor 2384
stepping : 2
cpu MHz : 800.000
cache size : 512 KB
physical id : 0
siblings : 4
core id : 0
cpu cores : 4
apicid : 0
initial apicid : 0
fpu : yes
fpu_exception : yes
cpuid level : 5
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm 3dnowext 3dnow constant_tsc rep_good nonstop_tsc extd_apicid pni monitor cx16 lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt
bogomips : 5387.73
TLB size : 1024 4K pages
clflush size : 64
cache_alignment : 64
address sizes : 48 bits physical, 48 bits virtual