[Gluster-users] fstat() sometimes sets ctime nanoseconds, sometimes not

[Vijay Bellur]

On 01/13/2014 08:27 PM, Alexander Kruppa wrote:
> Hello,
>
> I noticed strange behaviour with running tar on files stored on glusterfs. I did not set up the glusterfs, so I can't answer questions about details of its configuration, but I can easily contact the guy who can. The parameters printed by "mount" are:
>
> catrel-s1-ib:/catrel on /glusterfs type fuse.glusterfs (rw,relatime,user_id=0,group_id=0,default_permissions,allow_other,max_read=131072)
>
> As an example to demonstrate the problem, let's create a tar archive to contain the directory /glusterfs/test/, which contains a single file "foo":
>
> $ ls -l /glusterfs/test/
> total 216
> -rw-r--r-- 1 akruppa users 218658 Jan 13 13:29 foo
>
>
> Running tar results in the error message "file changed as we read it":
>
> $ tar cvf test.tar /glusterfs/test/
> tar: Removing leading `/' from member names
> /glusterfs/test/
> /glusterfs/test/foo
> tar: /glusterfs/test/foo: file changed as we read it
>
>
> Running tar 10 times on the directory, looking for the "file changed as we read it" error message, and waiting 1 second between each run:
>
> $ for I in `seq 10` ; do echo -n "$I: "; tar cvf test.tar /glusterfs/test/ 2>&1 | grep "file changed as we read it" || echo; sleep 1; done
> 1: tar: /glusterfs/kruppaal/test/foo: file changed as we read it
> 2: tar: /glusterfs/kruppaal/test/foo: file changed as we read it
> 3: tar: /glusterfs/kruppaal/test/foo: file changed as we read it
> 4: tar: /glusterfs/kruppaal/test/foo: file changed as we read it
> 5: tar: /glusterfs/kruppaal/test/foo: file changed as we read it
> 6: tar: /glusterfs/kruppaal/test/foo: file changed as we read it
> 7: tar: /glusterfs/kruppaal/test/foo: file changed as we read it
> 8: tar: /glusterfs/kruppaal/test/foo: file changed as we read it
> 9: tar: /glusterfs/kruppaal/test/foo: file changed as we read it
> 10: tar: /glusterfs/kruppaal/test/foo: file changed as we read it
>
>
> The same thing, but without waiting 1 second:
>
> $ for I in `seq 10` ; do echo -n "$I: "; tar cvf test.tar /glusterfs/test/ 2>&1 | grep "file changed as we read it" || echo; done
> 1: tar: /glusterfs/kruppaal/test/foo: file changed as we read it
> 2:
> 3:
> 4:
> 5:
> 6:
> 7:
> 8:
> 9:
> 10:
>
> So without the sleep 1, the tar runs except the first one seem to work. When specifying the file directly to tar, rather than the directory:
>
> $ for I in `seq 10` ; do echo -n "$I: "; tar cvf test.tar /glusterfs/test/foo 2>&1 | grep "file changed as we read it" || echo; sleep 1; done
> 1:
> 2:
> 3:
> 4:
> 5:
> 6:
> 7:
> 8:
> 9:
> 10:
>
> Now always seems to work. With a sleep time of 0.5 seconds instead of 1 second:
>
> $ for I in `seq 100` ; do echo -n "$I: "; tar cvf test.tar /glusterfs/test/ 2>&1 | grep "file changed as we read it" || echo; sleep 0.5; done
> 1: tar: /glusterfs/test/foo: file changed as we read it
> 2:
> 3: tar: /glusterfs/test/foo: file changed as we read it
> 4:
> 5: tar: /glusterfs/test/foo: file changed as we read it
> 6:
> 7: tar: /glusterfs/test/foo: file changed as we read it
> 8: ...
>
> It goes on like this, every other run fails. With a sleep time of 0.1, about every 10-th run fails.
>
> I modified tar to print the ctime it got from fstat() when the "file changed as we read it" occurs. The patch is below. With the modified tar, we find:
>
> $ ~/build/tar-1.26.my/src/tar cvf test.tar /glusterfs/test/
> /home/akruppa/build/tar-1.26.my/src/tar: Removing leading `/' from member names
> /glusterfs/test/
> /glusterfs/test/foo
> /home/akruppa/build/tar-1.26.my/src/tar: /glusterfs/test/foo: file changed as we read it
> original_ctime = (1389616142, 406799549), new_ctime = (1389616142, 0)
>
>
> It seems that fstat() sometimes fills in the nanosecond part of ctime, and sometimes not. The fact that the problem seems to depend on recent file accesses may hint at a metadata caching problem?
>

Interesting report. Which version of glusterfs is being used here?

md-cache (and stat-prefetch earlier) are the translators that perform 
metadata caching within glusterfs. Would it be possible to turn off this 
functionality by executing the following command on the server:

#gluster volume set <volname> stat-prefetch off

and then run the testcase again?

- Vijay