I have run into a similar hang on 'ls .snap' recently: https://tracker.ceph.com/issues/40101#note-2 On Wed, Jun 12, 2019 at 9:33 AM Yan, Zheng <ukernel@xxxxxxxxx> wrote: > > On Wed, Jun 12, 2019 at 3:26 PM Hector Martin <hector@xxxxxxxxxxxxxx> wrote: > > > > Hi list, > > > > I have a setup where two clients mount the same filesystem and > > read/write from mostly non-overlapping subsets of files (Dovecot mail > > storage/indices). There is a third client that takes backups by > > snapshotting the top-level directory, then rsyncing the snapshot over to > > another location. > > > > Ever since I switched the backup process to using snapshots, the rsync > > process has stalled at a certain point during the backup with a stuck > > MDS op: > > > > root@mon02:~# ceph daemon mds.mon02 dump_ops_in_flight > > { > > "ops": [ > > { > > "description": "client_request(client.146682828:199050 > > getattr pAsLsXsFs #0x10000000007//bak-20190612094501/<snip > > path>/dovecot.index.log 2019-06-12 12:20:56.992049 caller_uid=5000, > > caller_gid=5000{})", > > "initiated_at": "2019-06-12 12:20:57.001534", > > "age": 9563.847754, > > "duration": 9563.847780, > > "type_data": { > > "flag_point": "failed to rdlock, waiting", > > "reqid": "client.146682828:199050", > > "op_type": "client_request", > > "client_info": { > > "client": "client.146682828", > > "tid": 199050 > > }, > > "events": [ > > { > > "time": "2019-06-12 12:20:57.001534", > > "event": "initiated" > > }, > > { > > "time": "2019-06-12 12:20:57.001534", > > "event": "header_read" > > }, > > { > > "time": "2019-06-12 12:20:57.001538", > > "event": "throttled" > > }, > > { > > "time": "2019-06-12 12:20:57.001550", > > "event": "all_read" > > }, > > { > > "time": "2019-06-12 12:20:57.001713", > > "event": "dispatched" > > }, > > { > > "time": "2019-06-12 12:20:57.001997", > > "event": "failed to rdlock, waiting" > > } > > ] > > } > > } > > ], > > "num_ops": 1 > > } > > > > AIUI, when a snapshot is taken, all clients with dirty data are supposed > > to get a message to flush it to the cluster in order to produce a > > consistent snapshot. My guess is this isn't happening properly, so reads > > of that file in the snapshot are blocked. Doing a 'echo 3 > > > /proc/sys/vm/drop_caches' on both of the writing clients seems to clear > > the stuck op, but doing it once isn't enough; usually I get the stuck up > > and have to clear caches twice after making any given snapshot. > > > > Everything is on Ubuntu. The cluster is running 13.2.4 (mimic), and the > > clients are using the kernel client version 4.18.0-20-generic (writers) > > and 4.18.0-21-generic (backup host). > > > > I managed to reproduce it like this: > > > > host1$ mkdir _test > > host1$ cd _test/.snap > > > > host2$ cd _test > > host2$ for i in $(seq 1 10000); do (sleep 0.1; echo $i; sleep 1) > b_$i > > & sleep 0.05; done > > > > (while that is running) > > > > host1$ mkdir s11 > > host1$ cd s11 > > > > (wait a few seconds) > > > > host2$ ^C > > > > host1$ ls -al > > (hangs) > > > > This yielded this stuck request: > > > > { > > "ops": [ > > { > > "description": "client_request(client.146687505:13785 > > getattr pAsLsXsFs #0x1000017f41c//s11/b_42 2019-06-12 16:15:59.095025 > > caller_uid=0, caller_gid=0{})", > > "initiated_at": "2019-06-12 16:15:59.095559", > > "age": 30.846294, > > "duration": 30.846318, > > "type_data": { > > "flag_point": "failed to rdlock, waiting", > > "reqid": "client.146687505:13785", > > "op_type": "client_request", > > "client_info": { > > "client": "client.146687505", > > "tid": 13785 > > }, > > "events": [ > > { > > "time": "2019-06-12 16:15:59.095559", > > "event": "initiated" > > }, > > { > > "time": "2019-06-12 16:15:59.095559", > > "event": "header_read" > > }, > > { > > "time": "2019-06-12 16:15:59.095562", > > "event": "throttled" > > }, > > { > > "time": "2019-06-12 16:15:59.095573", > > "event": "all_read" > > }, > > { > > "time": "2019-06-12 16:15:59.096201", > > "event": "dispatched" > > }, > > { > > "time": "2019-06-12 16:15:59.096318", > > "event": "failed to rdlock, waiting" > > }, > > { > > "time": "2019-06-12 16:15:59.268368", > > "event": "failed to rdlock, waiting" > > } > > ] > > } > > } > > ], > > "num_ops": 1 > > } > > > > My guess is somewhere along the line of this process there's a race > > condition and the dirty client isn't properly flushing its data. > > > > A 'sync' on host2 does not clear the stuck op. 'echo 1 > > > /proc/sys/vm/drop_caches' does not either, while 'echo 2 > > > /proc/sys/vm/drop_caches' does fix it. So I guess the problem is a > > dentry/inode that is stuck dirty in the cache of host2? > > > > I have tracked down the bug. thank you for reporting this. 'echo 2 > > /proc/sys/vm/drop_cache' should fix the hang. If you can compile ceph > from source, please try following patch. > > diff --git a/src/mds/Locker.cc b/src/mds/Locker.cc > index ecd06294fa..94b947975a 100644 > --- a/src/mds/Locker.cc > +++ b/src/mds/Locker.cc > @@ -2956,7 +2956,8 @@ void Locker::handle_client_caps(MClientCaps *m) > > // client flushes and releases caps at the same time. make sure > MDCache::cow_inode() > // properly setup CInode::client_need_snapflush > - if ((m->get_dirty() & ~cap->issued()) && !need_snapflush) > + if (!need_snapflush && (m->get_dirty() & ~cap->issued()) && > + (m->flags & MClientCaps::FLAG_PENDING_CAPSNAP)) > cap->mark_needsnapflush(); > } > > > > > > > -- > > Hector Martin (hector@xxxxxxxxxxxxxx) > > Public Key: https://mrcn.st/pub > > _______________________________________________ > > ceph-users mailing list > > ceph-users@xxxxxxxxxxxxxx > > http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com > _______________________________________________ > ceph-users mailing list > ceph-users@xxxxxxxxxxxxxx > http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com _______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
 |