classification
Title: Numerous utime ns tests fail on FreeBSD w/ ZFS (update: and NetBSD w/ FFS, Solaris w/ UFS)
Type: behavior Stage: needs patch
Components: Versions: Python 3.3, Python 3.2, Python 2.7
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: trent Nosy List: Arfrever, Ed.Maste, haypo, jcea, koobs, larry, pitrou, skrah, trent
Priority: normal Keywords: patch

Created on 2012-08-21 02:15 by trent, last changed 2013-05-27 13:34 by Ed.Maste.

Files
File name Uploaded Description Edit
test_os.patch trent, 2012-10-16 21:40 review
Messages (27)
msg168728 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-08-21 02:15
I've got two FreeBSD buildslaves running on ZFS (8.2 and 9.1) experiencing this:

======================================================================
FAIL: test_futimes_ns (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 369, in test_futimes_ns
    self._test_utime_ns(futimes_ns, test_dir=False)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 339, in _test_utime_ns
    self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345497270884503433 != 1345497270884503000

======================================================================
FAIL: test_lutimes_ns (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 362, in test_lutimes_ns
    self._test_utime_ns(lutimes_ns)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 339, in _test_utime_ns
    self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345497270888847634 != 1345497270888847000

======================================================================
FAIL: test_utime (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 331, in test_utime
    self._test_utime(self.fname, getattr, utime, 10)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345497270.8923829 != 1345497270.892382

======================================================================
FAIL: test_utime_ns (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 346, in test_utime_ns
    self._test_utime_ns(utime_ns)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 339, in _test_utime_ns
    self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345497270894558518 != 1345497270894558000


I briefly stepped through the test on one of the affected slaves.  There's a rounding issue somewhere... I personally think this method is involved:

    def _test_utime_ns(self, set_times_ns, test_dir=True):
        def getattr_ns(o, attr):
            return getattr(o, attr + "_ns")
        ten_s = 10 * 1000 * 1000 * 1000
        self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
        if test_dir:
            self._test_utime(support.TESTFN, getattr_ns, set_times_ns, ten_s)

I didn't have enough time to keep debugging, so I'm raising this as a placeholder until I can pick it back up again.
msg168770 - (view) Author: Stefan Krah (skrah) * (Python committer) Date: 2012-08-21 13:45
Looks like a ZFS/nanosecond issue. My FreeBSD buildbot uses FFS and does not
have the failures.
msg168808 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2012-08-21 21:52
Can you tell me which code path it took?  Either by walking through the code as it runs, or by telling me about the preprocessor defines used by utime (HAVE_FUTIMES, HAVE_FUTIMENS, HAVE_FUTIMESAT, HAVE_UTIMENSAT, HAVE_UTIMES, HAVE_UTIME_H).  The easy way to do this would be to say

    from posix import _have_functions
    print(_have_functions)

and paste the result in.  Then also tell me if you have a file "utime.h" in either your standard include directory or in the "sys" subdirectory of that directory.
msg168811 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-08-21 22:06
>>> print(_have_functions)
['HAVE_FACCESSAT', 'HAVE_FCHDIR', 'HAVE_FCHMOD', 'HAVE_FCHMODAT', 'HAVE_FCHOWN', 'HAVE_FEXECVE', 'HAVE_FDOPENDIR', 'HAVE_FPATHCONF', 'HAVE_FSTATAT', 'HAVE_FSTATVFS', 'HAVE_FTRUNCATE', 'HAVE_FUTIMES', 'HAVE_FUTIMESAT', 'HAVE_LINKAT', 'HAVE_LCHFLAGS', 'HAVE_LCHMOD', 'HAVE_LCHOWN', 'HAVE_LSTAT', 'HAVE_LUTIMES', 'HAVE_MKDIRAT', 'HAVE_MKFIFOAT', 'HAVE_MKNODAT', 'HAVE_OPENAT', 'HAVE_READLINKAT', 'HAVE_RENAMEAT', 'HAVE_SYMLINKAT', 'HAVE_UNLINKAT']

/usr/include/utime.h exists.

FWIW, when I stepped through it a few nights ago, I remember that all the code paths eventually visited the point where the mtime gets converted into a decimal:

======================================================================
FAIL: test_utime (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 331, in test_utime
    self._test_utime(self.fname, getattr, utime, 10)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345497270.8923829 != 1345497270.892382

However, for the other errors:
    AssertionError: 1345497270884503433 != 1345497270884503000
    AssertionError: 1345497270888847634 != 1345497270888847000
....they'd get cast back before the assertEqual test would be done.

As for this:
    1345497270.8923829 != 1345497270.892382

The trailing 9 is getting lopped off, which results in the rounding errors.
msg168822 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2012-08-21 23:38
mtime is never converted into a "decimal".  Do you perhaps mean "double"?
msg168828 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-08-22 00:03
Oh, heh, yes, I meant double :-)
msg168883 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-08-22 13:11
Looks like it's not specific to just FreeBSD, no ZFS.  From a new NetBSD slave I set up:

======================================================================
FAIL: test_futimes_ns (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 369, in test_futimes_ns
    self._test_utime_ns(futimes_ns, test_dir=False)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 339, in _test_utime_ns
    self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345639042446725659 != 1345639042446725000

======================================================================
FAIL: test_lutimes_ns (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 362, in test_lutimes_ns
    self._test_utime_ns(lutimes_ns)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 339, in _test_utime_ns
    self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345639042450323780 != 1345639042450323000

======================================================================
FAIL: test_utime (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 331, in test_utime
    self._test_utime(self.fname, getattr, utime, 10)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 319, in _test_utime
    self.assertEqual(attr(st0, "st_atime"), attr(st1, "st_atime"))
AssertionError: 1345639042.4583352 != 1345639042.458335

======================================================================
FAIL: test_utime_ns (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 346, in test_utime_ns
    self._test_utime_ns(utime_ns)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 339, in _test_utime_ns
    self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345639042463150626 != 1345639042463150000

----------------------------------------------------------------------
(from http://buildbot.python.org/all/builders/x86%20NetBSD%205.1.2%20%5BSB%5D%203.x/builds/0/steps/test/logs/stdio)


Exact same symptoms as the original FreeBSD issue.
msg168898 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-08-22 17:04
> AssertionError: 1345639042446725659 != 1345639042446725000

Well, by the looks of it, some filesystems only have microsecond precision?
Would be best to confirm with a {Free,Net}BSD mailing-list, I think.
msg168911 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2012-08-23 00:34
Yes, but the code should still work.  The test that's failing reads the atime/mtime from a file, then writes those values out to the file, then reads again to confirm that they're the same.  That should always work.
msg170631 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-09-18 03:03
Just noticed that the Solaris 10 slave is failing in the same way:

======================================================================
FAIL: test_utime (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/cpython/buildslave/3.x.snakebite-solaris10-u10ga2-sparc64-1/build/Lib/test/test_os.py", line 332, in test_utime
    self._test_utime(support.TESTFN, getattr, utime, 10)
  File "/home/cpython/buildslave/3.x.snakebite-solaris10-u10ga2-sparc64-1/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1347752941.275297 != 1347752941.275296

Note that /home/cpython on this slave is backed by UFS, not ZFS.

(It's accessible to committers via sb->s10.)
msg173087 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-16 20:04
I've figured out what the primary problem is on these platforms: os.stat() returns st_mtime and st_atime values with nanosecond resolution, but without a corresponding utimensat(), we can only affect time with microsecond precision via utimes().

Therefore, the following logic is faulty:

    def _test_utime(self, filename, attr, utime, delta):
        # Issue #13327 removed the requirement to pass None as the
        # second argument. Check that the previous methods of passing
        # a time tuple or None work in addition to no argument.
        st0 = os.stat(filename)
        # Doesn't set anything new, but sets the time tuple way
        utime(filename, (attr(st0, "st_atime"), attr(st0, "st_mtime")))
        # Setting the time to the time you just read, then reading again,
        # should always return exactly the same times.
        st1 = os.stat(filename)
        self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
        self.assertEqual(attr(st0, "st_atime"), attr(st1, "st_atime"))
msg173092 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2012-10-16 20:59
Is there a different utime family function on these platforms that *can* write atime/mtime with ns resolution?
msg173094 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-16 21:03
There doesn't appear to be on FreeBSD.  Although, on Solaris, -D__EXTENSIONS__ opens up access to utimensat() (at least on 11), so I'll factor that into configure.ac.
msg173102 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-16 21:40
This patch (surprisingly) seems to do the job quite nicely:

diff -r 1280b38fe583 Lib/test/test_os.py
--- a/Lib/test/test_os.py	Tue Oct 16 23:14:03 2012 +1000
+++ b/Lib/test/test_os.py	Tue Oct 16 21:25:36 2012 +0000
@@ -40,6 +40,20 @@
     or (st.st_mtime != st[8])
     or (st.st_ctime != st[9]))
 
+try:
+    import posix
+except ImportError:
+    # Windows has nanosecond utime resolution.
+    UTIME_EPSILON = 2e-9
+else:
+    import sysconfig
+    if 'HAVE_UTIMENSAT' in posix._have_functions:
+        UTIME_EPSILON = 2e-9
+    elif 'HAVE_UTIMES' in sysconfig.get_config_vars():
+        UTIME_EPSILON = 2e-6
+    else:
+        UTIME_EPSILON = 1.0
+
 # Detect whether we're on a Linux system that uses the (now outdated
 # and unmaintained) linuxthreads threading library.  There's an issue
 # when combining linuxthreads with a failed execv call: see
@@ -312,18 +326,32 @@
         st0 = os.stat(filename)
         # Doesn't set anything new, but sets the time tuple way
         utime(filename, (attr(st0, "st_atime"), attr(st0, "st_mtime")))
-        # Setting the time to the time you just read, then reading again,
-        # should always return exactly the same times.
         st1 = os.stat(filename)
-        self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
-        self.assertEqual(attr(st0, "st_atime"), attr(st1, "st_atime"))
+
+        def _t(left, right, attr, name):
+            l = attr(left, name)
+            r = attr(right, name)
+            if isinstance(l, int):
+                assert isinstance(r, int)
+                l = l / 1e9
+                r = r / 1e9
+            return abs(l - r)
+
+        epsilon = UTIME_EPSILON
+        self.assertLess(_t(st0, st1, attr, "st_mtime"), epsilon)
+        self.assertLess(_t(st0, st1, attr, "st_atime"), epsilon)
+
         # Set to the current time in the old explicit way.
         os.utime(filename, None)
         st2 = os.stat(support.TESTFN)
         # Set to the current time in the new way
         os.utime(filename)
         st3 = os.stat(filename)
-        self.assertAlmostEqual(attr(st2, "st_mtime"), attr(st3, "st_mtime"), delta=delta)
+        self.assertAlmostEqual(
+            attr(st2, "st_mtime"),
+            attr(st3, "st_mtime"),
+            delta=delta
+        )
 
     def test_utime(self):
         def utime(file, times):


test_os passes on FreeBSD, Linux and Mac OS X with that applied.  However, the Solaris 10/SPARC box still fails:

AssertionError: 9.5367431640625e-07 not less than 2e-09

But it appears that build is actually picking up utimensat(), which makes the Solaris failures unrelated to the FreeBSD/NetBSD ones.  I'll do some more investigating.  Might warrant a separate issue.

Larry: thoughts on the test_os.patch as is?
msg173130 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2012-10-17 04:38
You're a sneaky, naughty bunny.  "posix._have_functions" indeed!  I guess your back was to the wall.

1)
If I follow your code correctly, when one has utimensat, the assertLess calls using _t consider st0.st_mtime_ns < st1.st_mtime_ns even if the left operand is (2e18-1) greater than the right.  It divides both operands by 1e9, then checks whether their delta is < 2e9.  In nanoseconds, 2e18-1 is roughly 63.5 years.  The case where one doesn't have utimensat but do have utimens is similarly generous.  Little wonder the test now passes!  Could you narrow down the range a little?

2)
I'd prefer if you amended the comment rather than remove it, perhaps adding

# (assuming your read and write functions both take the same units,
# which isn't true on all platforms--some Solaris and FreeBSD versions
# can read ns time but can only write ms time)

3)
Could you please find better names than "_t", "l", and "r"?

4)
In the future, please upload a patch as an attached file rather than as an inline comment.  This will permit me to use the bug tracker's built-in  Reitveld to examine the diff, which is more comfortable and permits inline comments.
msg173131 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-17 05:46
Thanks for the feedback Larry; yeah that patch definitely wasn't intended to be "production quality" -- more of a proof of concept.  I agree with your points, they'll be factored into the next patch.

However, I'm absolutely baffled by the Solaris 10 failure.  The more I looked into it, the weirder it got.  The issue is always the same:

    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1347752941.275297 != 1347752941.275296

That is, test_utime() always results in a st1.st_mtime that is "off-by-1" from st0.st_mtime.  The precision is well within the nanasecond resolution offered by utimensat, so it doesn't appear to be the same issue experienced by other platforms.

I'll have to break into the debugger again and see what's going on.

Side note: I noticed this comment/code just above _test_utime():

    def test_utime_dir(self):
        delta = 1000000
        st = os.stat(support.TESTFN)
        # round to int, because some systems may support sub-second
        # time stamps in stat, but not in utime.
        os.utime(support.TESTFN, (st.st_atime, int(st.st_mtime-delta)))
        st2 = os.stat(support.TESTFN)
        self.assertEqual(st2.st_mtime, int(st.st_mtime-delta))

That... seems to (albeit vaguely) describe what's going on here with Solaris 10.  I also noticed support.TESTFN is actually a directory in this test case.  Again, I'm not sure how that fits in with test_utime_dir() versus a second invocation of _test_utime(support.TESTFN) from test_utime().

test_utime_dir() is ultra-lax, test_utime() is ultra-strict, I'm not sure which one should be updated to match the other.
msg173132 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-17 05:52
Oh, and another "quirk" I noticed yesterday.  I usually religiously disable atime on all my filesystems.  For whatever reason, it's not disabled on this Solaris 10 box.

Turns out os.stat() was updating st_atime, which kind of throws a spanner in the works for all our st_atime tests in _test_utime() -- we call os.stat() after utime() to check that our atime update worked -- but the stat call results in another st_atime update.
msg173148 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2012-10-17 09:49
I don't know POSIX / UNIX all that well.  Does it require that a stat call updates atime?  Because that's one of those "how does it ever work" head-scratchers.  (Maybe everybody always disables atime these days?  I don't think I do.)
msg173149 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-10-17 09:55
> I don't know POSIX / UNIX all that well.  Does it require that a stat
> call updates atime?  Because that's one of those "how does it ever
> work" head-scratchers.  (Maybe everybody always disables atime these
> days?  I don't think I do.)

I think most Linux distributions disable it for you; or, rather, they
use the "relatime" mount option which is a smart cheat:

relatime
    Update  inode  access  times  relative  to  modify  or change time.
    Access time is only updated if the previous access time was earlier
    than  the  current  modify or change time. (Similar to noatime, but
    doesn't break mutt or other applications that need  to  know  if  a
    file has been read since the last time it was modified.)
msg173150 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-17 09:57
Re: "how did it ever work"... on Solaris, because of the st_mtime failure, it doesn't even get a chance to fail on the subsequent st_atime.  I suspect the only platform that's exercised the utimensat() to date is Linux, and either a) os.stat() doesn't affect atime on Linux, b) everyone has atime disabled, c) the two stat calls happen quick enough that no measurable difference is observed against st_atime.

As for POSIX:

http://pubs.opengroup.org/onlinepubs/9699919799/toc.htm

"The fstat() function shall update any time-related fields (as described in XBD File Times Update ), before writing into the stat structure."

The referenced section:

4.8 File Times Update

Each file has three distinct associated timestamps: the time of last data access, the time of last data modification, and the time the file status last changed. These values are returned in the file characteristics structure struct stat, as described in <sys/stat.h> .

Each function or utility in POSIX.1-2008 that reads or writes data (even if the data does not change) or performs an operation to change file status (even if the file status does not change) indicates which of the appropriate timestamps shall be marked for update. If an implementation of such a function or utility marks for update one of these timestamps in a place or time not specified by POSIX.1-2008, this shall be documented, except that any changes caused by pathname resolution need not be documented. For the other functions or utilities in POSIX.1-2008 (those that are not explicitly required to read or write file data or change file status, but that in some implementations happen to do so), the effect is unspecified.

An implementation may update timestamps that are marked for update immediately, or it may update such timestamps periodically. At the point in time when an update occurs, any marked timestamps shall be set to the current time and the update marks shall be cleared. All timestamps that are marked for update shall be updated when the file ceases to be open by any process or before a fstat(), fstatat(), fsync(), futimens(), lstat(), stat(), utime(), utimensat(), or utimes() is successfully performed on the file. Other times at which updates are done are unspecified. Marks for update, and updates themselves, shall not be done for files on read-only file systems; see Read-Only File System .

The resolution of timestamps of files in a file system is implementation-defined, but shall be no coarser than one-second resolution. The three timestamps shall always have values that are supported by the file system. Whenever any of a file's timestamps are to be set to a value V according to the rules of the preceding paragraphs of this section, the implementation shall immediately set the timestamp to the greatest value supported by the file system that is not greater than V.
msg173151 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-17 10:05
Here's a thought...  why not alter the test to work with fixed times and separate the atime tests from the mtime tests.

For atime, we can set utime(filename, (0.0, ...)) and see if a subsequent os.stat() returns st_atime as 0.0 -- that'll tell us whether or not atime is affected.

For the mtime tests, rather than having a variable UTIME_EPSILON, just have fixed dates that match the expected precision of the underlying platform?
msg173337 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-19 13:04
Larry and I just chatted about this on IRC.  Summary:

 1.)  I was wrong about os.stat() affecting atime.  I fired up a
      console session on Solaris to "prove" my atime observation
      only to find os.stat() had no impact on atime:

        % ./python
        Python 2.7.3+ (2.7:90a46f8943d0, Oct 18 2012, 11:09:15) [C] on sunos5
        Type "help", "copyright", "credits" or "license" for more information.
        >>> import os
        >>> fname = 'configure'
        >>> st0 = os.stat(fname)
        >>> os.utime(fname, (st0.st_atime, st0.st_mtime))
        >>> st0.st_atime
        1350571183.474864
        >>> st1 = os.stat(fname)
        >>> st1.st_atime
        1350571183.474864

      So, we can ignore my "but os.stat() affects atime!" noise
      earlier in this report.

 2.)  Regardless of the underlying platform, the unit tests should
      test utime() with nano, micro and second resolution.  However,
      the tests should be cognizant of the underlying platform's
      os.stat() versus os.utime() resolution when testing the actual
      results.

      That is, if you pass a nanosecond time to os.utime() on a platform
      that doesn't have underlying nanosecond support for utime (i.e. no
      utimensat()), then expect a microsecond resolution time back from
      stat().

 3.)  Regarding fixed times versus re-setting the first results of our
      stat() call: no strong opinion either way -- the main objective
      is to ensure the tests have good coverage and are robust.  So
      whatever gets the job done.
msg173341 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-19 13:18
On Tue, Oct 16, 2012 at 10:46:34PM -0700, Trent Nelson wrote:
> 
> Trent Nelson added the comment:
> 
> Thanks for the feedback Larry; yeah that patch definitely wasn't
> intended to be "production quality" -- more of a proof of concept.  I
> agree with your points, they'll be factored into the next patch.
> 
> However, I'm absolutely baffled by the Solaris 10 failure.  The more I
> looked into it, the weirder it got.  The issue is always the same:
> 
>     self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
>     AssertionError: 1347752941.275297 != 1347752941.275296
> 
> That is, test_utime() always results in a st1.st_mtime that is
> "off-by-1" from st0.st_mtime.  The precision is well within the
> nanasecond resolution offered by utimensat, so it doesn't appear to be
> the same issue experienced by other platforms.

    I've concluded that the problem on Solaris is actually unrelated
    to the original failures on FreeBSD and NetBSD that this issue
    was raised for (where os.stat() returns nanosecond resolution but
    os.utime() only accepts microsecond).

    I've raised a separate bug for this issue: #16287.
msg176881 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2012-12-04 08:46
I didn't read the whole issue, but the following code makes sense.

+try:
+    import posix
+except ImportError:
+    # Windows has nanosecond utime resolution.
+    UTIME_EPSILON = 2e-9
+else:
+    import sysconfig
+    if 'HAVE_UTIMENSAT' in posix._have_functions:
+        UTIME_EPSILON = 2e-9
+    elif 'HAVE_UTIMES' in sysconfig.get_config_vars():
+        UTIME_EPSILON = 2e-6
+    else:
+        UTIME_EPSILON = 1.0

Windows doesn't really have nanosecond resolution: the common Windows unit is 100 ns. See GetFileInformationByHandle() documentation: its BY_HANDLE_FILE_INFORMATION  structure has FILETIME fields, and FILETIME uses the 100 ns unit.

We might expose this unit (UTIME_EPSILON, in the os module maybe?) as we done for time function with time.get_clock_info().
msg187495 - (view) Author: koobs (koobs) Date: 2013-04-21 06:46
There's some work that's been in the FreeBSD bleachers since Jul 2012 to add futimens() and utimensat(), with some recent activity:

RFC: futimens(2) and utimensat(2) - Jul 2012
http://lists.freebsd.org/pipermail/freebsd-arch/2012-February/012409.html 

RFC: futimens(2) and utimensat(2) - Jan 2013
http://lists.freebsd.org/pipermail/freebsd-arch/2013-January/013903.html 

I've also recently been made aware of a vfs.timestamp_precision sysctl and tested adjusting it from it's default of 0 -> 3, without success:

sysctl -d vfs.timestamp_precision
vfs.timestamp_precision: File timestamp precision (0: seconds, 1: sec + ns accurate to 1/HZ, 2: sec + ns truncated to ms, 3+: sec + ns (max. precision))

I'll do my best at this end to encourage the above implementation to be committed and request merges to other branches of FreeBSD (likely just 9-STABLE)

In the meantime however, what can be done in the short-term to either tweak the tests so they pass or account for the difference in implementations?

The current test failures on the buildbots make it difficult at best to ensure core developers are being notified or exposed to other regressions and issues that have cropped up in recent months.
msg190076 - (view) Author: koobs (koobs) Date: 2013-05-26 11:08
I've moved both of the FreeBSD buildbot slaves off their ZFS-backed home directories and back to good old UFS.

I want to ensure FreeBSD support continues to improve, and having slaves get noticed when they fail or regress with ongoing development is a big part of that.

This is hard to achieve without movement on this issue, either in the form of a conditional skip, workaround or ultimate resolution
msg190077 - (view) Author: koobs (koobs) Date: 2013-05-26 11:15
I'm happy to move them back upon request, or create a FreeBSD/ZFS buildslave specially for the job, just let me know.
History
Date User Action Args
2013-05-27 13:34:17Ed.Mastesetnosy: + Ed.Maste
2013-05-26 11:15:01koobssetmessages: + msg190077
2013-05-26 11:08:14koobssetmessages: + msg190076
2013-04-21 06:46:22koobssetnosy: + koobs
messages: + msg187495
2012-12-05 12:15:26jceasetnosy: + jcea
2012-12-04 08:46:58hayposetnosy: + haypo
messages: + msg176881
2012-10-19 13:18:08trentsetmessages: + msg173341
title: Numerous utime ns tests fail on FreeBSD w/ ZFS -> Numerous utime ns tests fail on FreeBSD w/ ZFS (update: and NetBSD w/ FFS, Solaris w/ UFS)
2012-10-19 13:04:32trentsetmessages: + msg173337
title: Numerous utime ns tests fail on FreeBSD w/ ZFS (update: and NetBSD w/ FFS, Solaris w/ UFS) -> Numerous utime ns tests fail on FreeBSD w/ ZFS
2012-10-17 10:05:21trentsetmessages: + msg173151
2012-10-17 09:57:37trentsetmessages: + msg173150
2012-10-17 09:55:56pitrousetmessages: + msg173149
2012-10-17 09:49:30larrysetmessages: + msg173148
2012-10-17 05:52:56trentsetmessages: + msg173132
2012-10-17 05:46:34trentsetmessages: + msg173131
2012-10-17 04:38:16larrysetmessages: + msg173130
2012-10-16 21:40:48trentsetfiles: + test_os.patch
keywords: + patch
messages: + msg173102
2012-10-16 21:09:32Arfreversetnosy: + Arfrever
2012-10-16 21:03:48trentsetmessages: + msg173094
2012-10-16 20:59:02larrysetmessages: + msg173092
2012-10-16 20:04:44trentsetmessages: + msg173087
2012-09-18 12:58:57trentsettitle: Numerous utime ns tests fail on FreeBSD w/ ZFS -> Numerous utime ns tests fail on FreeBSD w/ ZFS (update: and NetBSD w/ FFS, Solaris w/ UFS)
2012-09-18 03:03:47trentsetmessages: + msg170631
2012-08-23 00:34:38larrysetmessages: + msg168911
2012-08-22 17:04:35pitrousetnosy: + pitrou
messages: + msg168898
2012-08-22 13:11:14trentsetmessages: + msg168883
2012-08-22 00:03:26trentsetmessages: + msg168828
2012-08-21 23:38:22larrysetmessages: + msg168822
2012-08-21 22:06:05trentsetmessages: + msg168811
2012-08-21 21:52:05larrysetmessages: + msg168808
2012-08-21 13:45:05skrahsetmessages: + msg168770
2012-08-21 13:00:27pitrousetnosy: + skrah
2012-08-21 11:51:24hayposetnosy: + larry
2012-08-21 02:15:34trentcreate