[root@dhcp42-61 ~]# cp -fv /nonroot/slave/thread7/level03/5aba0284%%DXAMLOZTMR slave 
‘/nonroot/slave/thread7/level03/5aba0284%%DXAMLOZTMR’ -> ‘slave’


[root@dhcp42-61 ~]# cp -fv /nonroot/master/thread7/level03/5aba0284%%DXAMLOZTMR master 
‘/nonroot/master/thread7/level03/5aba0284%%DXAMLOZTMR’ -> ‘master’

[root@dhcp42-61 ~]# md5sum master
764dc94fb8666ec09d89a12d960c75a4  master

[root@dhcp42-61 ~]# md5sum slave
977708c84a4149d26f2eac1eb53fee55  slave

[root@dhcp42-61 ~]# ls -l slave
--wxr-xr-x. 1 root root 4390 Mar 28 10:46 slave

[root@dhcp42-61 ~]# ls -l master
--wxr-xr-x. 1 root root 5025 Mar 28 10:47 master

[root@dhcp42-61 ~]# truncate --size 4390 ./master

[root@dhcp42-61 ~]# ls -l ./master
--wxr-xr-x. 1 root root 4390 Mar 28 10:47 ./master

[root@dhcp42-61 ~]# md5sum ./master.old 
977708c84a4149d26f2eac1eb53fee55  ./master

[root@dhcp42-61 ~]# md5sum slave
977708c84a4149d26f2eac1eb53fee55  slave

Note that file "slave" is a partial copy of "master". To be precise first 4390 bytes of "master" match with "slave"

From logs, I can see quick-read returns only 4390 bytes when read from slave mount. However stat on both master and slave return correct value of 5025.


From gdb,
(gdb) c
Continuing.
[Switching to Thread 0x7f52b649d700 (LWP 20804)]

Breakpoint 1, qr_readv (frame=0x7f52a8652b50, this=0x7f52b801b750, fd=0x7f52a8678810, size=8192, offset=0, flags=32768, xdata=0x0) at quick-read.c:611

(gdb) p *qr_inode
$2 = {data = 0x7f52b0999e30, size = 4390, priority = 0, ia_mtime = 1522139994, ia_mtime_nsec = 386948000, buf = {ia_ino = 13103533730534322441, ia_gfid = "\207\235&XT1O\"\265\331\032\200\236\330\361\t", 
    ia_dev = 64779, ia_type = IA_IFREG, ia_prot = {suid = 0 '\000', sgid = 0 '\000', sticky = 0 '\000', owner = {read = 0 '\000', write = 1 '\001', exec = 1 '\001'}, group = {read = 1 '\001', 
        write = 1 '\001', exec = 1 '\001'}, other = {read = 1 '\001', write = 0 '\000', exec = 1 '\001'}}, ia_nlink = 1, ia_uid = 0, ia_gid = 29991, ia_rdev = 0, ia_size = 5025, ia_blksize = 4096, 
    ia_blocks = 10, ia_atime = 1522140312, ia_atime_nsec = 610248000, ia_mtime = 1522139994, ia_mtime_nsec = 386948000, ia_ctime = 1522140312, ia_ctime_nsec = 614232024}, last_refresh = {tv_sec = 1522248921, 
    tv_usec = 635511}, lru = {next = 0x7f52b8036d90, prev = 0x7f52b195a3a0}}

There are two aspects to the problem:

* why was partial data cached in quick-read?
* Through gdb, I could see cache-timeout is 1s. However for quite a sometime quick-read kept returning stale data. What caused cache_refresh logic to misbehave for so long? Also note that after I attached gdb, I could see that cache was found invalid and readv was wound to backend and md5sum matched with that of master.

(In reply to Raghavendra G from comment #4)
> There are two aspects to the problem:
> 
> * why was partial data cached in quick-read?
> * Through gdb, I could see cache-timeout is 1s. However for quite a sometime
> quick-read kept returning stale data. What caused cache_refresh logic to
> misbehave for so long? 

Note that qr_inode->ia_mtime = qr_inode->buf->ia_mtime = 1522139994
Since refresh logic relies on ia_time, it thinks file has not changed

Also, even though qr_inode->size has wrong value, qr_inode->buf->ia_size has correct value of 5025.

> Also note that after I attached gdb, I could see that
> cache was found invalid and readv was wound to backend and md5sum matched
> with that of master.

cache-timeout by default is 1 sec. Attaching gdb makes sure that time last time inode was refreshed is greater than 1 sec. Note that most likely a lookup might've refreshed qr_inode->ia_time and was immediately followed by readv.

What makes this more complicated is all of qr_inode->ia_mtime, qr_inode->size are atomically updated from same iatt:

void
qr_content_update (xlator_t *this, qr_inode_t *qr_inode, void *data,
                   struct iatt *buf)
{
        qr_private_t      *priv = NULL;
        qr_inode_table_t  *table = NULL;

        priv = this->private;
	table = &priv->table;

 	LOCK (&table->lock);
	{
	        __qr_inode_prune (table, qr_inode);

		qr_inode->data = data;
                qr_inode->size = buf->ia_size;

                qr_inode->ia_mtime = buf->ia_mtime;
		qr_inode->ia_mtime_nsec = buf->ia_mtime_nsec;

	        qr_inode->buf = *buf;

	        gettimeofday (&qr_inode->last_refresh, NULL);

		__qr_inode_register (table, qr_inode);
	}
        UNLOCK (&table->lock);

	qr_cache_prune (this);
}

The only other place qr_inode->mtime is updated is in qr_content_refresh

void
__qr_content_refresh (xlator_t *this, qr_inode_t *qr_inode, struct iatt *buf)
{
	qr_private_t      *priv = NULL;
	qr_inode_table_t  *table = NULL;
        qr_conf_t         *conf = NULL;

	priv = this->private;
        table = &priv->table;
	conf = &priv->conf;

        if (qr_size_fits (conf, buf) && qr_mtime_equal (qr_inode, buf)) {
                qr_inode->buf = *buf;

                gettimeofday (&qr_inode->last_refresh, NULL);

		__qr_inode_register (table, qr_inode);
	} else {
                __qr_inode_prune (table, qr_inode);
        }

 	return;
}

So, how can we get an iatt whose mtime is latest, but file size is not correct?

<man rsync>

      -t, --times
              This  tells  rsync  to  transfer modification times along with the files and update them on the remote system.  Note that if this option is not used, the optimization that excludes files that
              have not been modified cannot be effective; in other words, a missing -t or -a will cause the next transfer to behave as if it used -I,  causing  all  files  to  be  updated  (though  rsync’s
              delta-transfer algorithm will make the update fairly efficient if the files haven’t actually changed, you’re much better off using -t).

</man rsync>

My guess is that rsync preserved mtime from master, even though file size changed. This confused quick-read to not detect file changes as mtime remained same. So, something like this might've happened:

* lookup on mount m1 fetched a partially written file whose size is 4390 bytes, but mtime is updated to mtime of master
* another write from rsync extended the file by 635 bytes changing the file size to 5025 bytes, but mtime on backend fs remained same

Every time quick-read got an iatt of the file, it checked the mtime and it matched with mtime when it had cached the file. So, quick-read things file has not changed and keep serving partial file of size 4390 bytes.

But there are some glaring loopholes in this argument. 
* One would expect rsync to update mtime once the entire file is written. What I said can happen only if rsync is updating mtime of file after _every_ write to file.
* Also, file size is pretty small. One would wonder what made rsync to update the file in two writes instead of a single one. Note that two writes are essential for this hypothesis to be true.

@Kotresh,

Can you verify and update the bug with what's the behaviour of rsync?

regards,
Raghavendra

[2018-04-05 10:31:37.842689] I [trace.c:1716:trace_lookup] 0-slave-debug: 198013: gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 path=/thread2/level02/level12/level22/level32/5ac5f625%%0NCC8DMKTG
[2018-04-05 10:31:37.843311] I [trace.c:612:trace_lookup_cbk] 0-slave-debug: 198013: gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 (op_ret=0 *buf {gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 ino=9488749538296052200, m
ode=100770, nlink=1, uid=0, gid=42539, size=4266, blocks=9, atime=2018-04-05-10:10:45 mtime=2018-04-05-10:15:28 ctime=2018-04-05-10:24:29 atime_sec=1522923045, atime_nsec=360115000, mtime_sec=1522923328, mtime_n
sec=526547000, ctime_sec=1522923869, ctime_nsec=54816113}, *postparent {gfid=00000000-0000-0000-0000-000000000000 ino=0, mode=0, nlink=0, uid=0, gid=0, size=0, blocks=0, atime=N/A mtime=N/A ctime=N/A atime_sec=0
, atime_nsec=0, mtime_sec=0, mtime_nsec=0, ctime_sec=0, ctime_nsec=0}
[2018-04-05 10:31:37.846794] I [trace.c:2209:trace_open] 0-slave-debug: 198014: gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 path=/thread2/level02/level12/level22/level32/5ac5f625%%0NCC8DMKTG flags=0 fd=0x7f7e3484e
c00
[2018-04-05 10:31:37.846977] I [trace.c:141:trace_open_cbk] 0-slave-debug: 198014: gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 op_ret=0, op_errno=0, *fd=0x7f7e3484ec00
[2018-04-05 10:31:37.848980] I [trace.c:1716:trace_lookup] 0-slave-debug: 14653: gfid=9108439f-3d67-4b02-a128-5287266f676e path=/thread8/level07/level17/level27/level37
[2018-04-05 10:31:37.849204] I [trace.c:2209:trace_open] 0-slave-debug: 198015: gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 path=/thread2/level02/level12/level22/level32/5ac5f625%%0NCC8DMKTG flags=1 fd=0x7f7e3484e
160
[2018-04-05 10:31:37.849375] I [trace.c:141:trace_open_cbk] 0-slave-debug: 198015: gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 op_ret=0, op_errno=0, *fd=0x7f7e3484e160

[2018-04-05 10:31:37.854173] I [trace.c:1684:trace_fxattrop] 0-slave-debug: 198018: gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 fd=0x7f7e3484e160, flags=0
[2018-04-05 10:31:37.854394] I [trace.c:1353:trace_fxattrop_cbk] 0-slave-debug: 198018: gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 op_ret=0, op_errno=0
[2018-04-05 10:31:37.856159] I [trace.c:1684:trace_fxattrop] 0-slave-debug: 198019: gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 fd=0x7f7e3484e160, flags=0
[2018-04-05 10:31:37.856350] I [trace.c:1353:trace_fxattrop_cbk] 0-slave-debug: 198019: gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 op_ret=0, op_errno=0

Note the mtime of file before writev - mtime_sec=1522923328, mtime_n
sec=526547000

[2018-04-05 10:31:37.857212] I [trace.c:2310:trace_writev] 0-slave-debug: 198020: gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 fd=0x7f7e3484e160, count=1,  offset=4200 flags=08001 write_size=4704
[2018-04-05 10:31:37.857470] I [trace.c:258:trace_writev_cbk] 0-slave-debug: 198020: (op_ret=4704, *prebuf = {gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 ino=9488749538296052200, mode=100770, nlink=1, uid=0, gid=4
2539, size=4266, blocks=9, atime=2018-04-05-10:10:45 mtime=2018-04-05-10:15:28 ctime=2018-04-05-10:31:37 atime_sec=1522923045, atime_nsec=360115000, mtime_sec=1522923328, mtime_nsec=526547000, ctime_sec=15229242
97, ctime_nsec=855060264}, *postbuf = {gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 ino=9488749538296052200, mode=100770, nlink=1, uid=0, gid=42539, size=8904, blocks=18, atime=2018-04-05-10:10:45 mtime=2018-04-05-
10:31:37 ctime=2018-04-05-10:31:37 atime_sec=1522923045, atime_nsec=360115000, mtime_sec=1522924297, mtime_nsec=856060283, ctime_sec=1522924297, ctime_nsec=856060283})

After writev mtime changes to mtime_sec=1522924297, mtime_nsec=856060283. Note that mtime in prebuf matches to mtime got from lookup.


[2018-04-05 10:31:37.936760] I [trace.c:2076:trace_setattr] 0-slave-debug: 198039: gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 path=/thread2/level02/level12/level22/level32/5ac5f625%%0NCC8DMKTG ia_atime=Apr 05 10:
31:37, ia_mtime=Apr 05 10:15:28
[2018-04-05 10:31:37.937120] I [trace.c:390:trace_setattr_cbk] 0-slave-debug: 198039: (op_ret=0, *prebuf = {gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 ino=9488749538296052200, mode=100770, nlink=1, uid=0, gid=42539, size=8904, blocks=18, atime=2018-04-05-10:10:45 mtime=2018-04-05-10:31:37 ctime=2018-04-05-10:31:37 atime_sec=1522923045, atime_nsec=360115000, mtime_sec=1522924297, mtime_nsec=858060321, ctime_sec=1522924297, ctime_nsec=909061302}, *postbuf = {gfid=e84eae56-7ffd-4b15-83ae-cf6e78c9b9e8 ino=9488749538296052200, mode=100770, nlink=1, uid=0, gid=42539, size=8904, blocks=18, atime=2018-04-05-10:31:37 mtime=2018-04-05-10:15:28 ctime=2018-04-05-10:31:37 atime_sec=1522924297, atime_nsec=935205000, mtime_sec=1522923328, mtime_nsec=526547000, ctime_sec=1522924297, ctime_nsec=936061821})

Now setattr changes mtime to the value before writev. Note that mtime-prebuf is less than mtime-postbuf. Also note that this file was present and populated with data before this writev with size of 4266 and write came at an offset of 4200. This matches with the hypothesis comment #8.

IOW, if a client has cached the file (in quick-read) before write (unique:198020) with a size of 4266, it won't notice the change of file due to write as mtime of file post write matches with mtime of file pre write. All reads on the file would return a data of size 4266 instead of the new size of 8904.

This bug affects io-cache too as it relies on mtime to maintain cache coherency with data on brick.

> Note that mtime-prebuf is less than mtime-postbuf.

Note that mtime-prebuf in setattr_cbk is greater than mtime-postbuf.

Looks like features.cache-invalidation is off. If it was turned on, upcall invalidations would've flushed quick-read cache as it also uses upcall framework along with mtime to identify changes to file.

@Rochelle/Kotresh,

Can you proved gluster volume info of slave volume, so that we can find out whether cache-invalidation is on?

(In reply to Kotresh HR from comment #14)
> Raghavendra,
> 
> Pasting volinfo from sosreports:
> 
> Volume Name: slave
> Type: Distributed-Replicate
> Volume ID: ffb16f20-f595-4951-91a8-661bfee1eb63
> Status: Started
> Snapshot Count: 0
> Number of Bricks: 2 x 3 = 6
> Transport-type: tcp
> Bricks:
> Brick1: 10.70.42.188:/rhs/brick1/b11
> Brick2: 10.70.42.8:/rhs/brick1/b12
> Brick3: 10.70.42.136:/rhs/brick1/b13
> Brick4: 10.70.42.188:/rhs/brick2/b14
> Brick5: 10.70.42.8:/rhs/brick2/b15
> Brick6: 10.70.42.136:/rhs/brick2/b16
> Options Reconfigured:
> diagnostics.client-log-level: TRACE
> transport.address-family: inet
> nfs.disable: on
> cluster.brick-multiplex: enable
> 
> Thanks,
> Kotresh HR

@Poornima,

Is upcall enabled by default? I guess the answer is no, but want your confirmation.

If upcall is not enabled by default, enabling upcall notifications on slave volume will fix this issue as quick-read consumes upcall to invalidate its cache when a file changes.

From glusterd-volume-set.c:
        
        { .key         = "features.cache-invalidation",
          .voltype     = "features/upcall",
          .value       = "off",
          .op_version  = GD_OP_VERSION_3_7_0,
        },
        { .key         = "features.cache-invalidation-timeout",
          .voltype     = "features/upcall",
          .op_version  = GD_OP_VERSION_3_7_0,
        },

So, I think upcall is turned off by default.

Upcall is not enabled by default, yeah it can fix this issue if upcall is enabled. But its a perf hit to be enabled on slave?

(In reply to Poornima G from comment #17)
> Upcall is not enabled by default, yeah it can fix this issue if upcall is
> enabled. But its a perf hit to be enabled on slave?

Do we've any data/approximation on how much performance drag can upcall be? I think we need to start looking at this aspect as going forward upcall/leases will play more prominent role in maintaining cache coherency.

@Rochelle,

Can you test with setting following options?
* features.cache-invalidation on

(In reply to Raghavendra G from comment #18)
> (In reply to Poornima G from comment #17)
> > Upcall is not enabled by default, yeah it can fix this issue if upcall is
> > enabled. But its a perf hit to be enabled on slave?
> 
> Do we've any data/approximation on how much performance drag can upcall be?
> I think we need to start looking at this aspect as going forward
> upcall/leases will play more prominent role in maintaining cache coherency.

Sorry i missed to reply to this. Especially in the geo-rep use case, enabling upcall on slave can generate lot of upcalls on the directories, as and when a new file gets created. I think there has to be a perf testing, before suggesting this as solution.

Kotresh had a suggestion to use ctime to identify staleness of cached data.

Following is my response to his suggestion:

<snip>

From stat information, mtime is guaranteed to change during file modification. That way, quick-read is posix complaint. There is nothing wrong in quick-read relying on mtime, if there was an application running on slave mount during sync from master, it could've run into same issue. I am not sure we allow that (accessing slave volume during sync from master). If yes, it'll be a problem with geo-rep :). Since quick-read is an internal consumer we can modify it to suit idiosyncrasies of mtime being constant across file changes, but external applications won't accept that logic.

To summarize, this problem will appear only if files mtimes are explicitly modified (just like in geo-rep through rsync). If there are too many such use cases, we can proceed with ctime based solution.

As to the ctime suggestion, some questions:
    * wouldn't rsync try to keep ctime in sync with master too? I think no, as I am not aware of any system call that allows ctime change (utime () only changes atime and mtime).
    * using ctime to track file changes solves the problem. But, it can result in false positives too (like changing ownership or access permissions, without file content change can change ctime). We can selectively turn this (using ctime instead of mtime) on on geo-rep slave volumes. But again, if slave is not consumed while sync is happening, I see no point in turning on quick-read till the volume is consumed.

I agree ctime can be a better solution (at least for geo-rep slaves and for cases where mtime is explicitly modified) for the reason it changes with file modification and ctime of a file cannot be explicitly set, while mtime and atime can be.

</snip>

An upstream patch has been submitted to do this - https://review.gluster.org/#/c/20286/.

This patch should be followed by changes to georeplication slave volume to have this option set for quick-read.

Closing (as per comment 43) as fix is provided as part of RHGS 3.5.0