[BUG] t7063-status-untracked-cache flaky?

[BUG] t7063-status-untracked-cache flaky?

[Lars Schneider]

Hi,

I noticed that "t7063-status-untracked-cache.sh" occasionally fails with "not ok 24 - test sparse status with untracked cache".

E.g. on OS X compiled with gcc:
https://travis-ci.org/larsxschneider/git/jobs/85432514

E.g. on Linux compiled with gcc:
https://travis-ci.org/larsxschneider/git/jobs/84986975

The test was added with commit 7687252. I have not really investigated the problem yet but the "avoid_racy" method caught my attention. Is this test known to be flaky? Would an increased sleep time in "avoid_racy" help?

Thanks,
Lars

Re: [BUG] t7063-status-untracked-cache flaky?

[David Turner]

On Thu, 2015-10-15 at 09:52 +0200, Lars Schneider wrote:
> Hi,
> 
> I noticed that "t7063-status-untracked-cache.sh" occasionally fails with "not ok 24 - test sparse status with untracked cache".
> 
> E.g. on OS X compiled with gcc:
> https://travis-ci.org/larsxschneider/git/jobs/85432514
> 
> E.g. on Linux compiled with gcc:
> https://travis-ci.org/larsxschneider/git/jobs/84986975
> 
> The test was added with commit 7687252. I have not really investigated the problem yet but the "avoid_racy" method caught my attention. Is this test known to be flaky? Would an increased sleep time in "avoid_racy" help?

I've never seen this test be flaky before your report.  I just tested
it, locally, though, and I can reproduce.  After 53 successes, it
failed.  Will investigate further.

Re: [BUG] t7063-status-untracked-cache flaky?

[Torsten Bögershausen]

I can't reproduce it here.
Do you want to give us some info about your setup ?
OS ?
Harddisk, SSD, Fusion ?
Does "debug=t verbose=t ./t7063-status-untracked-cache.sh >xx.txt 2>&1" 
give any more information ?


On 15.10.15 09:52, Lars Schneider wrote:
> Hi,
> 
> I noticed that "t7063-status-untracked-cache.sh" occasionally fails with "not ok 24 - test sparse status with untracked cache".

Re: [BUG] t7063-status-untracked-cache flaky?

[David Turner]

On Fri, 2015-10-16 at 17:22 +0200, Torsten Bögershausen wrote:
> On 15.10.15 09:52, Lars Schneider wrote:
> > Hi,
> > 
> > I noticed that "t7063-status-untracked-cache.sh" occasionally fails with "not ok 24 - test sparse status with untracked cache".
>
> I can't reproduce it here.
> Do you want to give us some info about your setup ?
> OS ?
> Harddisk, SSD, Fusion ?
> Does "debug=t verbose=t ./t7063-status-untracked-cache.sh >xx.txt
2>&1" 
> give any more information ?

(rearranged to bottom-post)

The problem is:

trash directory.t7063-status-untracked-cache$ diff trace trace.expect 
3,4c3,4
< directory invalidation: 1
< opendir: 1
---
> directory invalidation: 2
> opendir: 2


I can repro on a SSD.

I had to try many times to reproduce (I think even more the second
time). I just ran the test in a while loop until it failed.

I suspect that the kernel might be a bit slow to update the mtime on the
directory, but I have not yet been able to repro, and I don't understand
why it only happens in this one test, since sparseness should be
completely unrelated.

Re: [BUG] t7063-status-untracked-cache flaky?

[Junio C Hamano]

David Turner <dturner@twopensource.com> writes:

> The problem is:
>
> trash directory.t7063-status-untracked-cache$ diff trace trace.expect 
> 3,4c3,4
> < directory invalidation: 1
> < opendir: 1
> ---
>> directory invalidation: 2
>> opendir: 2
>
>
> I can repro on a SSD.
>
> I had to try many times to reproduce (I think even more the second
> time). I just ran the test in a while loop until it failed.
>
> I suspect that the kernel might be a bit slow to update the mtime on the
> directory, but I have not yet been able to repro, and I don't understand
> why it only happens in this one test, since sparseness should be
> completely unrelated.

If you are invalidating your cache based on mtime of the directory,
an operation within mtime granularity can cause you to miss it,
unless you try to be conservative and do the "assume invalid if
racy".  And if you do "assume invalid if racy", the result will
become timing dependent.  You may end up invalidating more than
absolutely necessary, i.e. the test writer may have known that at
least 1 must be definitely stale at that point in the test, but
if another directory was iffy and the code played safe, you would
see one more invalidation than expected (which would lead to
scanning the directory, hence one more opendir).

Is that what is going on here?

Re: [BUG] t7063-status-untracked-cache flaky?

[David Turner]

On Fri, 2015-10-16 at 13:34 -0700, Junio C Hamano wrote:
> David Turner <dturner@twopensource.com> writes:
> 
> > The problem is:
> >
> > trash directory.t7063-status-untracked-cache$ diff trace trace.expect 
> > 3,4c3,4
> > < directory invalidation: 1
> > < opendir: 1
> > ---
> >> directory invalidation: 2
> >> opendir: 2
> >
> >
> > I can repro on a SSD.
> >
> > I had to try many times to reproduce (I think even more the second
> > time). I just ran the test in a while loop until it failed.
> >
> > I suspect that the kernel might be a bit slow to update the mtime on the
> > directory, but I have not yet been able to repro, and I don't understand
> > why it only happens in this one test, since sparseness should be
> > completely unrelated.
> 
> If you are invalidating your cache based on mtime of the directory,
> an operation within mtime granularity can cause you to miss it,
> unless you try to be conservative and do the "assume invalid if
> racy".  And if you do "assume invalid if racy", the result will
> become timing dependent.  You may end up invalidating more than
> absolutely necessary, i.e. the test writer may have known that at
> least 1 must be definitely stale at that point in the test, but
> if another directory was iffy and the code played safe, you would
> see one more invalidation than expected (which would lead to
> scanning the directory, hence one more opendir).
> 
> Is that what is going on here?

The test has a sleep to avoid this.  Looking at it, I think it just
needs one more sleep.  Testing now; if correct, I'll send a patch.