Bug #59657: qa: test with postgres failed (deadlock between link and migrate straydn(rename)) - CephFS - Ceph

Actions

Copy link

Bug #59657

closed

qa: test with postgres failed (deadlock between link and migrate straydn(rename))

Added by Xiubo Li 12 months ago. Updated 11 months ago.

Status:

Resolved

Priority:

Normal

Assignee:

Xiubo Li

Category:

Target version:

Ceph - v19.0.0

% Done:

Source:

Q/A

Tags:

Backport:

Regression:

Severity:

3 - minor

Reviewed:

Affected Versions:

ceph-qa-suite:

Component(FS):

Labels (FS):

Pull request ID:

51363

Crash signature (v1):

Crash signature (v2):

Description

https://pulpito.ceph.com/vshankar-2023-05-03_16:19:11-fs-wip-vshankar-testing-20230503.142424-testing-default-smithi/7261318/

From teuthology.log there have two slow requests, which are rename and link:

2023-05-03T22:46:30.237 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:29 smithi018 ceph-mon[94987]: osdmap e100: 12 total, 12 up, 12 in
2023-05-03T22:46:30.238 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:29 smithi018 ceph-mon[94987]: 2 slow requests, 2 included below; oldest blocked for > 182.209563 secs
2023-05-03T22:46:30.238 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:29 smithi018 ceph-mon[94987]: slow request 182.209562 seconds old, received at 2023-05-03T22:43:27.054765+0000: client_request(client.25007:3087 link #0x10000000007/0000000100000000000000C4 #0x10000000007/00000001000000000000008E 2023-05-03T22:43:27.053778+0000 caller_uid=26, caller_gid=26{26,}) currently acquired locks
2023-05-03T22:46:30.238 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:29 smithi018 ceph-mon[94987]: slow request 182.205964 seconds old, received at 2023-05-03T22:43:27.058363+0000: peer_request(mds.2:80.0 authpin) currently dispatched
2023-05-03T22:46:30.272 INFO:journalctl@ceph.mon.c.smithi026.stdout:May 03 22:46:29 smithi026 ceph-mon[95442]: osdmap e100: 12 total, 12 up, 12 in
2023-05-03T22:46:30.273 INFO:journalctl@ceph.mon.c.smithi026.stdout:May 03 22:46:29 smithi026 ceph-mon[95442]: 2 slow requests, 2 included below; oldest blocked for > 182.209563 secs
2023-05-03T22:46:30.273 INFO:journalctl@ceph.mon.c.smithi026.stdout:May 03 22:46:29 smithi026 ceph-mon[95442]: slow request 182.209562 seconds old, received at 2023-05-03T22:43:27.054765+0000: client_request(client.25007:3087 link #0x10000000007/0000000100000000000000C4 #0x10000000007/00000001000000000000008E 2023-05-03T22:43:27.053778+0000 caller_uid=26, caller_gid=26{26,}) currently acquired locks
2023-05-03T22:46:30.274 INFO:journalctl@ceph.mon.c.smithi026.stdout:May 03 22:46:29 smithi026 ceph-mon[95442]: slow request 182.205964 seconds old, received at 2023-05-03T22:43:27.058363+0000: peer_request(mds.2:80.0 authpin) currently dispatched
2023-05-03T22:46:30.987 INFO:journalctl@ceph.mgr.y.smithi018.stdout:May 03 22:46:30 smithi018 ceph-4dfb0dbe-ea02-11ed-9b01-001a4aab830c-mgr-y[96470]: 2023-05-03T22:46:30.712+0000 7f413c0fc700 -1 client.25628: SimpleRADOSStriper: lock: snap_db_v0.db: waiting for locks:  lockers exclusive=1 tag= lockers=[client.15444:0e7f1cb7-d7d7-4986-a076-35085386d4cf:v1:172.21.15.7:0/1613962254]
2023-05-03T22:46:30.987 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:30 smithi018 ceph-mon[94987]: pgmap v63: 97 pgs: 1 active+undersized+remapped, 96 active+clean; 6.2 GiB data, 19 GiB used, 1.0 TiB / 1.0 TiB avail; 10 KiB/s rd, 252 B/s wr, 8 op/s; 22 B/s, 16 keys/s, 0 objects/s recovering
2023-05-03T22:46:31.272 INFO:journalctl@ceph.mon.c.smithi026.stdout:May 03 22:46:30 smithi026 ceph-mon[95442]: pgmap v63: 97 pgs: 1 active+undersized+remapped, 96 active+clean; 6.2 GiB data, 19 GiB used, 1.0 TiB / 1.0 TiB avail; 10 KiB/s rd, 252 B/s wr, 8 op/s; 22 B/s, 16 keys/s, 0 objects/s recovering
2023-05-03T22:46:31.736 INFO:journalctl@ceph.mgr.y.smithi018.stdout:May 03 22:46:31 smithi018 ceph-4dfb0dbe-ea02-11ed-9b01-001a4aab830c-mgr-y[96470]: 2023-05-03T22:46:31.443+0000 7f413c0fc700 -1 client.25628: SimpleRADOSStriper: lock: snap_db_v0.db: waiting for locks:  lockers exclusive=1 tag= lockers=[client.15444:0e7f1cb7-d7d7-4986-a076-35085386d4cf:v1:172.21.15.7:0/1613962254]
2023-05-03T22:46:32.237 INFO:journalctl@ceph.mgr.y.smithi018.stdout:May 03 22:46:32 smithi018 ceph-4dfb0dbe-ea02-11ed-9b01-001a4aab830c-mgr-y[96470]: 2023-05-03T22:46:32.175+0000 7f413c0fc700 -1 client.25628: SimpleRADOSStriper: lock: snap_db_v0.db: waiting for locks:  lockers exclusive=1 tag= lockers=[client.15444:0e7f1cb7-d7d7-4986-a076-35085386d4cf:v1:172.21.15.7:0/1613962254]
2023-05-03T22:46:32.238 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:31 smithi018 ceph-mon[94987]: Health check cleared: PG_AVAILABILITY (was: Reduced data availability: 14 pgs inactive)
2023-05-03T22:46:32.238 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:31 smithi018 ceph-mon[94987]: Health check cleared: PG_DEGRADED (was: Degraded data redundancy: 1325/8178 objects degraded (16.202%), 26 pgs degraded, 26 pgs undersized)
2023-05-03T22:46:32.238 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:31 smithi018 ceph-mon[94987]: 1 slow requests, 1 included below; oldest blocked for > 184.535205 secs
2023-05-03T22:46:32.239 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:31 smithi018 ceph-mon[94987]: slow request 184.535204 seconds old, received at 2023-05-03T22:43:27.057774+0000: client_request(mds.2:80 rename #0x60b/10000000524 #0x615/10000000524 caller_uid=0, caller_gid=0{}) currently requesting remote authpins
2023-05-03T22:46:32.271 INFO:journalctl@ceph.mon.c.smithi026.stdout:May 03 22:46:31 smithi026 ceph-mon[95442]: Health check cleared: PG_AVAILABILITY (was: Reduced data availability: 14 pgs inactive)
2023-05-03T22:46:32.272 INFO:journalctl@ceph.mon.c.smithi026.stdout:May 03 22:46:31 smithi026 ceph-mon[95442]: Health check cleared: PG_DEGRADED (was: Degraded data redundancy: 1325/8178 objects degraded (16.202%), 26 pgs degraded, 26 pgs undersized)
2023-05-03T22:46:32.272 INFO:journalctl@ceph.mon.c.smithi026.stdout:May 03 22:46:31 smithi026 ceph-mon[95442]: 1 slow requests, 1 included below; oldest blocked for > 184.535205 secs
2023-05-03T22:46:32.272 INFO:journalctl@ceph.mon.c.smithi026.stdout:May 03 22:46:31 smithi026 ceph-mon[95442]: slow request 184.535204 seconds old, received at 2023-05-03T22:43:27.057774+0000: client_request(mds.2:80 rename #0x60b/10000000524 #0x615/10000000524 caller_uid=0, caller_gid=0{}) currently requesting remote authpins
2023-05-03T22:46:33.237 INFO:journalctl@ceph.mgr.y.smithi018.stdout:May 03 22:46:32 smithi018 ceph-4dfb0dbe-ea02-11ed-9b01-001a4aab830c-mgr-y[96470]: 2023-05-03T22:46:32.917+0000 7f413c0fc700 -1 client.25628: SimpleRADOSStriper: lock: snap_db_v0.db: waiting for locks:  lockers exclusive=1 tag= lockers=[client.15444:0e7f1cb7-d7d7-4986-a076-35085386d4cf:v1:172.21.15.7:0/1613962254]
2023-05-03T22:46:33.238 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:32 smithi018 ceph-mon[94987]: Health check failed: 1 MDSs report slow requests (MDS_SLOW_REQUEST)
2023-05-03T22:46:33.238 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:32 smithi018 ceph-mon[94987]: mds.? [v2:172.21.15.18:6836/3125860468,v1:172.21.15.18:6837/3125860468] up:active
2023-05-03T22:46:33.239 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:32 smithi018 ceph-mon[94987]: fsmap cephfs:3 {0=b=up:active,1=i=up:active,2=h=up:active} 3 up:standby-replay 6 up:standby
2023-05-03T22:46:33.239 INFO:journalctl@ceph.mon.b.smithi018.stdout:May 03 22:46:32 smithi018 ceph-mon[94987]: pgmap v64: 97 pgs: 1 active+undersized+remapped, 96 active+clean; 6.2 GiB data, 19 GiB used, 1.0 TiB / 1.0 TiB avail; 7.0 KiB/s rd, 170 B/s wr, 5 op/s; 14 B/s, 10 keys/s, 0 objects/s recovering
2023-05-03T22:46:33.271 INFO:journalctl@ceph.mon.c.smithi026.stdout:May 03 22:46:32 smithi026 ceph-mon[95442]: Health check failed: 1 MDSs report slow requests (MDS_SLOW_REQUEST)

A new link request came after the *#0x10000000007/0000000100000000000000C4 * was unlinked:

2023-05-03T22:43:27.054+0000 7f47f0d39700  1 -- [v2:172.21.15.18:6836/3125860468,v1:172.21.15.18:6837/3125860468] <== client.25007 172.21.15.7:0/2166797606 686 ==== client_request(client.25007:3087 link #0x10000000007/0000000100000000000000C4 #0x10000000007/00000001000000000000008E 2023-05-03T22:43:27.053778+0000 caller_uid=26, caller_gid=26{26,}) v4 ==== 304+0+0 (secure 0 0 0) 0x55b957b0f800 con 0x55b957538c00                                                2023-05-03T22:43:27.054+0000 7f47f0d39700  4 mds.2.server handle_client_request client_request(client.25007:3087 link #0x10000000007/0000000100000000000000C4 #0x10000000007/00000001000000000000008E 2023-05-03T22:43:27.053778+0000 caller_uid=26, caller_gid=26{26,}) v4

After discovering the remote dentry 00000001000000000000008E from mds.1 it will retry the link request:

2023-05-03T22:43:27.054+0000 7f47f0d39700 12 mds.2.cache traverse: path seg depth 0 '00000001000000000000008E' snapid head
2023-05-03T22:43:27.054+0000 7f47f0d39700 20 mds.2.cache.dir(0x10000000007.001*) lookup (00000001000000000000008E, 'head')
2023-05-03T22:43:27.054+0000 7f47f0d39700 12 mds.2.cache traverse: miss on dentry 00000001000000000000008E in [dir 0x10000000007.001* /volumes/_nogroup/sv_1/ae8b8a6c-cc22-4750-bb9a-eed68342dd66/postgres/data/pg_wal/ [2,head] rep@1.1 REP dir_auth=1 state=0 f(v4 m2023-05-03T22:42:43.128466+0000 10=10+0) n(v4 rc2023-05-03T22:42:43.132466+0000 b167772160 10=10+0) hs=0+0,ss=0+0 | dnwaiter=0 child=0 subtree=1 0x55b957733600]
...
2023-05-03T22:43:27.054+0000 7f47f0d39700  1 -- [v2:172.21.15.18:6836/3125860468,v1:172.21.15.18:6837/3125860468] send_to--> mds [v2:172.21.15.26:6838/1214601057,v1:172.21.15.26:6839/1214601057] -- discover(105 0x10000000007.001* 00000001000000000000008E) v1 -- ?+0 0x55b9579e1520
...
2023-05-03T22:43:27.055+0000 7f47f0d39700  1 -- [v2:172.21.15.18:6836/3125860468,v1:172.21.15.18:6837/3125860468] <== mds.1 v2:172.21.15.26:6838/1214601057 1015 ==== discover_reply(105 0x10000000007) v2 ==== 108+0+0 (unknown 0 0 0) 0x55b957aa3c00 con 0x55b957539c00
2023-05-03T22:43:27.055+0000 7f47f0d39700  7 mds.2.cache discover_reply discover_reply(105 0x10000000007) v2
2023-05-03T22:43:27.055+0000 7f47f0d39700 10 mds.2.cache  found tid 105
2023-05-03T22:43:27.055+0000 7f47f0d39700 20 mds.2.cache.dir(0x10000000007.001*) lookup (00000001000000000000008E, 'head')
2023-05-03T22:43:27.055+0000 7f47f0d39700 20 mds.2.cache.dir(0x10000000007.001*) lookup_exact_snap (head, '00000001000000000000008E')
2023-05-03T22:43:27.055+0000 7f47f0d39700 12 mds.2.cache.dir(0x10000000007.001*) add_null_dentry [dentry #0x1/volumes/_nogroup/sv_1/ae8b8a6c-cc22-4750-bb9a-eed68342dd66/postgres/data/pg_wal/00000001000000000000008E [1,head] rep@1.0 NULL (dversion lock) v=0 ino=(nil) state=64|bottomlru 0x55b95727b680]
2023-05-03T22:43:27.055+0000 7f47f0d39700  7 mds.2.cache decode_replica_dentry added [dentry #0x1/volumes/_nogroup/sv_1/ae8b8a6c-cc22-4750-bb9a-eed68342dd66/postgres/data/pg_wal/00000001000000000000008E [1,head] rep@1.0 NULL (dversion lock) v=0 ino=(nil) state=64|bottomlru 0x55b95727b680]
2023-05-03T22:43:27.055+0000 7f47f0d39700 12 mds.2.cache.dir(0x10000000007.001*) link_remote_inode [dentry #0x1/volumes/_nogroup/sv_1/ae8b8a6c-cc22-4750-bb9a-eed68342dd66/postgres/data/pg_wal/00000001000000000000008E [3,head] rep@1.1 NULL (dversion lock) v=0 ino=(nil) state=64|bottomlru 0x55b95727b680] remote 0x10000000524
2023-05-03T22:43:27.055+0000 7f47f0d39700 10 mds.2.cache.dir(0x10000000007.001*) take_dentry_waiting 00000001000000000000008E [3,head] found waiter on snap head on [dir 0x10000000007.001* /volumes/_nogroup/sv_1/ae8b8a6c-cc22-4750-bb9a-eed68342dd66/postgres/data/pg_wal/ [2,head] rep@1.1 REP dir_auth=1 state=0 f(v4 m2023-05-03T22:42:43.128466+0000 10=10+0) n(v4 rc2023-05-03T22:42:43.132466+0000 b167772160 10=10+0) hs=1+0,ss=0+0 | dnwaiter=1 child=1 subtree=1 0x55b957733600]
...
2023-05-03T22:43:27.055+0000 7f47f0d39700  7 mds.2.20 mds has 1 queued contexts
2023-05-03T22:43:27.055+0000 7f47f0d39700 10 mds.2.20  finish 0x55b957281120
2023-05-03T22:43:27.055+0000 7f47f0d39700 10 MDSContext::complete: 18C_MDS_RetryRequest
2023-05-03T22:43:27.055+0000 7f47f0d39700  7 mds.2.server dispatch_client_request client_request(client.25007:3087 link #0x10000000007/0000000100000000000000C4 #0x10000000007/00000001000000000000008E 2023-05-03T22:43:27.053778+0000 caller_uid=26, caller_gid=26{26,}) v4
...

While this time since it found the 00000001000000000000008E was a remove dentry, then it will trigger to migrate the straydn to mds.1:

2023-05-03T22:43:27.055+0000 7f47f0d39700 12 mds.2.cache traverse: path seg depth 0 '00000001000000000000008E' snapid head
2023-05-03T22:43:27.055+0000 7f47f0d39700 20 mds.2.cache.dir(0x10000000007.001*) lookup (00000001000000000000008E, 'head')
2023-05-03T22:43:27.055+0000 7f47f0d39700 20 mds.2.cache.dir(0x10000000007.001*)   hit -> (00000001000000000000008E,head)
2023-05-03T22:43:27.055+0000 7f47f0d39700  7 mds.2.cache linking in remote in [inode 0x10000000524 [...4,head] ~mds2/stray1/10000000524 auth{1=2} v2589 pv2593 ap=3 snaprealm=0x55b9579fbd40 DIRTYPARENT s=16777216 n(v0 rc2023-05-03T22:43:05.925109+0000 b16777216 1=1+0)->n(v0 rc2023-05-03T22:43:05.925109+0000 b16777216 1=1+0) (ifile lock->excl w=2) (iversion lock) cr={25007=0-37748736@2} caps={25007=pAsLsXsFcb/pAsxXsxFsxcrwb@61},l=25007(-1) mcw={1=AsXsFscr} | ptrwaiter=2 request=0 lock=1 importingcaps=0 caps=1 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 scrubqueue=0 0x55b957a1a580]
2023-05-03T22:43:27.055+0000 7f47f0d39700 10 mds.2.cache.strays eval_remote [dentry #0x1/volumes/_nogroup/sv_1/ae8b8a6c-cc22-4750-bb9a-eed68342dd66/postgres/data/pg_wal/00000001000000000000008E [3,head] rep@1.1 REMOTE(reg) (dversion lock) v=0 ino=0x10000000524 state=0 0x55b95727b680]
2023-05-03T22:43:27.055+0000 7f47f0d39700 20 mds.2.cache.strays _eval_stray_remote [dentry #0x102/stray1/10000000524 [3,head] auth{1=1} (dversion lock) pv=2593 v=2589 ino=0x10000000524 state=1879048193|new | request=0 lock=0 inodepin=1 replicated=1 dirty=1 authpin=0 0x55b957967680]
2023-05-03T22:43:27.055+0000 7f47f0d39700 10 mds.2.cache.strays migrate_stray [dentry #0x102/stray1/10000000524 [3,head] auth{1=1} (dversion lock) pv=2593 v=2589 ino=0x10000000524 state=1879048193|new | request=0 lock=0 inodepin=1 replicated=1 dirty=1 authpin=0 0x55b957967680] to mds.1
2023-05-03T22:43:27.055+0000 7f47f0d39700  1 -- [v2:172.21.15.18:6836/3125860468,v1:172.21.15.18:6837/3125860468] send_to--> mds [v2:172.21.15.26:6838/1214601057,v1:172.21.15.26:6839/1214601057] -- client_request(unknown.0:80 rename #0x60b/10000000524 #0x615/10000000524 caller_uid=0, caller_gid=0{}) v6 -- ?+0 0x55b9579b0600
2023-05-03T22:43:27.055+0000 7f47f0d39700  1 -- [v2:172.21.15.18:6836/3125860468,v1:172.21.15.18:6837/3125860468] --> [v2:172.21.15.26:6838/1214601057,v1:172.21.15.26:6839/1214601057] -- client_request(unknown.0:80 rename #0x60b/10000000524 #0x615/10000000524 caller_uid=0, caller_gid=0{}) v6 -- 0x55b9579b0600 con 0x55b957539c00
...

And then without the migrating to finish the link request will continue by authpin the inode:

2023-05-03T22:43:27.055+0000 7f47f0d39700 10 mds.2.cache path_traverse finish on snapid head
2023-05-03T22:43:27.055+0000 7f47f0d39700 10 mds.2.locker acquire_locks request(client.25007:3087 nref=3 cr=0x55b957b0f800)
2023-05-03T22:43:27.055+0000 7f47f0d39700 20 mds.2.locker  must wrlock (ifile mix dirty) [inode 0x10000000007 [...4,head] /volumes/_nogroup/sv_1/ae8b8a6c-cc22-4750-bb9a-eed68342dd66/postgres/data/pg_wal/ rep@0.1 fragtree_t(*^3) v2151 f(v9 m2023-05-03T22:43:26.783783+0000 66=65+1) n(v8 rc2023-05-03T22:43:16.764939+0000 b486539264 31=29+2)/n(v0 rc2023-05-03T22:41:42.662406+0000 b12582912 3=1+2) (isnap sync r=1) (inest mix dirty) (ifile mix dirty) (iversion lock) caps={25007=pAsLsXs/pAsLsXsFsxcral@128} | dirtyscattered=2 request=0 lock=1 importing=0 dirfrag=6 caps=1 dirwaiter=0 waiter=0 discoverbase=0 0x55b9576a4580]
...
2023-05-03T22:43:27.056+0000 7f47f0d39700 10 mds.2.locker  must authpin [inode 0x10000000524 [...4,head] ~mds2/stray1/10000000524 auth{1=2} v2589 pv2593 ap=3 snaprealm=0x55b9579fbd40 DIRTYPARENT s=16777216 n(v0 rc2023-05-03T22:43:05.925109+0000 b16777216 1=1+0)->n(v0 rc2023-05-03T22:43:05.925109+0000 b16777216 1=1+0) (ifile lock->excl w=2) (iversion lock) cr={25007=0-37748736@2} caps={25007=pAsLsXsFcb/pAsxXsxFsxcrwb@61},l=25007(-1) mcw={1=AsXsFscr} | ptrwaiter=2 request=0 lock=1 importingcaps=0 caps=1 remoteparent=1 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 scrubqueue=0 0x55b957a1a580]                                                                                         
2023-05-03T22:43:27.056+0000 7f47f0d39700 10 mds.2.locker  auth_pinning [inode 0x10000000524 [...4,head] ~mds2/stray1/10000000524 auth{1=2} v2589 pv2593 ap=3 snaprealm=0x55b9579fbd40 DIRTYPARENT s=16777216 n(v0 rc2023-05-03T22:43:05.925109+0000 b16777216 1=1+0)->n(v0 rc2023-05-03T22:43:05.925109+0000 b16777216 1=1+0) (ifile lock->excl w=2) (iversion lock) cr={25007=0-37748736@2} caps={25007=pAsLsXsFcb/pAsxXsxFsxcrwb@61},l=25007(-1) mcw={1=AsXsFscr} | ptrwaiter=2 request=0 lock=1 importingcaps=0 caps=1 remoteparent=1 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 scrubqueue=0 0x55b957a1a580]
2023-05-03T22:43:27.056+0000 7f47f0d39700 10 mds.2.cache.ino(0x10000000524) auth_pin by 0x55b9579e3c00 on [inode 0x10000000524 [...4,head] ~mds2/stray1/10000000524 auth{1=2} v2589 pv2593 ap=4 snaprealm=0x55b9579fbd40 DIRTYPARENT s=16777216 n(v0 rc2023-05-03T22:43:05.925109+0000 b16777216 1=1+0)->n(v0 rc2023-05-03T22:43:05.925109+0000 b16777216 1=1+0) (ifile lock->excl w=2) (iversion lock) cr={25007=0-37748736@2} caps={25007=pAsLsXsFcb/pAsxXsxFsxcrwb@61},l=25007(-1) mcw={1=AsXsFscr} | ptrwaiter=2 request=0 lock=1 importingcaps=0 caps=1 remoteparent=1 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 scrubqueue=0 0x55b957a1a580] now 4
...

And then it went to sleep due to the rename request from mds.1 has request to freeze authpin:

24 auth{1=2} v2593 ap=2 snaprealm=0x55b9579fbd40 DIRTYPARENT FREEZING=1 s=16777216 n(v0 rc2023-05-03T22:43:05.925109+0000 b16777216 1=1+0) (ifile excl) (iversion lock) cr={25007=0-37748736@3} caps={25007=pAsXsFsxcrwb/pAsxXsxFsxcrwb@65},l=25007(-1) mcw={1=AsXsFscr} | ptrwaiter=2 request=1 lock=0 importingcaps=0 caps=1 remoteparent=1 freezing=1 dirtyparent=1 replicated=1 dirty=1 waiter=1 authpin=1 scrubqueue=0 0x55b957a1a580]
2023-05-03T22:43:27.059+0000 7f47f0d39700 20 mds.2.locker  client.25007 pending pAsXsFsxcrwb allowed pAsLsXsFsxcrwb wanted pAsxXsxFsxcrwb
2023-05-03T22:43:27.059+0000 7f47f0d39700 10 mds.2.cache.ino(0x10000000524) add_waiter tag 10 0x55b9578bbd40 !ambig 1 !frozen 1 !freezing 0
2023-05-03T22:43:27.059+0000 7f47f0d39700 15 mds.2.cache.ino(0x10000000524) taking waiter here
2023-05-03T22:43:27.059+0000 7f47f0d39700  7 mds.2.locker try_eval (ilink sync) freezing, waiting on [inode 0x10000000524 [...4,head] ~mds2/stray1/10000000524 auth{1=2} v2593 ap=2 snaprealm=0x55b9579fbd40 DIRTYPARENT FREEZING=1 s=16777216 n(v0 rc2023-05-03T22:43:05.925109+0000 b16777216 1=1+0) (ifile excl) (iversion lock) cr={25007=0-37748736@3} caps={25007=pAsXsFsxcrwb/pAsxXsxFsxcrwb@65},l=25007(-1) mcw={1=AsXsFscr} | ptrwaiter=2 request=1 lock=0 importingcaps=0 caps=1 remoteparent=1 freezing=1 dirtyparent=1 replicated=1 dirty=1 waiter=1 authpin=1 scrubqueue=0 0x55b957a1a580]
2023-05-03T22:43:27.059+0000 7f47f0d39700 10 mds.2.cache.ino(0x10000000524) add_waiter tag 800000000000000 0x55b957ccd920 !ambig 1 !frozen 1 !freezing 0
2023-05-03T22:43:27.059+0000 7f47f0d39700 15 mds.2.cache.ino(0x10000000524) taking waiter here

The rename request from mds.1, though it get the authpin_ack but that's just a notification that the authpin was blocked:

2023-05-03T22:43:27.057+0000 7f0ce0f13700  4 mds.1.server handle_client_request client_request(mds.2:80 rename #0x60b/10000000524 #0x615/10000000524 caller_uid=0, caller_gid=0{}) v6
2023-05-03T22:43:27.057+0000 7f0ce0f13700  7 mds.1.cache request_start request(mds.2:80 nref=2 cr=0x55a435ba0c00)
2023-05-03T22:43:27.057+0000 7f0ce0f13700  7 mds.1.server dispatch_client_request client_request(mds.2:80 rename #0x60b/10000000524 #0x615/10000000524 caller_uid=0, caller_gid=0{}) v6
2023-05-03T22:43:27.057+0000 7f0ce0f13700  7 mds.1.server handle_client_rename client_request(mds.2:80 rename #0x60b/10000000524 #0x615/10000000524 caller_uid=0, caller_gid=0{}) v6                                                   
2023-05-03T22:43:27.057+0000 7f0ce0f13700 10 mds.1.server rdlock_two_paths_xlock_destdn request(mds.2:80 nref=2 cr=0x55a435ba0c00) #0x60b/10000000524 #0x615/10000000524
2023-05-03T22:43:27.057+0000 7f0ce0f13700  7 mds.1.cache traverse: opening base ino 0x60b snap head
...
2023-05-03T22:43:27.057+0000 7f0ce0f13700 10 mds.1.locker  req remote auth_pin of [inode 0x10000000524 [...4,head] ~mds2/stray1/10000000524 rep@2.2 v2589 snaprealm=0x55a436e63b00 s=16777216 n(v0 rc2023-05-03T22:42:58.262229+0000 b16777216 1=1+0) (ifile lock) (iversion lock) cr={25007=0-37748736@2} caps={25007=pLs/pAsxXsxFsxcrwb@79} | request=0 lock=0 caps=1 remoteparent=1 waiter=0 0x55a436fae100]
2023-05-03T22:43:27.057+0000 7f0ce0f13700  1 -- [v2:172.21.15.26:6838/1214601057,v1:172.21.15.26:6839/1214601057] send_to--> mds [v2:172.21.15.18:6836/3125860468,v1:172.21.15.18:6837/3125860468] -- peer_request(mds.2:80.0 authpin) v1 -- ?+0 0x55a437138380
2023-05-03T22:43:27.057+0000 7f0ce0f13700  1 -- [v2:172.21.15.26:6838/1214601057,v1:172.21.15.26:6839/1214601057] --> [v2:172.21.15.18:6836/3125860468,v1:172.21.15.18:6837/3125860468] -- peer_request(mds.2:80.0 authpin) v1 -- 0x55a437138380 con 0x55a436b4f400
2023-05-03T22:43:27.057+0000 7f0ce0f13700  1 -- [v2:172.21.15.26:6838/1214601057,v1:172.21.15.26:6839/1214601057] <== mds.2 v2:172.21.15.18:6836/3125860468 1224 ==== lock(a=lock isnap 0x10000000524.head) v1 ==== 69+0+0 (crc 0 0 0) 0x55a435b9d880 con 0x55a436b4f400
2023-05-03T22:43:27.057+0000 7f0ce0f13700 10 mds.1.locker handle_simple_lock lock(a=lock isnap 0x10000000524.head) v1 on (isnap sync) [inode 0x10000000524 [...4,head] ~mds2/stray1/10000000524 rep@2.2 v2589 snaprealm=0x55a436e63b00 s=16777216 n(v0 rc2023-05-03T22:42:58.262229+0000 b16777216 1=1+0) (ifile lock) (iversion lock) cr={25007=0-37748736@2} caps={25007=pLs/pAsxXsxFsxcrwb@79} | request=1 lock=0 caps=1 remoteparent=1 waiter=0 0x55a436fae100]
2023-05-03T22:43:27.057+0000 7f0ce0f13700 10 mds.1.locker eval_gather (isnap sync->lock) on [inode 0x10000000524 [...4,head] ~mds2/stray1/10000000524 rep@2.2 v2589 snaprealm=0x55a436e63b00 s=16777216 n(v0 rc2023-05-03T22:42:58.262229+0000 b16777216 1=1+0) (ifile lock) (iversion lock) cr={25007=0-37748736@2} caps={25007=pLs/pAsxXsxFsxcrwb@79} | request=1 lock=0 caps=1 remoteparent=1 waiter=0 0x55a436fae100]
2023-05-03T22:43:27.057+0000 7f0ce0f13700  7 mds.1.locker eval_gather finished gather on (isnap sync->lock) on [inode 0x10000000524 [...4,head] ~mds2/stray1/10000000524 rep@2.2 v2589 snaprealm=0x55a436e63b00 s=16777216 n(v0 rc2023-05-03T22:42:58.262229+0000 b16777216 1=1+0) (ifile lock) (iversion lock) cr={25007=0-37748736@2} caps={25007=pLs/pAsxXsxFsxcrwb@79} | request=1 lock=0 caps=1 remoteparent=1 waiter=0 0x55a436fae100]
2023-05-03T22:43:27.057+0000 7f0ce0f13700  1 -- [v2:172.21.15.26:6838/1214601057,v1:172.21.15.26:6839/1214601057] send_to--> mds [v2:172.21.15.18:6836/3125860468,v1:172.21.15.18:6837/3125860468] -- lock(a=lockack isnap 0x10000000524.head) v1 -- ?+0 0x55a437101c00
2023-05-03T22:43:27.057+0000 7f0ce0f13700  1 -- [v2:172.21.15.26:6838/1214601057,v1:172.21.15.26:6839/1214601057] --> [v2:172.21.15.18:6836/3125860468,v1:172.21.15.18:6837/3125860468] -- lock(a=lockack isnap 0x10000000524.head) v1 -- 0x55a437101c00 con 0x55a436b4f400
2023-05-03T22:43:27.058+0000 7f0ce0f13700  1 -- [v2:172.21.15.26:6838/1214601057,v1:172.21.15.26:6839/1214601057] <== mds.2 v2:172.21.15.18:6836/3125860468 1225 ==== peer_request(mds.2:80.0 authpin_ack) v1 ==== 139+0+0 (crc 0 0 0) 0x55a437138380 con 0x55a436b4f400
2023-05-03T22:43:27.058+0000 7f0ce0f13700  4 mds.1.server handle_peer_request mds.2:80 from mds.2
2023-05-03T22:43:27.058+0000 7f0ce0f13700  7 mds.1.cache request_get mds.2:80 request(mds.2:80 nref=1 cr=0x55a435ba0c00)
2023-05-03T22:43:27.058+0000 7f0ce0f13700 10 mds.1.server handle_peer_auth_pin_ack on request(mds.2:80 nref=2 cr=0x55a435ba0c00) peer_request(mds.2:80.0 authpin_ack) v1
2023-05-03T22:43:27.058+0000 7f0ce0f13700  7 mds.1.locker rdlock_finish on (isnap sync) on [inode 0x101 [...4,head] ~mds1/ auth{0=17,2=11} v12 snaprealm=0x55a435c938c0 DIRTYPARENT f(v0 10=0+10) n(v5 rc2023-05-03T22:43:26.783783+0000 b268435456 27=16+11)/n(v0 rc2023-05-03T22:40:02.322228+0000 11=0+11) old_inodes=2 (inest mix dirty) (iversion lock) | dirtyscattered=1 lock=0 dirfrag=1 dirtyparent=1 replicated=1 dirty=1 authpin=0 0x55a435bf6680]
2023-05-03T22:43:27.058+0000 7f0ce0f13700 10 mds.1.locker simple_eval (isnap sync) on [inode 0x101 [...4,head] ~mds1/ auth{0=17,2=11} v12 snaprealm=0x55a435c938c0 DIRTYPARENT f(v0 10=0+10) n(v5 rc2023-05-03T22:43:26.783783+0000 b268435456 27=16+11)/n(v0 rc2023-05-03T22:40:02.322228+0000 11=0+11) old_inodes=2 (inest mix dirty) (iversion lock) | dirtyscattered=1 lock=0 dirfrag=1 dirtyparent=1 replicated=1 dirty=1 authpin=0 0x55a435bf6680]
2023-05-03T22:43:27.058+0000 7f0ce0f13700  7 mds.1.locker rdlock_finish on (isnap sync) on [inode 0x60b [...4,head] ~mds1/stray1/ auth{0=17,2=11} v404 ap=1 DIRTYPARENT f(v0 m2023-05-03T22:43:27.033779+0000 15=15+0) n(v0 rc2023-05-03T22:43:27.033779+0000 b251658240 16=15+1) old_inodes=2 (inest mix) (iversion lock) | lock=0 dirfrag=1 stickydirs=1 stray=1 dirtyrstat=0 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 0x55a435bf7180]
2023-05-03T22:43:27.058+0000 7f0ce0f13700 10 mds.1.locker simple_eval (isnap sync) on [inode 0x60b [...4,head] ~mds1/stray1/ auth{0=17,2=11} v404 ap=1 DIRTYPARENT f(v0 m2023-05-03T22:43:27.033779+0000 15=15+0) n(v0 rc2023-05-03T22:43:27.033779+0000 b251658240 16=15+1) old_inodes=2 (inest mix) (iversion lock) | lock=0 dirfrag=1 stickydirs=1 stray=1 dirtyrstat=0 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 0x55a435bf7180]
2023-05-03T22:43:27.058+0000 7f0ce0f13700  7 mds.1.locker rdlock_finish on (isnap sync) on [inode 0x102 [...4,head] ~mds2/ rep@2.20 v13 snaprealm=0x55a435cbb200 f(v0 10=0+10) n(v4 rc2023-05-03T22:43:26.907781+0000 b218103808 24=13+11)/n(v0 rc2023-05-03T22:40:03.329553+0000 11=0+11) old_inodes=2 (inest mix) (iversion lock) | lock=0 dirfrag=1 discoverbase=0 0x55a436cfd080]
2023-05-03T22:43:27.058+0000 7f0ce0f13700  7 mds.1.locker rdlock_finish on (isnap sync) on [inode 0x615 [...4,head] ~mds2/stray1/ rep@2.20 v107 f(v0 m2023-05-03T22:43:27.013779+0000 15=15+0) n(v0 rc2023-05-03T22:43:27.013779+0000 b251658240 16=15+1) old_inodes=2 (inest mix) (iversion lock) | request=1 lock=0 dirfrag=1 dirwaiter=0 discoverbase=0 0x55a436d81700]
2023-05-03T22:43:27.059+0000 7f0ce0f13700  1 -- [v2:172.21.15.26:6838/1214601057,v1:172.21.15.26:6839/1214601057] <== mds.2 v2:172.21.15.18:6836/3125860468 1226 ==== lock(a=lock ilink 0x10000000524.head) v1 ==== 69+0+0 (crc 0 0 0) 0x55a437101c00 con 0x55a436b4f400
...

Then get dealocked.

Actions

Copy link

Updated by Xiubo Li 12 months ago

From the logs evicting the unresponding client or closing the sessions could unblock the deadlock issue:

2023-05-03T22:49:01.568+0000 7f0cdcf0b700 20 mds.1.cache upkeep thread waiting interval 1.000000000s
2023-05-03T22:49:01.595+0000 7f0cdf710700  0 log_channel(cluster) log [WRN] : 1 slow requests, 0 included below; oldest blocked for > 334.538164 secs
2023-05-03T22:49:01.595+0000 7f0cdf710700 10 mds.1.log trim 1 / 128 segments, 715 / -1 events, 0 (0) expiring, 0 (0) expired 
2023-05-03T22:49:01.595+0000 7f0cdf710700 10 mds.1.log _trim_expired_segments waiting for 1/4194304 to expire
2023-05-03T22:49:01.595+0000 7f0cdf710700 10 mds.1.server find_idle_sessions. last cleared laggy state 2147.74s ago
2023-05-03T22:49:01.595+0000 7f0cdf710700 20 mds.1.server evicting session client.25007 172.21.15.7:0/2166797606 since autoclose has arrived                                                                                           2023-05-03T22:49:01.595+0000 7f0cdf710700  0 log_channel(cluster) log [WRN] : evicting unresponsive client smithi007:0 (25007), after 306.204 seconds
2023-05-03T22:49:01.595+0000 7f0cdf710700 10 mds.1.server autoclosing stale session client.25007 172.21.15.7:0/2166797606 last renewed caps 306.204s ago
2023-05-03T22:49:01.595+0000 7f0cdf710700  1 mds.1.18 Evicting (and blocklisting) client session 25007 (172.21.15.7:0/2166797606)
2023-05-03T22:49:01.595+0000 7f0cdf710700  0 log_channel(cluster) log [INF] : Evicting (and blocklisting) client session 25007 (172.21.15.7:0/2166797606)
2023-05-03T22:49:01.595+0000 7f0cdf710700  4 mds.1.18 Preparing blocklist command... (wait=0)
2023-05-03T22:49:01.595+0000 7f0cdf710700  4 mds.1.18 Sending mon blocklist command: {"prefix":"osd blocklist", "blocklistop":"add","addr":"172.21.15.7:0/2166797606"}
2023-05-03T22:49:01.595+0000 7f0cdf710700  1 -- [v2:172.21.15.26:6838/1214601057,v1:172.21.15.26:6839/1214601057] --> [v2:172.21.15.26:3300/0,v1:172.21.15.26:6789/0] -- mon_command({"prefix":"osd blocklist", "blocklistop":"add","addr":"172.21.15.7:0/2166797606"} v 0) v1 -- 0x55a436fc3c80 con 0x55a435b53800
2023-05-03T22:49:01.595+0000 7f0cdf710700 10 mds.1.locker scatter_tick

Actions

Copy link