[Gluster-devel] Issue about the size of fstat is less than the really size of the syslog file
Lian, George (Nokia - CN/Hangzhou)
george.lian at nokia.com
Wed Nov 2 04:56:08 UTC 2016
Hi,
Sorry, it seems the issue still there with readdir-ahead off.
# tail -f syslog >syslog.2.log
tail: syslog: file truncated
tail: syslog: file truncated
tail: syslog: file truncated
tail: syslog: file truncated
tail: syslog: file truncated
tail: syslog: file truncated
The last line is new truncated error message after the following set with option readdir-ahead.
# gluster volume set log performance.readdir-ahead off
volume set: success
[root at SN-0(RNC-124) /root]
# gluster volume info log
Volume Name: log
Type: Replicate
Volume ID: 9d987a23-1d64-4857-980a-548f1dd0d1e6
Status: Started
Number of Bricks: 1 x 2 = 2
Transport-type: tcp
Bricks:
Brick1: 169.254.0.12:/mnt/bricks/log/brick
Brick2: 169.254.0.13:/mnt/bricks/log/brick
Options Reconfigured:
performance.readdir-ahead: off
BRs
George
-----Original Message-----
From: gluster-devel-bounces at gluster.org [mailto:gluster-devel-bounces at gluster.org] On Behalf Of Raghavendra Gowdappa
Sent: Tuesday, November 01, 2016 9:29 PM
To: Raghavendra G <raghavendra at gluster.com>
Cc: Gluster-devel at gluster.org; Zizka, Jan (Nokia - CZ/Prague) <jan.zizka at nokia.com>; Zhang, Bingxuan (Nokia - CN/Hangzhou) <bingxuan.zhang at nokia.com>
Subject: Re: [Gluster-devel] Issue about the size of fstat is less than the really size of the syslog file
----- Original Message -----
> From: "Raghavendra G" <raghavendra at gluster.com>
> To: "Pranith Kumar Karampuri" <pkarampu at redhat.com>
> Cc: Gluster-devel at gluster.org, "Jan Zizka (Nokia - CZ/Prague)" <jan.zizka at nokia.com>, "Bingxuan Zhang (Nokia -
> CN/Hangzhou)" <bingxuan.zhang at nokia.com>
> Sent: Tuesday, November 1, 2016 6:55:31 PM
> Subject: Re: [Gluster-devel] Issue about the size of fstat is less than the really size of the syslog file
>
> Hi George,
>
> You can try your tests in two scenarios:
>
> 1. Switch off following performance translators:
> a. write-behind
> b. quick-read
> c. readdir-ahead
>
> Once you see that the issue goes away in the above scenario, you can apply
> write-behind fix [1] and turn write-behind on.
>
> We have a fix in quick-read at [2].
>
> You can also try to test with the quick-read fix and turning quick-read on.
> However, since your issue is stale stat I doubt quick-read is not the
s/quick-read is not the culprit/quick-read is the culprit/
> culprit here (The issue with quick-read is stale data).
>
> We see that readdir-ahead is not updating/flushing the stats stored along
> with dentries when write or file modifications happen. That seem to be the
> issue with readdir-ahead. For now, during both of the above two scenarios,
> please keep readdir-ahead off.
>
> [1] http://review.gluster.org/15757/2
> [2] http://review.gluster.org/#/c/15759/2
>
> regards,
> Raghavendra
>
> On Tue, Nov 1, 2016 at 7:55 AM, Pranith Kumar Karampuri < pkarampu at redhat.com
> > wrote:
>
>
>
>
>
> On Tue, Nov 1, 2016 at 7:32 AM, Lian, George (Nokia - CN/Hangzhou) <
> george.lian at nokia.com > wrote:
>
>
>
>
>
> Hi,
>
>
>
> I will test it with your patches and update to you when I have result.
>
> hi George,
> Please use http://review.gluster.org/#/c/15757/2 i.e. second version of
> Raghavendra's patch. I tested it and it worked fine. We are still trying to
> figure out quick-read and readdir-ahead as I type this mail.
>
>
>
>
>
>
>
>
>
>
> Thanks a lots
>
>
>
> Best Regards,
>
> George
>
>
>
> From: Pranith Kumar Karampuri [mailto: pkarampu at redhat.com ]
> Sent: Monday, October 31, 2016 11:23 AM
> To: Lian, George (Nokia - CN/Hangzhou) < george.lian at nokia.com >
> Cc: Raghavendra Gowdappa < rgowdapp at redhat.com >; Zhang, Bingxuan (Nokia -
> CN/Hangzhou) < bingxuan.zhang at nokia.com >; Gluster-devel at gluster.org ;
> Zizka, Jan (Nokia - CZ/Prague) < jan.zizka at nokia.com >
>
> Subject: Re: [Gluster-devel] Issue about the size of fstat is less than the
> really size of the syslog file
>
>
>
>
>
>
>
>
> Removing I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX at internal.nsn.com , it is causing
> mail delivery problems for me.
>
>
> George,
>
>
> Raghavendra and I made some progress on this issue. We were in parallel
> working on another issue which is similar where elastic search indices are
> getting corrupted because of wrong stat sizes in our opinion. So I have been
> running different translator stacks in identifying the problematic xlators
> which are leading to indices corruption.
>
>
> We found the list to be 1) Write-behind, 2) Quick-read, 3) Readdir-ahead.
> Raghavendra and I just had a chat and we are suspecting that lack of
> lookup/readdirp implementation in write-behind could be the reason for this
> problem. Similar problems may exist in other two xlators too. But we are
> working on write-behind with priority.
>
>
> Our theory is this:
>
>
> If we do a 4KB write for example and it is cached in write-behind and we do a
> lookup on the file/do a readdirp on the directory with this file we send out
> wrong stat value to the kernel. There are different caches between kernel
> and gluster which may lead to fstat never coming till write-behind. So we
> need to make sure that we don't get into this situation.
>
>
> Action items:
>
>
> At the moment Raghavendra is working on a patch to implement lookup/readdirp
> in write-behind. I am going to test the same for elastic search. Will it be
> possible for you to test your application against the same patch and confirm
> that the patch fixes the problem?
>
>
>
>
>
> On Fri, Oct 28, 2016 at 12:08 PM, Pranith Kumar Karampuri <
> pkarampu at redhat.com > wrote:
>
>
>
>
> hi George,
>
>
> It would help if we can identify the bare minimum xlators which are
> contributing to the issue like Raghavendra was mentioning earlier. We were
> wondering if it is possible for you to help us in identifying the issue by
> running the workload on a modified setup? We can suggest testing out using
> custom volfiles so that we can slowly build the graph which could be causing
> this issue. We would like you guys to try out this problem with just
> posix-xlator and fuse and nothing else.
>
>
>
>
>
> On Thu, Oct 27, 2016 at 1:40 PM, Lian, George (Nokia - CN/Hangzhou) <
> george.lian at nokia.com > wrote:
>
>
>
> Hi, Raghavendra,
>
> Could you please give some suggestion for this issue? we try to find the clue
> for this issue for a long time, but it has no progress:(
>
> Thanks & Best Regards,
> George
>
> -----Original Message-----
> From: Lian, George (Nokia - CN/Hangzhou)
> Sent: Wednesday, October 19, 2016 4:40 PM
> To: 'Raghavendra Gowdappa' < rgowdapp at redhat.com >
> Cc: Gluster-devel at gluster.org ; I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX_GMS <
> I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX at internal.nsn.com >; Zhang, Bingxuan (Nokia -
> CN/Hangzhou) < bingxuan.zhang at nokia.com >; Zizka, Jan (Nokia - CZ/Prague) <
> jan.zizka at nokia.com >
> Subject: RE: [Gluster-devel] Issue about the size of fstat is less than the
> really size of the syslog file
>
> Hi, Raghavendra
>
> Just now, we test it with glusterfs log with debug-level "TRACE", and let
> some application trigger "glusterfs" produce large log, in that case, when
> we set write-behind and stat-prefetch both OFF,
> Tail the glusterfs log such like mnt-{VOLUME-NAME}.log, it still failed with
> "file truncated",
>
> So that means if file's IO in huge amount, the issue will still be there even
> write-behind and stat-prefetch both OFF.
>
> Best Regards,
> George
>
> -----Original Message-----
> From: Raghavendra Gowdappa [mailto: rgowdapp at redhat.com ]
>
>
> Sent: Wednesday, October 19, 2016 2:54 PM
> To: Lian, George (Nokia - CN/Hangzhou) < george.lian at nokia.com >
> Cc: Gluster-devel at gluster.org ; I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX_GMS <
> I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX at internal.nsn.com >; Zhang, Bingxuan (Nokia -
> CN/Hangzhou) < bingxuan.zhang at nokia.com >; Zizka, Jan (Nokia - CZ/Prague) <
> jan.zizka at nokia.com >
> Subject: Re: [Gluster-devel] Issue about the size of fstat is less than the
> really size of the syslog file
>
>
>
> ----- Original Message -----
> > From: "George Lian (Nokia - CN/Hangzhou)" < george.lian at nokia.com >
> > To: "Raghavendra Gowdappa" < rgowdapp at redhat.com >
> > Cc: Gluster-devel at gluster.org , "I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX_GMS"
> > < I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX at internal.nsn.com >, "Bingxuan Zhang
> > (Nokia - CN/Hangzhou)"
> > < bingxuan.zhang at nokia.com >, "Jan Zizka (Nokia - CZ/Prague)" <
> > jan.zizka at nokia.com >
> > Sent: Wednesday, October 19, 2016 12:05:01 PM
> > Subject: RE: [Gluster-devel] Issue about the size of fstat is less than the
> > really size of the syslog file
> >
> > Hi, Raghavendra,
> >
> > Thanks a lots for your quickly update!
> > In my case, there are so many process(write) is writing to the syslog file,
> > it do involve the writer is in the same host and writing in same mount
> > point
> > while the tail(reader) is reading it.
> >
> > The bug I just guess is:
> > When a writer write the data with write-behind, it call the call-back
> > function " mdc_writev_cbk" and called "mdc_inode_iatt_set_validate" to
> > validate the "iatt" data, but with the code I mentioned last mail, it do
> > nothing.
>
> mdc_inode_iatt_set_validate has following code
>
> <snippet>
> if (!iatt || !iatt->ia_ctime) {
> mdc->ia_time = 0;
> goto unlock;
> }
> </snippet>
>
> Which means a NULL iatt sets mdc->ia_time to 0. This results in subsequent
> lookup/stat calls to be NOT served from md-cache. Instead, the stat is
> served from backend bricks. So, I don't see an issue here.
>
> However, one case where a NULL iatt is different from a valid iatt (which
> differs from the value stored in md-cache) is that the latter results in a
> call to inode_invalidate. This invalidation propagates to kernel and all
> dentry and page cache corresponding to file is purged. So, I am suspecting
> whether the stale stat you saw was served from kernel cache (not from
> glusterfs). If this is the case, having mount options "attribute-timeout=0"
> and "entry-timeout=0" should've helped.
>
> I am still at loss to point out the RCA for this issue.
>
>
> > And in same time, the reader(tail) read the "iatt" data, but in case of the
> > cache-time is not timeout, it will return the "iatt" data without the last
> > change.
> >
> > Do your think it is a possible bug?
> >
> > Thanks & Best Regards,
> > George
> >
> > -----Original Message-----
> > From: Raghavendra Gowdappa [mailto: rgowdapp at redhat.com ]
> > Sent: Wednesday, October 19, 2016 2:06 PM
> > To: Lian, George (Nokia - CN/Hangzhou) < george.lian at nokia.com >
> > Cc: Gluster-devel at gluster.org ; I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX_GMS
> > < I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX at internal.nsn.com >; Zhang, Bingxuan
> > (Nokia -
> > CN/Hangzhou) < bingxuan.zhang at nokia.com >; Zizka, Jan (Nokia - CZ/Prague)
> > < jan.zizka at nokia.com >
> > Subject: Re: [Gluster-devel] Issue about the size of fstat is less than the
> > really size of the syslog file
> >
> >
> >
> > ----- Original Message -----
> > > From: "George Lian (Nokia - CN/Hangzhou)" < george.lian at nokia.com >
> > > To: "Raghavendra Gowdappa" < rgowdapp at redhat.com >
> > > Cc: Gluster-devel at gluster.org , "I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX_GMS"
> > > < I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX at internal.nsn.com >, "Bingxuan Zhang
> > > (Nokia
> > > - CN/Hangzhou)"
> > > < bingxuan.zhang at nokia.com >, "Jan Zizka (Nokia - CZ/Prague)"
> > > < jan.zizka at nokia.com >
> > > Sent: Wednesday, October 19, 2016 10:51:24 AM
> > > Subject: RE: [Gluster-devel] Issue about the size of fstat is less than
> > > the
> > > really size of the syslog file
> > >
> > > Hi, Raghavendra,
> > >
> > > When we disable md-cache(gluster volume set log
> > > performance.md-cache-timeout
> > > 0), the issue seems gone.
> > > (we can't disable with " gluster volume set log performance.md-cache off"
> > > why?)
> >
> > Please use
> > #gluster volume set log performance.stat-prefetch off
> >
> > >
> > > So I double confuse that the code I abstract in last mail maybe have some
> > > issue for this case.
> > > Could you please share your comments?
> >
> > Please find my comments below.
> >
> > >
> > > Thanks & Best Regards,
> > > George
> > >
> > > -----Original Message-----
> > > From: Lian, George (Nokia - CN/Hangzhou)
> > > Sent: Friday, October 14, 2016 1:44 PM
> > > To: 'Raghavendra Gowdappa' < rgowdapp at redhat.com >
> > > Cc: Gluster-devel at gluster.org ; I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX_GMS
> > > < I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX at internal.nsn.com >; Zhang, Bingxuan
> > > (Nokia
> > > -
> > > CN/Hangzhou) < bingxuan.zhang at nokia.com >; Zizka, Jan (Nokia - CZ/Prague)
> > > < jan.zizka at nokia.com >
> > > Subject: RE: [Gluster-devel] Issue about the size of fstat is less than
> > > the
> > > really size of the syslog file
> > >
> > > Hi, Raghavendra,
> > >
> > > Our version of GlusterFS is 3.6.9, and I also check the newest code of
> > > main
> > > branch, the function of " mdc_inode_iatt_set_validate" is almost same,
> > > from
> > > the following code of this function,
> > > We could see a "TODO" comments inline, does it mean if we enhance
> > > write-behind feature, the "iatt" field in callback will be NULL, so that
> > > inode_invalidate will not be called? So the size of file will not update
> > > since "write behind" enabled ?
> > > Is it the root cause for "tail" application failed with "file truncated"
> > > issue ?
> > >
> > > LOCK (&mdc->lock);
> > > {
> > > if (!iatt || !iatt->ia_ctime) {
> > > mdc->ia_time = 0;
> > > goto unlock;
> > > }
> > >
> > > /*
> > > * Invalidate the inode if the mtime or ctime has changed
> > > * and the prebuf doesn't match the value we have cached.
> > > * TODO: writev returns with a NULL iatt due to
> > > * performance/write-behind, causing invalidation on writes.
> > > */
> >
> > The issue explained in this comment is hit only when writes are done. But,
> > in
> > your use-case only "tail" is the application running on the mount (If I am
> > not wrong, the writer is running on a different mountpoint). So, I doubt
> > you are hitting this issue. But, you are saying that the issue goes away
> > when write-behind/md-cache is turned off pointing to some interaction
> > between md-cache and write-behind causing the issue. I need more time to
> > look into this issue. Can you file a bug on this?
> >
> > > if (IA_ISREG(inode->ia_type) &&
> > > ((iatt->ia_mtime != mdc->md_mtime) ||
> > > (iatt->ia_ctime != mdc->md_ctime)))
> > > if (!prebuf || (prebuf->ia_ctime != mdc->md_ctime) ||
> > > (prebuf->ia_mtime != mdc->md_mtime))
> > > inode_invalidate(inode);
> > >
> > > mdc_from_iatt (mdc, iatt);
> > >
> > > time (&mdc->ia_time);
> > > }
> > >
> > > Best Regards,
> > > George
> > > -----Original Message-----
> > > From: Raghavendra Gowdappa [mailto: rgowdapp at redhat.com ]
> > > Sent: Thursday, October 13, 2016 8:58 PM
> > > To: Lian, George (Nokia - CN/Hangzhou) < george.lian at nokia.com >
> > > Cc: Gluster-devel at gluster.org ; I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX_GMS
> > > < I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX at internal.nsn.com >; Zhang, Bingxuan
> > > (Nokia
> > > -
> > > CN/Hangzhou) < bingxuan.zhang at nokia.com >; Zizka, Jan (Nokia - CZ/Prague)
> > > < jan.zizka at nokia.com >
> > > Subject: Re: [Gluster-devel] Issue about the size of fstat is less than
> > > the
> > > really size of the syslog file
> > >
> > >
> > >
> > > ----- Original Message -----
> > > > From: "George Lian (Nokia - CN/Hangzhou)" < george.lian at nokia.com >
> > > > To: Gluster-devel at gluster.org
> > > > Cc: "I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX_GMS"
> > > > < I_EXT_MBB_WCDMA_SWD3_DA1_MATRIX at internal.nsn.com >, "Bingxuan Zhang
> > > > (Nokia
> > > > - CN/Hangzhou)" < bingxuan.zhang at nokia.com >, "Jan Zizka (Nokia -
> > > > CZ/Prague)"
> > > > < jan.zizka at nokia.com >
> > > > Sent: Thursday, October 13, 2016 2:33:53 PM
> > > > Subject: [Gluster-devel] Issue about the size of fstat is less than the
> > > > really size of the syslog file
> > > >
> > > > Hi, Dear Expert,
> > > > We have use glusterfs as a network filesystem, and syslog store in
> > > > there,
> > > > some clients on different host may write the syslog file via
> > > > “glusterfs”
> > > > mount point.
> > > > Now we encounter an issue when we “tail” the syslog file, it will
> > > > occasional
> > > > failed with error “ file truncated ”
> > > > As we study and trace with the “tail” source code, it failed with the
> > > > following code:
> > > > if ( S_ISREG (mode) && stats.st_size < f[i].size )
> > > > {
> > > > error (0, 0, _("%s: file truncated"), quotef (name));
> > > > /* Assume the file was truncated to 0,
> > > > and therefore output all "new" data. */
> > > > xlseek (fd, 0, SEEK_SET, name);
> > > > f[i].size = 0;
> > > > }
> > > > When stats.st_size < f[i].size, what mean the size report by fstat is
> > > > less
> > > > than “tail” had read, it lead to “file truncated”, we also use “strace”
> > > > tools to trace the tail application, the related tail strace log as the
> > > > below:
> > > > nanosleep({1, 0}, NULL) = 0
> > > > fstat(3, {st_mode=S_IFREG|0644, st_size=192543105, ...}) = 0
> > > > nanosleep({1, 0}, NULL) = 0
> > > > fstat(3, {st_mode=S_IFREG|0644, st_size=192543105, ...}) = 0
> > > > nanosleep({1, 0}, NULL) = 0
> > > > fstat(3, {st_mode=S_IFREG|0644, st_size=192543105, ...}) = 0
> > > > nanosleep({1, 0}, NULL) = 0
> > > > fstat(3, {st_mode=S_IFREG|0644, st_size=192544549, ...}) = 0
> > > > read(3, " Data … -"..., 8192) = 1444
> > > > read(3, " Data.. "..., 8192) = 720
> > > > read(3, "", 8192) = 0
> > > > fstat(3, {st_mode=S_IFREG|0644, st_size=192544789, ...}) = 0
> > > > write(1, “DATA…..” ) = 2164
> > > > write(2, "tail: ", 6tail: ) = 6
> > > > write(2, "/mnt/log/master/syslog: file tru"...,
> > > > 38/mnt/log/master/syslog:
> > > > file truncated) = 38
> > > > as the above strace log, tail has read 1444+720=2164 bytes,
> > > > but fstat tell “tail” 192544789 – 192543105 = 1664 which less than
> > > > 2164,
> > > > so
> > > > it lead to “tail” application “file truncated”.
> > > > And if we turn off “write-behind” feature, the issue will not be
> > > > reproduced
> > > > any more.
> > >
> > > That seems strange. There are no writes happening on the fd/inode through
> > > which tail is reading/stating from. So, it seems strange that
> > > write-behind
> > > is involved here. I suspect whether any of md-cache/read-ahead/io-cache
> > > is
> > > causing the issue. Can you,
> > >
> > > 1. Turn off md-cache, read-ahead, io-cache xlators
> > > 2. mount glusterfs with --attribute-timeout=0
> > > 3. set write-behind on
> > >
> > > and rerun the tests? If you don't hit the issue, you can experiment by
> > > turning on/off of md-cache, read-ahead and io-cache translators and see
> > > what
> > > are the minimal number of xlators that need to be turned off to not hit
> > > the
> > > issue (with write-behind on)?
> > >
> > > regards,
> > > Raghavendra
> > >
> > > > So we think it may be related to cache consistence issue due to
> > > > performance
> > > > consider, but we still have concern that:
> > > > The syslog file is used only with “Append” mode, so the size of file
> > > > shouldn’t be reduced, when a client read the file, why “fstat” can’t
> > > > return
> > > > the really size match to the cache?
> > > > From current investigation, we doubt that the current implement of
> > > > “glusterfs” has a bug on “fstat” when cache is on.
> > > > Your comments is our highly appreciated!
> > > > Thanks & Best Regards
> > > > George
> > > >
> > > > _______________________________________________
> > > > Gluster-devel mailing list
> > > > Gluster-devel at gluster.org
> > > > http://www.gluster.org/mailman/listinfo/gluster-devel
> > >
> >
> _______________________________________________
> Gluster-devel mailing list
> Gluster-devel at gluster.org
> http://www.gluster.org/mailman/listinfo/gluster-devel
>
>
>
>
>
>
> --
>
>
> Pranith
>
>
>
>
>
> --
>
>
> Pranith
>
>
>
> --
> Pranith
>
> _______________________________________________
> Gluster-devel mailing list
> Gluster-devel at gluster.org
> http://www.gluster.org/mailman/listinfo/gluster-devel
>
>
>
> --
> Raghavendra G
>
> _______________________________________________
> Gluster-devel mailing list
> Gluster-devel at gluster.org
> http://www.gluster.org/mailman/listinfo/gluster-devel
_______________________________________________
Gluster-devel mailing list
Gluster-devel at gluster.org
http://www.gluster.org/mailman/listinfo/gluster-devel
More information about the Gluster-devel
mailing list