t7063 failure on FreeBSD 10.3 i386/amd64

Not sure what's going on, below is the relevant output when run with -i -v --tee (the rest succeeds without -i):

ok 26 - untracked cache correct after status

expecting success:

	avoid_racy &&
	: >../trace &&
	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
	git status --porcelain >../status.actual &&
	cat >../status.expect <<EOF &&

M done/two
?? .gitignore
?? done/five
?? dtwo/
EOF

	test_cmp ../status.expect ../status.actual &&
	cat >../trace.expect <<EOF &&

node creation: 0
gitignore invalidation: 0
directory invalidation: 0
opendir: 0
EOF
test_cmp ../trace.expect ../trace

trace renamed from trace.expect +2 -2

@@ -1,4 +1,4 @@
 node creation: 0
 gitignore invalidation: 0
-directory invalidation: 0
-opendir: 0
+directory invalidation: 1
+opendir: 1

not ok 27 - test sparse status again with untracked cache

Oops, forgot to Cc some folks who worked on this :x

Filesystem is ufs and it fails regardless of whether soft-updates is enabled or not.

Quoted 4 lines · Eric Wong

Oops, forgot to Cc some folks who worked on this :x

Filesystem is ufs and it fails regardless of whether soft-updates is enabled or not.

Nothing stands out to my eyes, so I'm going to install freebsd this weekend. I hope ufs does not have any nasty surprise for me. Stay tuned.

Quoted 9 lines · Duy Nguyen

Quoted 4 lines · Eric Wong

Oops, forgot to Cc some folks who worked on this :x

Filesystem is ufs and it fails regardless of whether soft-updates is enabled or not.

Nothing stands out to my eyes, so I'm going to install freebsd this weekend. I hope ufs does not have any nasty surprise for me. Stay tuned.

Thanks, this problem might be ufs-specific, tmpfs is fine. Tested tmpfs with:

kldload tmpfs
mkdir /tmp/tmpfs
mount -t tmpfs tmpfs /tmp/tmpfs

(Documenting all this since much of this is new to me)

I noticed FreeBSD now provides ready-to-run VM images along with normal installation stuff, including qcow2 ones for QEMU users, so that saves some time.

http://ftp.freebsd.org/pub/FreeBSD/releases/VM-IMAGES/10.3-RELEASE/amd64/Latest/FreeBSD-10.3-RELEASE-amd64.qcow2.xz

Quoted 4 lines · Eric Wong

Oops, forgot to Cc some folks who worked on this :x

Filesystem is ufs and it fails regardless of whether soft-updates is enabled or not.

Nothing stands out to my eyes, so I'm going to install freebsd this weekend. I hope ufs does not have any nasty surprise for me. Stay tuned.

Quoted 9 lines · Duy Nguyen

Quoted 4 lines · Eric Wong

Oops, forgot to Cc some folks who worked on this :x

Filesystem is ufs and it fails regardless of whether soft-updates is enabled or not.

Nothing stands out to my eyes, so I'm going to install freebsd this weekend. I hope ufs does not have any nasty surprise for me. Stay tuned.

The good news is it looks like a false alarm due to a racy test (and it happens on ext2 too, zfs not tested), no big flaw or anything (phew!). The bad news is, I still have no idea what's happening and why is_racy_stat() returns true in this particular case. It'll take some more time...

I give up.

Let's start with the commit message of [1] from freebsd.git [2]

Sync timestamp changes for inodes of special files to disk as late as possible (when the inode is reclaimed). Temporarily only do this if option UFS_LAZYMOD configured and softupdates aren't enabled. UFS_LAZYMOD is intentionally left out of /sys/conf/options.

This is mainly to avoid almost useless disk i/o on battery powered machines. It's silly to write to disk (on the next sync or when the inode becomes inactive) just because someone hit a key or something wrote to the screen or /dev/null.

PR: 5577 [3]

The short version of that, in the context of t7063, is that when a directory is updated, its mtime may be updated later, not immediately. This can be shown with a simple command sequence

date; sleep 1; touch abc; rm abc; sleep 10; ls -lTd .

One would expect that the date shown in ls would be one second from date, but it's 10 seconds later. If we put another ls -lTd . in front of sleep 10, then the date of the last ls comes as expected. The first ls somehow forces mtime to be updated.

t7063 is really sensitive to directory mtime. When mtime is too "new", git code suspects racy timestamps and will not trigger the shortcut in untracked cache, in t7063.26 (or t7063.25 before this patch) and eventually be detected in t7063.28

We have two options thanks to this special FreeBSD feature:

1) Stop supporting untracked cache on FreeBSD. Skip t7063 entirely when running on FreeBSD

2) Work around this problem (using the same 'ls' trick) and continue to support untracked cache on FreeBSD

I initially wanted to go with 1) because I didn't know the exact nature of this feature and feared that it would make untracked cache work unreliably, using the cached version when it should not.

Since the behavior of this thing is clearer now. The picture is not that bad. If this indeed happens often, untracked cache would assume racy condition more often and _fall back_ to non-untracked cache code paths. Which means it may be less effective, but it will not show wrong things.

This patch goes with option 2.

PS. For those who want to look further in FreeBSD source code, this flag is now called IN_LAZYMOD. I can see it's effective in ext2 and ufs. zfs is questionable.

[1] 660e6408e6df99a20dacb070c5e7f9739efdf96d
[2] git://github.com/freebsd/freebsd.git
[3] https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=5577

Reported-by Eric Wong <[email protected]>

Signed-off-by Nguyễn Thái Ngọc Duy <[email protected]>

---
This is only of those commits that commit messages are more important than the patch itself. One of the good notes about directory mtime, if we start to use it in more places in git.

 t/t7063-status-untracked-cache.sh | 4 ++++
 t/test-lib.sh                     | 6 ++++++
 2 files changed, 10 insertions(+)

t/t7063-status-untracked-cache.sh +0 -0

index a971884..08fc586 100755

t/t7063-status-untracked-cache.sh test_expect_success 'create/modify files, some of which are gitignored' ' · line 424

Quoted 3 lines · Nguyễn Thái Ngọc Duy

t/t7063-status-untracked-cache.sh +3 -0

+test_expect_success FREEBSD 'Work around lazy mtime update' '
+	ls -ld . >/dev/null
+'

stat . >/dev/null

would be more to the point of what is going on, here. But I
also wonder if untracked cache itself could/should be doing this internally.

(I'm not familiar with that code, of course)

Thanks again for looking into this.

Quoted 3 lines

would be more to the point of what is going on, here. But I
also wonder if untracked cache itself could/should be doing this internally.

Still wondering :>

Am 30.07.2016 um 15:20 schrieb Nguyễn Thái Ngọc Duy <[email protected]>:

Let's start with the commit message of [1] from freebsd.git [2]

Sync timestamp changes for inodes of special files to disk as late as possible (when the inode is reclaimed). Temporarily only do this if option UFS_LAZYMOD configured and softupdates aren't enabled. UFS_LAZYMOD is intentionally left out of /sys/conf/options.

This is mainly to avoid almost useless disk i/o on battery powered machines. It's silly to write to disk (on the next sync or when the inode becomes inactive) just because someone hit a key or something wrote to the screen or /dev/null.

   PR:             5577 [3]

The short version of that, in the context of t7063, is that when a directory is updated, its mtime may be updated later, not immediately. This can be shown with a simple command sequence

date; sleep 1; touch abc; rm abc; sleep 10; ls -lTd .

One would expect that the date shown in ls would be one second from date, but it's 10 seconds later. If we put another ls -lTd . in front of sleep 10, then the date of the last ls comes as expected. The first ls somehow forces mtime to be updated.

t7063 is really sensitive to directory mtime. When mtime is too "new", git code suspects racy timestamps and will not trigger the shortcut in untracked cache, in t7063.26 (or t7063.25 before this patch) and eventually be detected in t7063.28

We have two options thanks to this special FreeBSD feature:

1) Stop supporting untracked cache on FreeBSD. Skip t7063 entirely when running on FreeBSD

2) Work around this problem (using the same 'ls' trick) and continue to support untracked cache on FreeBSD

I initially wanted to go with 1) because I didn't know the exact nature of this feature and feared that it would make untracked cache work unreliably, using the cached version when it should not.

Since the behavior of this thing is clearer now. The picture is not that bad. If this indeed happens often, untracked cache would assume racy condition more often and _fall back_ to non-untracked cache code paths. Which means it may be less effective, but it will not show wrong things.

This patch goes with option 2.

PS. For those who want to look further in FreeBSD source code, this flag is now called IN_LAZYMOD. I can see it's effective in ext2 and ufs. zfs is questionable.

[1] 660e6408e6df99a20dacb070c5e7f9739efdf96d
[2] git://github.com/freebsd/freebsd.git
[3] https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=5577

Reported-by Eric Wong <[email protected]>

Signed-off-by Nguyễn Thái Ngọc Duy <[email protected]>

---
This is only of those commits that commit messages are more important than the patch itself. One of the good notes about directory mtime, if we start to use it in more places in git.

t/t7063-status-untracked-cache.sh | 4 ++++
t/test-lib.sh | 6 ++++++

2 files changed, 10 insertions(+)

t/t7063-status-untracked-cache.sh +0 -0

index a971884..08fc586 100755
@@ -419,6 +419,10 @@ test_expect_success 'create/modify files, some of which are gitignored' '
   rm base

'

the term FREEBSD may be too generic to point out a single feature in an OS distributution.
Following your investigations, it may even be possible that other systems adapt this "feature"?

How about
LAZY_DIR_MTIME_UPDATE
(or similar)

Quoted 5 lines · Torstem Bögershausen

the term FREEBSD may be too generic to point out a single feature in an OS distributution.
Following your investigations, it may even be possible that other systems adapt this "feature"?

Quoted 3 lines

How about
LAZY_DIR_MTIME_UPDATE
(or similar)

This feature was added in 1998, so yes there's a chance it has spread to a few fbsd derivatives (not sure if openbsd or netbsd is close enough and they ever exchange changes). But I'd rather wait for the second OS to expose the same feature before renaming it.

Quoted 6 lines · Duy Nguyen

Quoted 5 lines · Torstem Bögershausen

the term FREEBSD may be too generic to point out a single feature in an OS distributution.
Following your investigations, it may even be possible that other systems adapt this "feature"?

Quoted 8 lines

Quoted 3 lines

How about
LAZY_DIR_MTIME_UPDATE
(or similar)

This feature was added in 1998, so yes there's a chance it has spread to a few fbsd derivatives (not sure if openbsd or netbsd is close enough and they ever exchange changes). But I'd rather wait for the second OS to expose the same feature before renaming it.

I think a name based on the observed behaviour ("feature") would be more appropriate because I'd be more worried about us finding other glitches we see (initially) only on FBSD. People who need to adjust tests that use the same FBSD prereq would have to wonder which prereq-skip is due to which glitch.

OK how about this squashed in? The name was taken from fbsd definition IN_LAZYMOD.

Off topic. Since I found this macro defined twice, in ext2 and ufs, but not in zfs (found its source!), I assume zfs does not have this particular feature (but I didn't test it). Untracked cache may be more effecient there.

-- 8< --

t/t7063-status-untracked-cache.sh +1 -1

index 08fc586..8bb048a 100755
@@ -419,7 +419,7 @@ test_expect_success 'create/modify files, some of which are gitignored' '
 	rm base
 '
 
-test_expect_success FREEBSD 'Work around lazy mtime update' '
+test_expect_success LAZYMOD 'Work around lazy mtime update' '
 	ls -ld . >/dev/null
 '
 

t/test-lib.sh +1 -3

index 3c730a2..1fc5266 100644
@@ -962,7 +962,7 @@ case $(uname -s) in
 	test_set_prereq GREP_STRIPS_CR
 	;;
 *FreeBSD*)
-	test_set_prereq FREEBSD
+	test_set_prereq LAZYMOD
 	test_set_prereq POSIXPERM
 	test_set_prereq BSLASHPSPEC
 	test_set_prereq EXECKEEPSPID
-- 8< --
 
--

Duy

v2 goes with Junio's suggestion (good one!).

t/t7063-status-untracked-cache.sh +12 -1

+# On some filesystems (e.g. FreeBSD's ext2 and ufs) this and that
+# happens when we do blah, which forces the untracked cache code to
+# take the slow path.  A test that wants to make sure the fast path
+# works correctly should call this helper to make mtime of the
+# containing directory in sync with the reality after doing blah and
+# before checking the fast path behaviour
+sync_mtime () {
+	find . -type d -exec ls -ld {} \; >/dev/null
+}
+
 avoid_racy() {
 	sleep 1
 }

@@ -416,7 +426,8 @@ test_expect_success 'create/modify files, some of which are gitignored' '
 	echo four >done/four && # four is gitignored at a higher level
 	echo five >done/five && # five is not gitignored
 	echo test >base && #we need to ensure that the root dir is touched
-	rm base
+	rm base &&
+	sync_mtime
 '
 
 test_expect_success 'test sparse status with untracked cache' '

Quoted 1 line · Nguyễn Thái Ngọc Duy

v2 goes with Junio's suggestion (good one!).

Ehh, have you even read what you copied and pasted? "this and that" and "blah" are meant to be placeholders for you to fill in.

I am not sure if "-exec ls -ld" is a good idea. Doesn't "find" by itself does enough lstat(2) call to work already?

Even if it were
necessary to trigger a separate stat(2) call, wouldn't "-ls" be sufficient?

v3 differs from v2 in one line

    --- a/t/t7063-status-untracked-cache.sh
    +++ b/t/t7063-status-untracked-cache.sh
    @@ -11,7 +11,7 @@ test_description='test untracked cache'
     # containing directory in sync with the reality after doing blah and
     # before checking the fast path behaviour
     sync_mtime () {
    -   find . -type d -exec ls -ld {} \; >/dev/null
    +   find . -type d -ls >/dev/null
     }

t/t7063-status-untracked-cache.sh +12 -2

+# On some filesystems (e.g. FreeBSD's ext2 and ufs) this and that
+# happens when we do blah, which forces the untracked cache code to
+# take the slow path.  A test that wants to make sure the fast path
+# works correctly should call this helper to make mtime of the
+# containing directory in sync with the reality after doing blah and
+# before checking the fast path behaviour
+sync_mtime () {
+       find . -type d -ls >/dev/null
+}
+
 avoid_racy() {
        sleep 1
 }

@@ -416,7 +426,8 @@ test_expect_success 'create/modify files, some of which are gitignored' '
        echo four >done/four && # four is gitignored at a higher level
        echo five >done/five && # five is not gitignored
        echo test >base && #we need to ensure that the root dir is touched
-       rm base
+       rm base &&
+       sync_mtime
 '
 
 test_expect_success 'test sparse status with untracked cache' '
--

2.9.1.566.gbd532d4

If you mean to tell the user "I won't describe it in detail, if you really want to know,
go run blame yourself", spell it out like so. I was hoping that you can summarize
in-line there to help the readers here.

Quoted 5 lines · Junio C Hamano

If you mean to tell the user "I won't describe it in detail, if you really want to know,
go run blame yourself", spell it out like so. I was hoping that you can summarize
in-line there to help the readers here.

Here is a proposed fixup.

 t/t7063-status-untracked-cache.sh | 16 ++++++++++------
 1 file changed, 10 insertions(+), 6 deletions(-)

t/t7063-status-untracked-cache.sh +10 -6

index d31d080..e0a8228 100755
@@ -4,12 +4,16 @@ test_description='test untracked cache'
 
 . ./test-lib.sh
 
-# On some filesystems (e.g. FreeBSD's ext2 and ufs) this and that
-# happens when we do blah, which forces the untracked cache code to
-# take the slow path.  A test that wants to make sure the fast path
-# works correctly should call this helper to make mtime of the
-# containing directory in sync with the reality after doing blah and
-# before checking the fast path behaviour
+# On some filesystems (e.g. FreeBSD's ext2 and ufs) directory mtime
+# is updated lazily after contents in the directory changes, which
+# forces the untracked cache code to take the slow path.  A test
+# that wants to make sure that the fast path works correctly should
+# call this helper to make mtime of the containing directory in sync
+# with the reality before checking the fast path behaviour.
+#
+# See <[email protected]> if you want to know
+# more.
+
 sync_mtime () {
        find . -type d -ls >/dev/null
 }