# [BUG] t7063-status-untracked-cache flaky? 6 messages from 2015-10-15 to 2015-10-16. Participants: Lars Schneider, David Turner, Torsten Bögershausen, Junio C Hamano. Thread: https://gitlist.dev/t/40564 ## Lars Schneider, 2015-10-15 07:52 Subject: [BUG] t7063-status-untracked-cache flaky? Message-ID: <326E1A8B-3612-4771-80B8-77346C0D762D@gmail.com> URL: https://gitlist.dev/e/326E1A8B-3612-4771-80B8-77346C0D762D%40gmail.com ``` 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 ``` ## David Turner, 2015-10-15 19:44 Subject: Re: [BUG] t7063-status-untracked-cache flaky? Message-ID: <1444938244.20887.6.camel@twopensource.com> URL: https://gitlist.dev/e/1444938244.20887.6.camel%40twopensource.com In-Reply-To: <326E1A8B-3612-4771-80B8-77346C0D762D@gmail.com> ``` 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. ``` ## Torsten Bögershausen, 2015-10-16 15:22 Subject: Re: [BUG] t7063-status-untracked-cache flaky? Message-ID: <56211619.3090907@web.de> URL: https://gitlist.dev/e/56211619.3090907%40web.de In-Reply-To: <326E1A8B-3612-4771-80B8-77346C0D762D@gmail.com> ``` 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". ``` ## David Turner, 2015-10-16 20:11 Subject: Re: [BUG] t7063-status-untracked-cache flaky? Message-ID: <1445026298.20887.28.camel@twopensource.com> URL: https://gitlist.dev/e/1445026298.20887.28.camel%40twopensource.com In-Reply-To: <56211619.3090907@web.de> ``` 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. ``` ## Junio C Hamano, 2015-10-16 20:34 Subject: Re: [BUG] t7063-status-untracked-cache flaky? Message-ID: URL: https://gitlist.dev/e/xmqqfv1aeena.fsf%40gitster.mtv.corp.google.com In-Reply-To: <1445026298.20887.28.camel@twopensource.com> ``` David Turner 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? ``` ## David Turner, 2015-10-16 21:25 Subject: Re: [BUG] t7063-status-untracked-cache flaky? Message-ID: <1445030740.20887.33.camel@twopensource.com> URL: https://gitlist.dev/e/1445030740.20887.33.camel%40twopensource.com In-Reply-To: ``` On Fri, 2015-10-16 at 13:34 -0700, Junio C Hamano wrote: > David Turner 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. ```