Alexander Kruppa
2014-Jan-13 14:57 UTC
[Gluster-users] fstat() sometimes sets ctime nanoseconds, sometimes not
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? Best regards, Alex Kruppa Patch against the GNU tar 1.26 sources (http://ftp.gnu.org/gnu/tar/): $ diff tar-1.26/src/create.c tar-1.26.my/src/create.c 1788c1788,1789 < if ((timespec_cmp (get_stat_ctime (&final_stat), original_ctime) != 0 ---> struct timespec new_ctime = get_stat_ctime (&final_stat); > if ((timespec_cmp (new_ctime, original_ctime) != 01796a1798,1800> fprintf (stderr, "original_ctime = (%ld, %ld), new_ctime = (%ld, %ld)\n", > (long) original_ctime.tv_sec, (long) original_ctime.tv_nsec, > (long) new_ctime.tv_sec, (long) new_ctime.tv_nsec);
Vijay Bellur
2014-Jan-13 17:47 UTC
[Gluster-users] fstat() sometimes sets ctime nanoseconds, sometimes not
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