test-utime failure

[Phil Estes <pestes at us dot ibm dot com>]

H.J. Lu reported a failure of this testcase in post of "Sun, 4 May 2003
16:58:19 -0700"[1]

I have seen this failure several times recently and have come to the
following conclusion after spending some time looking into it.  If
test-utime is run within a loop over several seconds, this failure can
be reproduced at least once or twice per second, depending on the speed
of the machine, and possibly load as well--all it requires is that a
utime(file, NULL) call is made during the first 8-10ms after a "second
transition" of the system's internal clock (I'm being intentionally
vague here as I haven't looked into what time source is being used by
the various calls in question).  What appears to occur is that the now1
and now2 variables are populated via the time(NULL) call with the "new"
second, and the utime(file, NULL) call causes the file to receive a
modify timestamp that contains the "old" second.  This test failure can
be alleviated with a simple hack to force the test to not run if a
second transition has just occurred (don't run unless tv_usec > ~9000).

However, I am more interested in what the real issue is--i.e. why is a
call to utime() sandwiched between two calls to time() assigning a
different (older) "seconds since the epoch" value--is it granularity of
time source? (remember that this only occurs in the "first" 8-10ms of
the transition of the second), is it a bug?, is this kernel related, h/w
related?  It basically seems that there is possibly two different time
sources being used by utime() and/or the time() calls and/or granularity
of clock that opens a small hole (approx 1% of the time) for which the
response from utime() [or more clearly, stat(), which reports what utime
set the modtime/actime to] and time() are different.  I have augmented
the test output with more information from gettimeofday() in [2] below.

Finally, here are a few details about where I have reproduced this
problem:

** All x86 H/W (various Pentium II/III and IV machines with 
                128Mb-2G RAM)
** All libc 2.2.5

(1) RedHat 7.3 + errata (Uni-processor kernel 2.4.18-10)
(2 & 3) SuSE 8.0 + errata (2 machines, 2.4.18-64GB-SMP & 2.4.18-4GB)
(4) Debian?? (2.4.20 #1 SMP)

Thanks,
Phil Estes
pestes@us.ibm.com


[1] http://sources.redhat.com/ml/libc-alpha/2003-05/msg00042.html

[2] The following represents a couple examples of a run of test-utime
    where the second has just "transitioned" and the output of
    gettimeofday(&timev, &tz) has been used to augment the regular
    test results.  Note that the output "modtime %ld < %ld > %ld"
    represents the "seconds since epoch" values for utime()/stat(),
    now1 = time(), now2 = time() respectively.

-----run 1----
1055775280.978513 Test succeeded.
1055775280.984260 Test succeeded.
1055775280.990436 Test succeeded.
1055775280.996156 Test succeeded.
oops 1611 (tv_usec value @ failure)
now1: 1055775281.1610, now2: 1055775281.1614
1055775281.1611 modtime 1055775280 <1055775281 >1055775281

-----run 2----
1055773507.969924 Test succeeded.
1055773507.978268 Test succeeded.
1055773507.986719 Test succeeded.
1055773507.994722 Test succeeded.
oops 3026 (tv_usec value @ failure)
now1: 1055773508.3026, now2: 1055773508.3030
1055773508.3026 modtime 1055773507 <1055773508 >1055773508