Bug #2019: mds: CInode::filelock stuck in sync->mix - CephFS - Ceph

Actions

Copy link

Bug #2019

closed

mds: 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:

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?

Actions

Copy link

Updated by Sage Weil over 11 years ago

Project changed from Ceph to CephFS
Category deleted (1)

Actions

Copy link

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.

Actions

Copy link

Updated by Greg Farnum almost 11 years ago

Status changed from Can't reproduce to 12

See #5036.

Actions

Copy link

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]

Actions

Copy link