Project

General

Profile

Actions

Bug #62021

open

mds: unnecessary second lock on snaplock

Added by Patrick Donnelly 10 months ago. Updated 10 months ago.

Status:
Fix Under Review
Priority:
Normal
Category:
Correctness/Safety
Target version:
% Done:

0%

Source:
Development
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
MDS
Labels (FS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

https://github.com/ceph/ceph/blob/3ca0f45de9fa00088fc670b19a3ebd8d5e778b3b/src/mds/Server.cc#L4612-L4615

2023-07-14T14:34:27.031-0400 7fe4b5942700  7 mds.0.server dispatch_client_request client_request(client.4449:3 create #0x10000000001/test 2023-07-14T14:34:27.031081-0400 caller_uid=10000, caller_gid=100{10,100,}) v4
2023-07-14T14:34:27.031-0400 7fe4b5942700  7 mds.0.server open w/ O_CREAT on #0x10000000001/test
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.server rdlock_path_xlock_dentry request(client.4449:3 nref=2 cr=0x5611264d1b00) #0x10000000001/test
2023-07-14T14:34:27.031-0400 7fe4b5942700  7 mds.0.cache traverse: opening base ino 0x10000000001 snap head
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker try_rdlock_snap_layout request(client.4449:3 nref=3 cr=0x5611264d1b00) [inode 0x10000000001 [...2,head] /bar/ auth v28 DIRTYPARENT f(v0 m2023-07-14T14:22:00.159118-0400 1=1+0) n(v0 rc2023-07-14T14:22:00.943084-0400 2=1+1) (inest lock) (ifile excl) (iversion lock) caps={4449=pAsLsXs/pAsLsXsFsx@1},l=4449 | request=0 lock=0 dirfrag=1 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x5611264f4100]
2023-07-14T14:34:27.031-0400 7fe4b5942700 20 mds.0.locker  got rdlock on (isnap sync r=1) [inode 0x10000000001 [...2,head] /bar/ auth v28 DIRTYPARENT f(v0 m2023-07-14T14:22:00.159118-0400 1=1+0) n(v0 rc2023-07-14T14:22:00.943084-0400 2=1+1) (isnap sync r=1) (inest lock) (ifile excl) (iversion lock) caps={4449=pAsLsXs/pAsLsXsFsx@1},l=4449 | request=0 lock=1 dirfrag=1 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x5611264f4100]
2023-07-14T14:34:27.031-0400 7fe4b5942700 20 mds.0.locker  got rdlock on (ipolicy sync r=1) [inode 0x10000000001 [...2,head] /bar/ auth v28 DIRTYPARENT f(v0 m2023-07-14T14:22:00.159118-0400 1=1+0) n(v0 rc2023-07-14T14:22:00.943084-0400 2=1+1) (isnap sync r=1) (inest lock) (ipolicy sync r=1) (ifile excl) (iversion lock) caps={4449=pAsLsXs/pAsLsXsFsx@1},l=4449 | request=0 lock=2 dirfrag=1 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x5611264f4100]
2023-07-14T14:34:27.031-0400 7fe4b5942700 20 mds.0.locker  got rdlock on (isnap sync r=1) [inode 0x1 [...2,head] / auth v14 snaprealm=0x5611263d1b00 DIRTYPARENT f(v0 m2023-07-14T14:21:56.313220-0400 2=1+1) n(v1 rc2023-07-14T14:22:00.943084-0400 4=2+2)/n(v0 rc2023-07-14T13:22:20.164527-0400 1=0+1) (isnap sync r=1) (inest lock) (iversion lock) caps={4449=pAsLsXsFs/-@2} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x561126496000]
2023-07-14T14:34:27.031-0400 7fe4b5942700 20 mds.0.locker  got rdlock on (ipolicy sync r=1) [inode 0x1 [...2,head] / auth v14 snaprealm=0x5611263d1b00 DIRTYPARENT f(v0 m2023-07-14T14:21:56.313220-0400 2=1+1) n(v1 rc2023-07-14T14:22:00.943084-0400 4=2+2)/n(v0 rc2023-07-14T13:22:20.164527-0400 1=0+1) (isnap sync r=1) (inest lock) (ipolicy sync r=1) (iversion lock) caps={4449=pAsLsXsFs/-@2} | dirtyscattered=0 request=0 lock=2 dirfrag=1 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x561126496000]
2023-07-14T14:34:27.031-0400 7fe4b5942700 12 mds.0.cache traverse: path seg depth 0 'test' snapid head
2023-07-14T14:34:27.031-0400 7fe4b5942700 20 mds.0.cache.dir(0x10000000001) lookup (test, 'head')
2023-07-14T14:34:27.031-0400 7fe4b5942700 20 mds.0.cache.dir(0x10000000001)   hit -> (test,head)
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker acquire_locks request(client.4449:3 nref=3 cr=0x5611264d1b00)
2023-07-14T14:34:27.031-0400 7fe4b5942700 20 mds.0.locker  must rdlock (dn sync) [dentry #0x1/bar/test [2,head] auth (dversion lock) v=6 ino=0x10000000002 state=1610612736 | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x561126620a00]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker  must authpin [dentry #0x1/bar/test [2,head] auth (dversion lock) v=6 ino=0x10000000002 state=1610612736 | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x561126620a00]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker  auth_pinning [dentry #0x1/bar/test [2,head] auth (dversion lock) v=6 ino=0x10000000002 state=1610612736 | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x561126620a00]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.cache.den(0x10000000001 test) auth_pin by 0x5611264d5600 on [dentry #0x1/bar/test [2,head] auth (dversion lock) v=6 ap=1 ino=0x10000000002 state=1610612736 | request=0 lock=0 inodepin=1 dirty=1 authpin=1 0x561126620a00] now 1
2023-07-14T14:34:27.031-0400 7fe4b5942700 15 mds.0.cache.dir(0x10000000001) adjust_nested_auth_pins 1 on [dir 0x10000000001 /bar/ [2,head] auth v=7 cv=0/0 ap=0+1 state=1610612737|complete f(v0 m2023-07-14T14:22:00.159118-0400 1=1+0) n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) hs=1+0,ss=0+0 dirty=1 | child=1 dirty=1 authpin=0 0x561126652400] by 0x5611264d5600 count now 0/1
2023-07-14T14:34:27.031-0400 7fe4b5942700  7 mds.0.locker rdlock_start  on (dn sync) on [dentry #0x1/bar/test [2,head] auth (dversion lock) v=6 ap=1 ino=0x10000000002 state=1610612736 | request=0 lock=0 inodepin=1 dirty=1 authpin=1 0x561126620a00]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker  got rdlock on (dn sync r=1) [dentry #0x1/bar/test [2,head] auth (dn sync r=1) (dversion lock) v=6 ap=1 ino=0x10000000002 state=1610612736 | request=0 lock=1 inodepin=1 dirty=1 authpin=1 0x561126620a00]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker acquire_locks request(client.4449:3 nref=3 cr=0x5611264d1b00)
2023-07-14T14:34:27.031-0400 7fe4b5942700 20 mds.0.locker  must rdlock (isnap sync) [inode 0x10000000002 [2,head] /bar/test auth v6 DIRTYPARENT s=0 n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x5611264f4680]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker  must authpin [inode 0x10000000002 [2,head] /bar/test auth v6 DIRTYPARENT s=0 n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x5611264f4680]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker  auth_pinning [inode 0x10000000002 [2,head] /bar/test auth v6 DIRTYPARENT s=0 n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x5611264f4680]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.cache.ino(0x10000000002) auth_pin by 0x5611264d5600 on [inode 0x10000000002 [2,head] /bar/test auth v6 ap=1 DIRTYPARENT s=0 n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x5611264f4680] now 1
2023-07-14T14:34:27.031-0400 7fe4b5942700 15 mds.0.cache.dir(0x10000000001) adjust_nested_auth_pins 1 on [dir 0x10000000001 /bar/ [2,head] auth v=7 cv=0/0 ap=0+2 state=1610612737|complete f(v0 m2023-07-14T14:22:00.159118-0400 1=1+0) n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) hs=1+0,ss=0+0 dirty=1 | child=1 dirty=1 authpin=0 0x561126652400] by 0x5611264f4680 count now 0/2
2023-07-14T14:34:27.031-0400 7fe4b5942700  7 mds.0.locker rdlock_start  on (isnap sync) on [inode 0x10000000002 [2,head] /bar/test auth v6 ap=1 DIRTYPARENT s=0 n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x5611264f4680]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker  got rdlock on (isnap sync r=1) [inode 0x10000000002 [2,head] /bar/test auth v6 ap=1 DIRTYPARENT s=0 n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=1 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x5611264f4680]
2023-07-14T14:34:27.031-0400 7fe4b5942700  7 mds.0.cache found target [inode 0x10000000002 [2,head] /bar/test auth v6 ap=1 DIRTYPARENT s=0 n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=1 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x5611264f4680]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.cache path_traverse finish on snapid head
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker acquire_locks request(client.4449:3 nref=2 cr=0x5611264d1b00)
2023-07-14T14:34:27.031-0400 7fe4b5942700 20 mds.0.locker  must rdlock (isnap sync r=1) [inode 0x10000000002 [2,head] /bar/test auth v6 ap=1 DIRTYPARENT s=0 n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=1 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x5611264f4680]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker  must authpin [inode 0x10000000002 [2,head] /bar/test auth v6 ap=1 DIRTYPARENT s=0 n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=1 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x5611264f4680]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker  already auth_pinned [inode 0x10000000002 [2,head] /bar/test auth v6 ap=1 DIRTYPARENT s=0 n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=1 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x5611264f4680]
2023-07-14T14:34:27.031-0400 7fe4b5942700 10 mds.0.locker  already rdlocked (isnap sync r=1) [inode 0x10000000002 [2,head] /bar/test auth v6 ap=1 DIRTYPARENT s=0 n(v0 rc2023-07-14T14:22:00.943084-0400 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=1 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x5611264f4680]

For openc, rdlock_path_xlock_dentry always gets a rdlock on the final directory in the path.

This does not create any type of bug. It's just superfluous code.

Actions #1

Updated by Patrick Donnelly 10 months ago

  • Status changed from In Progress to Fix Under Review
  • Pull request ID set to 52462
Actions

Also available in: Atom PDF