Actions
Bug #2019
closedmds: CInode::filelock stuck in sync->mix
Added by Greg Farnum about 12 years ago. Updated over 10 years ago.
Status:
Resolved
Priority:
Normal
Assignee:
-
Category:
-
Target version:
-
% Done:
0%
Source:
Tags:
Backport:
Regression:
Severity:
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
Labels (FS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
Reported by Kioob`Taff in irc. Some logging is available at gregf@kai:~/logs/kioob. Unfortunately not of the lock getting into that state, though. Anyway this was detected because several requests come in which hang on getting a readlock on ifile, which it can't while in that state. Looking through the logs we have, the inode never does anything on its own behalf, only appearing in the log when other requests try and grab it or whatever. Why isn't it exiting this state?
Updated by Sage Weil over 11 years ago
- Project changed from Ceph to CephFS
- Category deleted (
1)
Updated by Greg Farnum over 11 years ago
- Status changed from New to Can't reproduce
Presumably we'll see this again, but it hasn't turned up in our testing lately and we need more info to debug it.
Updated by Milosz Tanski almost 11 years ago
I'm into this as part of bug: #5036
root@c-mds-223d7f41:/var/log/ceph# cat /tmp/mds.log.txt | grep '10000003dae'
2013-07-03 21:08:39.166930 7fe31b107700 7 mds.0.server dispatch_client_request client_request(client.16961:1591 getattr pAsLsXsFs #10000003dae)
2013-07-03 21:08:39.166943 7fe31b107700 10 mds.0.server rdlock_path_pin_ref request(client.16961:1591 cr=0x433e780) #10000003dae
2013-07-03 21:08:39.166952 7fe31b107700 7 mds.0.cache traverse: opening base ino 10000003dae snap head
2013-07-03 21:08:39.166964 7fe31b107700 10 mds.0.server ref is [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=8+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=7 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.167286 7fe31b107700 20 mds.0.locker must rdlock (iauth sync) [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=8+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.167319 7fe31b107700 20 mds.0.locker must rdlock (ilink sync) [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=8+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.167346 7fe31b107700 20 mds.0.locker must rdlock (ifile mix->sync) [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=8+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.167374 7fe31b107700 20 mds.0.locker must rdlock (ixattr sync) [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=8+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.167401 7fe31b107700 20 mds.0.locker must rdlock (isnap sync r=7) [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=8+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.167541 7fe31b107700 10 mds.0.locker must authpin [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=8+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.167568 7fe31b107700 10 mds.0.locker must authpin [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=8+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.167593 7fe31b107700 10 mds.0.locker must authpin [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=8+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.167618 7fe31b107700 10 mds.0.locker must authpin [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=8+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.167643 7fe31b107700 10 mds.0.locker must authpin [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=8+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.167931 7fe31b107700 10 mds.0.locker auth_pinning [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=8+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.167957 7fe31b107700 10 mds.0.cache.ino(10000003dae) auth_pin by 0x9783800 on [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=9+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080] now 9+0
2013-07-03 21:08:39.168003 7fe31b107700 10 mds.0.locker already auth_pinned [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=9+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.168030 7fe31b107700 10 mds.0.locker already auth_pinned [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=9+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.168055 7fe31b107700 10 mds.0.locker already auth_pinned [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=9+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.168080 7fe31b107700 10 mds.0.locker already auth_pinned [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=9+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.168325 7fe31b107700 7 mds.0.locker rdlock_start on (isnap sync r=7) on [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=9+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.168352 7fe31b107700 10 mds.0.locker got rdlock on (isnap sync r=8) [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=9+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.168378 7fe31b107700 7 mds.0.locker rdlock_start on (ifile mix->sync) on [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=9+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.168403 7fe31b107700 7 mds.0.locker rdlock_start waiting on (ifile mix->sync) on [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=9+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
2013-07-03 21:08:39.168430 7fe31b107700 10 mds.0.cache.ino(10000003dae) add_waiter tag 40000000 0x9570600 !ambig 1 !frozen 1 !freezing 1
2013-07-03 21:08:39.168435 7fe31b107700 15 mds.0.cache.ino(10000003dae) taking waiter here
2013-07-03 21:08:39.168439 7fe31b107700 10 mds.0.locker nudge_log (ifile mix->sync) on [inode 10000003dae [2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/category.idx auth v572 ap=9+0 s=915297 n(v0 b915297 1=1+0) (ifile mix->sync) (iversion lock) cr={16909=0-8388608@1,16923=0-8388608@1} caps={5679=pAsLsXsFr/-@1,16909=pAsLsXsFr/pAsxXsxFxwb@3,16922=pAsLsXsFr/p@0,16923=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,16924=p/p@0,16961=pAsLsXsFr/-@1} | request=8 lock=1 caps=1 truncating=0 dirty=1 waiter=1 authpin=1 0x8970080]
Updated by Zheng Yan almost 11 years ago
it's a kclient bug, probably already fixed by 'libceph: call r_unsafe_callback when unsafe reply is received'
Actions