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.expect 2016-07-18 22:23:28.679886000 +0000 +++ ../trace 2016-07-18 22:23:28.677135000 +0000

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.

Eric Wong <e@80x24.org> wrote:

On Tue, Jul 19, 2016 at 12:54 AM, Eric Wong <e@80x24.org> wrote:

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.

Duy Nguyen <pclouds@gmail.com> wrote:

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

Notes:

* "-net user" because I'm lazy (ICMP ping won't work out-of-the-box)

* kvm can be substituted for qemu-system-$ARCH for the KVM-less
  or users lacking write access to /dev/kvm

* hostfwd=... allows me to ssh into port 22215 from my Linux host
  to hit port 22 in the guest

* "dhclient vtnet0 && pkg install git gettext gmake python libiconv"
  should be enough to get started

kvm -smp 8 -m 2048 \
	-drive if=virtio,file=FreeBSD-10.3-RELEASE-amd64.qcow2 \
	-net nic,model=virtio \
	-net user,hostfwd=tcp:127.0.0.1:22215-:22 \
	-display curses

On Wed, Jul 20, 2016 at 5:02 AM, Eric Wong <e@80x24.org> wrote:

If you can, try with some other "real" filesystems, not virtual ones like tmpfs, e.g. zfs or ext2 (not sure if it's supported on fbsd). This is just to make sure I didn't hit a bug specific to fbsd. Don't worry if you don't have time to do it. I'll get to it eventually.

Yeah that's what I'm going to do, but not right now..

On Tue, Jul 19, 2016 at 6:12 PM, Duy Nguyen <pclouds@gmail.com> wrote:

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...

On Wed, Jul 27, 2016 at 07:33:17PM +0200, Duy Nguyen wrote:

I give up. FreeBSD behaves so weird in this case.

The code of interest is this

    test_expect_success 'test sparse status with untracked cache' '
    	: >../trace &&
    	avoid_racy &&
    	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
    	git status --porcelain >../status.actual &&
    	...
    '

For some reason mtime of current directory is always latest time when git makes the stat call. Even if I make avoid_racy sleep longer, several seconds, mtime of "." will be the latest time.

But cwd stat info is _not_ supposed to change! We haven't touched it while avoid_racy is running. avoid_racy is just a wrapper of sleep. And sleep does not change cwd's mtime from the shell prompt. I tried running the script with bash too (suspecting problem with default shell) and replaced avoid_racy with /bin/sleep. Nothing.

Does our test framework run something in background??? No, it can't be.

If a stat call is made before avoid_racy, then mtime is pinned down and does not change anymore. So a "fix" is something like this. I tried a minimal program that just does "stat" to make sure it's stat that does it, not some side effect from 'ls'.

On Sat, Jul 30, 2016 at 3:31 PM, Duy Nguyen <pclouds@gmail.com> wrote:

I lied. Sleeping 30 seconds in that test case works, but there is no way I'm sending a patch to delay 30 seconds. FreeBSD must have some delayed mtime update "feature" in its vfs layer somewhere.

Now 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 <e@80x24.org>
Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 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(+)

Nguyễn Thái Ngọc Duy <pclouds@gmail.com> wrote:

Yikes. I guess FreeBSD doesn't have an in-memory inode cache it can keep up-to-date without flushing to disk?

Fwiw, `stat .` seems to have the same effect as `ls -lTd .`...

Thanks, Tested-by: Eric Wong <e@80x24.org>

	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.

Eric Wong <e@80x24.org> wrote:

If there's some older FreeBSD w/o stat(1); "test -x ." ought to work, too, and it's faster being a shell builtin.

I suspect some shell might be clever about optimizing away a more-obvious "test -d .", so I choose "test -x ."

Still wondering :>

On Sun, Jul 31, 2016 at 3:07 AM, Eric Wong <e@80x24.org> wrote:

There's nothing we can do besides maybe run a cron job executing 'sync' every second or so. We need to force mtime to be written down close to.. you know.. mtime. By the time git is executed, it's already late. You can execute 'sync' inside git then wait a couple seconds.. but that's just stupid. And removing the racy check is even more dangerous, now you can get false output.

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)

On Mon, Aug 1, 2016 at 3:37 AM, Torstem Bögershausen <tboegi@web.de> wrote:

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.

Duy Nguyen <pclouds@gmail.com> writes:

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.

On Mon, Aug 01, 2016 at 02:04:44PM -0700, Junio C Hamano wrote:

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< --

Duy Nguyen <pclouds@gmail.com> writes:

I am sorry that I didn't spot this possiblity earlier, but do we need anything conditional? Either FREEBSD or LAZYMOD prerequisite tells very little what the "Work around lazy mtime update" is and where it triggers (I think the conclusion of your investigation was that the timestamp on the containing directory, but that is ONLY recorded in the log message, i.e. readers need to run 'git blame' to find out).

It might be a better approach to have a helper function with descriptive name and comment early in t7063, e.g.

	# 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
	test_sync_directory_mtime () {
		ls -ld . >/dev/null
        }

and then call it at strategic places without any prerequisite.

The helper may turn out to be useful outside the context of 7063 later, at which time we can move it to test-lib-functions, but that is a separate step.

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.24 and eventually be detected in t7063.27

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 not affected.

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

Reported-by: Eric Wong <e@80x24.org>
Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 v2 goes with Junio's suggestion (good one!). And since there is an
 intention to reuse this new function, I make sure all directories are
 stat'd to pin down their mtime.

 t/t7063-status-untracked-cache.sh | 13 ++++++++++++-
 1 file changed, 12 insertions(+), 1 deletion(-)

Nguyễn Thái Ngọc Duy  <pclouds@gmail.com> writes:

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?

On Wed, Aug 3, 2016 at 6:16 PM, Junio C Hamano <gitster@pobox.com> wrote:

I did. But after a bit of consideration, I think the confusion caused by "this and that" would force the reader to blame and read the entire commit message.

Hmm.. because in some cases we could have dtype from readdir()?

Yep. Let me run some tests before sending v3.

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.24 and eventually be detected in t7063.27

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 not affected.

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

Reported-by: Eric Wong <e@80x24.org>
Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
---
 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
     }
 
 avoid_racy() {
 t/t7063-status-untracked-cache.sh | 13 ++++++++++++-
 1 file changed, 12 insertions(+), 1 deletion(-)

On Wed, Aug 3, 2016 at 10:45 AM, Nguyễn Thái Ngọc Duy <pclouds@gmail.com> wrote:

"this and that" and "blah" are still there.

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.

Junio C Hamano <gitster@pobox.com> writes:

Here is a proposed fixup.

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

On Wed, Aug 3, 2016 at 9:07 PM, Junio C Hamano <gitster@pobox.com> wrote:

Great! Sorry I only have one or two hours these days and could not propose something else quicker.