Actions
Bug #5036
closed`ls` hangs on random folder
Status:
Resolved
Priority:
High
Assignee:
-
Category:
-
Target version:
-
% Done:
0%
Source:
other
Tags:
Backport:
Regression:
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
Labels (FS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
strace hangs at "getdents(3,": https://clbin.com/LktUw
The informations when dumping via SysRq:
kernel: ls D ffff88062b3bdac8 0 10297 9519 0x00000080 kernel: ffff88062c2a1988 0000000000000086 ffff88062c2a1908 ffff880600000001 kernel: 0000000000012b00 ffff88062c2a1fd8 ffff88062c2a0010 0000000000012b00 kernel: ffff88062c2a1fd8 0000000000012b00 ffff88062aa434e0 ffff88062b3bd520 kernel: Call Trace: kernel: [<ffffffff8151110f>] schedule+0x3f/0x60 kernel: [<ffffffff815115ad>] schedule_timeout+0x1fd/0x2e0 kernel: [<ffffffff8107f8e5>] ? queue_work_on+0x25/0x30 kernel: [<ffffffff8107faaf>] ? queue_work+0x1f/0x30 kernel: [<ffffffff8107fb6d>] ? queue_delayed_work+0x2d/0x40 kernel: [<ffffffff81510f43>] wait_for_common+0xd3/0x180 kernel: [<ffffffff810575d0>] ? try_to_wake_up+0x2a0/0x2a0 kernel: [<ffffffff8151102d>] wait_for_completion_killable+0x1d/0x30 kernel: [<ffffffffa02a68c5>] ceph_mdsc_do_request+0x135/0x2b0 [ceph] kernel: [<ffffffffa028ea97>] ceph_lookup+0x117/0x300 [ceph] kernel: [<ffffffff81170865>] d_alloc_and_lookup+0x45/0x90 kernel: [<ffffffff8117bb95>] ? d_lookup+0x35/0x60 kernel: [<ffffffff811725d0>] do_lookup+0x2e0/0x330 kernel: [<ffffffff81173b2f>] link_path_walk+0x18f/0x920 kernel: [<ffffffff8117275e>] ? path_init+0x13e/0x3d0 kernel: [<ffffffff8107f8e5>] ? queue_work_on+0x25/0x30 kernel: [<ffffffff81174925>] path_lookupat+0x55/0x680 kernel: [<ffffffff81174f81>] do_path_lookup+0x31/0xc0 kernel: [<ffffffff81175cc9>] user_path_at_empty+0x59/0xa0 kernel: [<ffffffffa0288c59>] ? ceph_do_getattr+0xf9/0x190 [ceph] kernel: [<ffffffffa0288d36>] ? ceph_getattr+0x46/0x100 [ceph] kernel: [<ffffffff8116a778>] ? cp_new_stat+0xf8/0x110 kernel: [<ffffffff81175d21>] user_path_at+0x11/0x20 kernel: [<ffffffff8116a85c>] vfs_fstatat+0x4c/0x90 kernel: [<ffffffff8116a90e>] vfs_lstat+0x1e/0x20 kernel: [<ffffffff8116a934>] sys_newlstat+0x24/0x50 kernel: [<ffffffff810c3fbf>] ? audit_syscall_entry+0x1bf/0x1f0 kernel: [<ffffffff8151b182>] system_call_fastpath+0x16/0x1b
This problem happened with both of mount types: kernel module and FUSE.
# uname -r 3.0.71-1.el6.elrepo.x86_64
Please let me know if you need any further information.
Updated by Quan Tong Anh almost 11 years ago
As you can see, the ls process is stuck in D state:
/proc/10297/status
Name: ls State: D (disk sleep) Tgid: 10297 Pid: 10297 PPid: 9519 TracerPid: 0 Uid: 0 0 0 0 Gid: 0 0 0 0 FDSize: 256 Groups: 0 VmPeak: 115732 kB VmSize: 115732 kB VmLck: 0 kB VmHWM: 728 kB VmRSS: 728 kB VmData: 204 kB VmStk: 136 kB VmExe: 100 kB VmLib: 2008 kB VmPTE: 68 kB VmSwap: 0 kB Threads: 1 SigQ: 31/193083 SigPnd: 0000000000000000 ShdPnd: 0000000000000000 SigBlk: 0000000000000000 SigIgn: 0000000000000000 SigCgt: 0000000197887007 CapInh: 0000000000000000 CapPrm: ffffffffffffffff CapEff: ffffffffffffffff CapBnd: ffffffffffffffff Cpus_allowed: ffffff Cpus_allowed_list: 0-23 Mems_allowed: 00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000003 Mems_allowed_list: 0-1 voluntary_ctxt_switches: 52 nonvoluntary_ctxt_switches: 1
/proc/10297/wchan
ceph_mdsc_do_request
/proc/10297/io
rchar: 7780 wchar: 0 syscr: 14 syscw: 0 read_bytes: 0 write_bytes: 0 cancelled_write_bytes: 0
Updated by Sage Weil almost 11 years ago
- Project changed from Ceph to CephFS
- Category deleted (
26) - Target version deleted (
v0.61 - Cuttlefish)
Updated by Quan Tong Anh almost 11 years ago
By turning on the debug mode of MDS:
ceph mds tell \* injectargs '--debug-mds 20 --debug-ms 1'
I see the following in the
ceph-mds.id.log:
2013-05-11 09:58:16.064842 7f0043fff700 0 mds.0.server missing 100000008b1 #1/adproc-data/tvc/load_success_final/2013-05-10/adv1368177807899.dat (mine), will load later
Updated by Milosz Tanski almost 11 years ago
I'm experiencing the same issue here when trying to ls one directory in our ceph cluster on nodes. Using both vanilla kernel client in 3.10 and my (fscache) version.
I'm not sure how to read the Ceph mds log.
2013-07-03 21:08:39.166922 7fe31b107700 7 mds.0.cache request_start request(client.16961:1591 cr=0x433e780)
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.166959 7fe31b107700 10 mds.0.cache path_traverse finish on snapid 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.167046 7fe31b107700 10 mds.0.locker acquire_locks request(client.16961:1591 cr=0x433e780)
2013-07-03 21:08:39.167058 7fe31b107700 20 mds.0.locker must rdlock (isnap sync r=7) [inode 1 [...2,head] / auth v1811 ap=7+0 snaprealm=0x3165d80 f(v2 m2013-06-14 03:54:04.299693 2=0+2) n(v343 rc2013-07-03 20:09:19.884452 b24895892640 12268=12091+177)/n(v0 1=0+1) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/-@2,12557=pAsLsXsFs/-@2,12564=pAsLsXsFs/-@2,16909=pAsLsXsFs/-@3,16922=pAsLsXsFs/-@2,16923=pAsLsXsFs/-@2,16924=pAsLsXs/-@0,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x3151860]
2013-07-03 21:08:39.167124 7fe31b107700 20 mds.0.locker must rdlock (isnap sync r=7) [inode 10000000000 [...2,head] /petabucket/ auth v4103 ap=7+1 f(v2 m2013-07-03 18:10:29.427025 3=0+3) n(v338 rc2013-07-03 20:09:19.884452 b24895892640 12267=12091+176) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/-@2,12557=pAsLsXsFs/-@3,12564=pAsLsXsFs/-@3,16909=pAsLsXsFs/-@2,16922=pAsLsXs/-@1,16923=pAsLsXsFs/-@3,16924=pAsLsXs/-@0,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirtyrstat=0 dirty=1 authpin=1 0x31520c0]
2013-07-03 21:08:39.167182 7fe31b107700 20 mds.0.locker must rdlock (isnap sync r=7) [inode 1000000272c [...2,head] /petabucket/beta/ auth v4858 ap=7+1 f(v2 m2013-07-03 18:59:57.696111 85=0+85) n(v164 rc2013-07-03 20:09:19.884452 b12257686751 6061=5975+86) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/p@2,12557=pAsLsXs/-@0,16909=pAsLsXsFs/p@2,16922=pAsLsXs/-@1,16923=pAsLsXsFs/-@2,16924=pAsLsXs/-@1,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x70ef6a0]
2013-07-03 21:08:39.167235 7fe31b107700 20 mds.0.locker must rdlock (isnap sync r=7) [inode 10000003da4 [...2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/ auth v34275 ap=7+1 f(v2 m2013-07-03 20:09:19.884452 63=63+0) n(v0 rc2013-07-03 20:09:19.884452 b184888667 64=63+1) (isnap sync r=7) (inest lock dirty) (iversion lock) caps={5679=pAsLsXsFs/-@2,16909=pAsLsXsFs/-@2,16922=pAsLsXs/p@1,16923=pAsLsXs/-@0,16924=pAsLsXs/p@1,16961=pAsLsXsFs/-@6} | dirtyscattered=1 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x896acc0]
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.167428 7fe31b107700 10 mds.0.locker must authpin [inode 1 [...2,head] / auth v1811 ap=7+0 snaprealm=0x3165d80 f(v2 m2013-06-14 03:54:04.299693 2=0+2) n(v343 rc2013-07-03 20:09:19.884452 b24895892640 12268=12091+177)/n(v0 1=0+1) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/-@2,12557=pAsLsXsFs/-@2,12564=pAsLsXsFs/-@2,16909=pAsLsXsFs/-@3,16922=pAsLsXsFs/-@2,16923=pAsLsXsFs/-@2,16924=pAsLsXs/-@0,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x3151860]
2013-07-03 21:08:39.167459 7fe31b107700 10 mds.0.locker must authpin [inode 10000000000 [...2,head] /petabucket/ auth v4103 ap=7+1 f(v2 m2013-07-03 18:10:29.427025 3=0+3) n(v338 rc2013-07-03 20:09:19.884452 b24895892640 12267=12091+176) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/-@2,12557=pAsLsXsFs/-@3,12564=pAsLsXsFs/-@3,16909=pAsLsXsFs/-@2,16922=pAsLsXs/-@1,16923=pAsLsXsFs/-@3,16924=pAsLsXs/-@0,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirtyrstat=0 dirty=1 authpin=1 0x31520c0]
2013-07-03 21:08:39.167489 7fe31b107700 10 mds.0.locker must authpin [inode 1000000272c [...2,head] /petabucket/beta/ auth v4858 ap=7+1 f(v2 m2013-07-03 18:59:57.696111 85=0+85) n(v164 rc2013-07-03 20:09:19.884452 b12257686751 6061=5975+86) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/p@2,12557=pAsLsXs/-@0,16909=pAsLsXsFs/p@2,16922=pAsLsXs/-@1,16923=pAsLsXsFs/-@2,16924=pAsLsXs/-@1,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x70ef6a0]
2013-07-03 21:08:39.167516 7fe31b107700 10 mds.0.locker must authpin [inode 10000003da4 [...2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/ auth v34275 ap=7+1 f(v2 m2013-07-03 20:09:19.884452 63=63+0) n(v0 rc2013-07-03 20:09:19.884452 b184888667 64=63+1) (isnap sync r=7) (inest lock dirty) (iversion lock) caps={5679=pAsLsXsFs/-@2,16909=pAsLsXsFs/-@2,16922=pAsLsXs/p@1,16923=pAsLsXs/-@0,16924=pAsLsXs/p@1,16961=pAsLsXsFs/-@6} | dirtyscattered=1 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x896acc0]
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.167669 7fe31b107700 10 mds.0.locker auth_pinning [inode 1 [...2,head] / auth v1811 ap=7+0 snaprealm=0x3165d80 f(v2 m2013-06-14 03:54:04.299693 2=0+2) n(v343 rc2013-07-03 20:09:19.884452 b24895892640 12268=12091+177)/n(v0 1=0+1) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/-@2,12557=pAsLsXsFs/-@2,12564=pAsLsXsFs/-@2,16909=pAsLsXsFs/-@3,16922=pAsLsXsFs/-@2,16923=pAsLsXsFs/-@2,16924=pAsLsXs/-@0,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x3151860]
2013-07-03 21:08:39.167698 7fe31b107700 10 mds.0.cache.ino(1) auth_pin by 0x9783800 on [inode 1 [...2,head] / auth v1811 ap=8+0 snaprealm=0x3165d80 f(v2 m2013-06-14 03:54:04.299693 2=0+2) n(v343 rc2013-07-03 20:09:19.884452 b24895892640 12268=12091+177)/n(v0 1=0+1) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/-@2,12557=pAsLsXsFs/-@2,12564=pAsLsXsFs/-@2,16909=pAsLsXsFs/-@3,16922=pAsLsXsFs/-@2,16923=pAsLsXsFs/-@2,16924=pAsLsXs/-@0,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x3151860] now 8+0
2013-07-03 21:08:39.167727 7fe31b107700 10 mds.0.locker auth_pinning [inode 10000000000 [...2,head] /petabucket/ auth v4103 ap=7+1 f(v2 m2013-07-03 18:10:29.427025 3=0+3) n(v338 rc2013-07-03 20:09:19.884452 b24895892640 12267=12091+176) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/-@2,12557=pAsLsXsFs/-@3,12564=pAsLsXsFs/-@3,16909=pAsLsXsFs/-@2,16922=pAsLsXs/-@1,16923=pAsLsXsFs/-@3,16924=pAsLsXs/-@0,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirtyrstat=0 dirty=1 authpin=1 0x31520c0]
2013-07-03 21:08:39.167755 7fe31b107700 10 mds.0.cache.ino(10000000000) auth_pin by 0x9783800 on [inode 10000000000 [...2,head] /petabucket/ auth v4103 ap=8+1 f(v2 m2013-07-03 18:10:29.427025 3=0+3) n(v338 rc2013-07-03 20:09:19.884452 b24895892640 12267=12091+176) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/-@2,12557=pAsLsXsFs/-@3,12564=pAsLsXsFs/-@3,16909=pAsLsXsFs/-@2,16922=pAsLsXs/-@1,16923=pAsLsXsFs/-@3,16924=pAsLsXs/-@0,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirtyrstat=0 dirty=1 authpin=1 0x31520c0] now 8+1
2013-07-03 21:08:39.167783 7fe31b107700 15 mds.0.cache.dir(1) adjust_nested_auth_pins 1/1 on [dir 1 / [2,head] auth v=4105 cv=4090/4090 dir_auth=0 ap=0+8+9 state=1610612738|complete f(v2 m2013-06-14 03:54:04.299693 2=0+2) n(v343 rc2013-07-03 20:09:19.884452 b24895892640 12268=12091+177) hs=2+0,ss=0+0 dirty=1 | child=1 subtree=1 dirty=1 waiter=0 authpin=0 0x3170000] by 0x31520c0 count now 0 + 9
2013-07-03 21:08:39.167801 7fe31b107700 10 mds.0.locker auth_pinning [inode 1000000272c [...2,head] /petabucket/beta/ auth v4858 ap=7+1 f(v2 m2013-07-03 18:59:57.696111 85=0+85) n(v164 rc2013-07-03 20:09:19.884452 b12257686751 6061=5975+86) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/p@2,12557=pAsLsXs/-@0,16909=pAsLsXsFs/p@2,16922=pAsLsXs/-@1,16923=pAsLsXsFs/-@2,16924=pAsLsXs/-@1,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x70ef6a0]
2013-07-03 21:08:39.167827 7fe31b107700 10 mds.0.cache.ino(1000000272c) auth_pin by 0x9783800 on [inode 1000000272c [...2,head] /petabucket/beta/ auth v4858 ap=8+1 f(v2 m2013-07-03 18:59:57.696111 85=0+85) n(v164 rc2013-07-03 20:09:19.884452 b12257686751 6061=5975+86) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/p@2,12557=pAsLsXs/-@0,16909=pAsLsXsFs/p@2,16922=pAsLsXs/-@1,16923=pAsLsXsFs/-@2,16924=pAsLsXs/-@1,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x70ef6a0] now 8+1
2013-07-03 21:08:39.167853 7fe31b107700 15 mds.0.cache.dir(10000000000) adjust_nested_auth_pins 1/1 on [dir 10000000000 /petabucket/ [2,head] auth v=4860 cv=4852/4852 ap=0+8+9 state=1610612738|complete f(v2 m2013-07-03 18:10:29.427025 3=0+3) n(v338 rc2013-07-03 20:09:19.884452 b24895892640 12266=12091+175) hs=3+0,ss=0+0 dirty=2 | child=1 dirty=1 waiter=0 authpin=0 0x31707f0] by 0x70ef6a0 count now 0 + 9
2013-07-03 21:08:39.167867 7fe31b107700 10 mds.0.locker auth_pinning [inode 10000003da4 [...2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/ auth v34275 ap=7+1 f(v2 m2013-07-03 20:09:19.884452 63=63+0) n(v0 rc2013-07-03 20:09:19.884452 b184888667 64=63+1) (isnap sync r=7) (inest lock dirty) (iversion lock) caps={5679=pAsLsXsFs/-@2,16909=pAsLsXsFs/-@2,16922=pAsLsXs/p@1,16923=pAsLsXs/-@0,16924=pAsLsXs/p@1,16961=pAsLsXsFs/-@6} | dirtyscattered=1 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x896acc0]
2013-07-03 21:08:39.167892 7fe31b107700 10 mds.0.cache.ino(10000003da4) auth_pin by 0x9783800 on [inode 10000003da4 [...2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/ auth v34275 ap=8+1 f(v2 m2013-07-03 20:09:19.884452 63=63+0) n(v0 rc2013-07-03 20:09:19.884452 b184888667 64=63+1) (isnap sync r=7) (inest lock dirty) (iversion lock) caps={5679=pAsLsXsFs/-@2,16909=pAsLsXsFs/-@2,16922=pAsLsXs/p@1,16923=pAsLsXs/-@0,16924=pAsLsXs/p@1,16961=pAsLsXsFs/-@6} | dirtyscattered=1 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x896acc0] now 8+1
2013-07-03 21:08:39.167916 7fe31b107700 15 mds.0.cache.dir(1000000272c) adjust_nested_auth_pins 1/1 on [dir 1000000272c /petabucket/beta/ [2,head] auth v=34423 cv=0/0 ap=0+8+9 state=1610612738|complete f(v2 m2013-07-03 18:59:57.696111 85=0+85) n(v164 rc2013-07-03 20:09:19.884452 b12257686751 6060=5975+85) hs=85+0,ss=0+0 dirty=85 | child=1 dirty=1 authpin=0 0x415fb48] by 0x896acc0 count now 0 + 9
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.167983 7fe31b107700 15 mds.0.cache.dir(10000003da4) adjust_nested_auth_pins 1/1 on [dir 10000003da4 /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/ [2,head] auth v=603 cv=0/0 ap=0+9+9 state=1610612738|complete f(v2 m2013-07-03 20:09:19.884452 63=63+0) n(v0 rc2013-07-03 20:09:19.884452 b184888667 63=63+0) hs=63+9,ss=0+0 dirty=72 | child=1 dirty=1 authpin=0 0x4173cc0] by 0x8970080 count now 0 + 9
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.168106 7fe31b107700 7 mds.0.locker rdlock_start on (isnap sync r=7) on [inode 1 [...2,head] / auth v1811 ap=8+0 snaprealm=0x3165d80 f(v2 m2013-06-14 03:54:04.299693 2=0+2) n(v343 rc2013-07-03 20:09:19.884452 b24895892640 12268=12091+177)/n(v0 1=0+1) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/-@2,12557=pAsLsXsFs/-@2,12564=pAsLsXsFs/-@2,16909=pAsLsXsFs/-@3,16922=pAsLsXsFs/-@2,16923=pAsLsXsFs/-@2,16924=pAsLsXs/-@0,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x3151860]
2013-07-03 21:08:39.168136 7fe31b107700 10 mds.0.locker got rdlock on (isnap sync r=8) [inode 1 [...2,head] / auth v1811 ap=8+0 snaprealm=0x3165d80 f(v2 m2013-06-14 03:54:04.299693 2=0+2) n(v343 rc2013-07-03 20:09:19.884452 b24895892640 12268=12091+177)/n(v0 1=0+1) (isnap sync r=8) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/-@2,12557=pAsLsXsFs/-@2,12564=pAsLsXsFs/-@2,16909=pAsLsXsFs/-@3,16922=pAsLsXsFs/-@2,16923=pAsLsXsFs/-@2,16924=pAsLsXs/-@0,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x3151860]
2013-07-03 21:08:39.168166 7fe31b107700 7 mds.0.locker rdlock_start on (isnap sync r=7) on [inode 10000000000 [...2,head] /petabucket/ auth v4103 ap=8+1 f(v2 m2013-07-03 18:10:29.427025 3=0+3) n(v338 rc2013-07-03 20:09:19.884452 b24895892640 12267=12091+176) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/-@2,12557=pAsLsXsFs/-@3,12564=pAsLsXsFs/-@3,16909=pAsLsXsFs/-@2,16922=pAsLsXs/-@1,16923=pAsLsXsFs/-@3,16924=pAsLsXs/-@0,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirtyrstat=0 dirty=1 authpin=1 0x31520c0]
2013-07-03 21:08:39.168194 7fe31b107700 10 mds.0.locker got rdlock on (isnap sync r=8) [inode 10000000000 [...2,head] /petabucket/ auth v4103 ap=8+1 f(v2 m2013-07-03 18:10:29.427025 3=0+3) n(v338 rc2013-07-03 20:09:19.884452 b24895892640 12267=12091+176) (isnap sync r=8) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/-@2,12557=pAsLsXsFs/-@3,12564=pAsLsXsFs/-@3,16909=pAsLsXsFs/-@2,16922=pAsLsXs/-@1,16923=pAsLsXsFs/-@3,16924=pAsLsXs/-@0,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirtyrstat=0 dirty=1 authpin=1 0x31520c0]
2013-07-03 21:08:39.168223 7fe31b107700 7 mds.0.locker rdlock_start on (isnap sync r=7) on [inode 1000000272c [...2,head] /petabucket/beta/ auth v4858 ap=8+1 f(v2 m2013-07-03 18:59:57.696111 85=0+85) n(v164 rc2013-07-03 20:09:19.884452 b12257686751 6061=5975+86) (isnap sync r=7) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/p@2,12557=pAsLsXs/-@0,16909=pAsLsXsFs/p@2,16922=pAsLsXs/-@1,16923=pAsLsXsFs/-@2,16924=pAsLsXs/-@1,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x70ef6a0]
2013-07-03 21:08:39.168249 7fe31b107700 10 mds.0.locker got rdlock on (isnap sync r=8) [inode 1000000272c [...2,head] /petabucket/beta/ auth v4858 ap=8+1 f(v2 m2013-07-03 18:59:57.696111 85=0+85) n(v164 rc2013-07-03 20:09:19.884452 b12257686751 6061=5975+86) (isnap sync r=8) (inest lock) (iversion lock) caps={5679=pAsLsXsFs/p@2,12557=pAsLsXs/-@0,16909=pAsLsXsFs/p@2,16922=pAsLsXs/-@1,16923=pAsLsXsFs/-@2,16924=pAsLsXs/-@1,16961=pAsLsXsFs/-@3} | dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x70ef6a0]
2013-07-03 21:08:39.168275 7fe31b107700 7 mds.0.locker rdlock_start on (isnap sync r=7) on [inode 10000003da4 [...2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/ auth v34275 ap=8+1 f(v2 m2013-07-03 20:09:19.884452 63=63+0) n(v0 rc2013-07-03 20:09:19.884452 b184888667 64=63+1) (isnap sync r=7) (inest lock dirty) (iversion lock) caps={5679=pAsLsXsFs/-@2,16909=pAsLsXsFs/-@2,16922=pAsLsXs/p@1,16923=pAsLsXs/-@0,16924=pAsLsXs/p@1,16961=pAsLsXsFs/-@6} | dirtyscattered=1 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x896acc0]
2013-07-03 21:08:39.168300 7fe31b107700 10 mds.0.locker got rdlock on (isnap sync r=8) [inode 10000003da4 [...2,head] /petabucket/beta/be9deb7a5cbe8d3cc97be2f7ed7336f358bbae240a693f8ecc076336f8219593/ auth v34275 ap=8+1 f(v2 m2013-07-03 20:09:19.884452 63=63+0) n(v0 rc2013-07-03 20:09:19.884452 b184888667 64=63+1) (isnap sync r=8) (inest lock dirty) (iversion lock) caps={5679=pAsLsXsFs/-@2,16909=pAsLsXsFs/-@2,16922=pAsLsXs/p@1,16923=pAsLsXs/-@0,16924=pAsLsXs/p@1,16961=pAsLsXsFs/-@6} | dirtyscattered=1 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1 0x896acc0]
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]
2013-07-03 21:08:41.811393 7fe318f01700 7 mds.0.cache trim max=100000 cur=17013
2013-07-03 21:08:41.811428 7fe318f01700 10 mds.0.cache trim_client_leases
2013-07-03 21:08:41.811953 7fe318f01700 2 mds.0.cache check_memory_usage total 280452, rss 110384, heap 125004, malloc 78538 mmap 0, baseline 125004, buffers 0, max 1048576, 14210 / 14223 inodes have caps, 25005 caps, 1.75807 caps per inode
2013-07-03 21:08:41.811978 7fe318f01700 10 mds.0.log trim 30 / 30 segments, 41607 / -1 events, 0 (0) expiring, 0 (0) expired
2013-07-03 21:08:41.811985 7fe318f01700 10 mds.0.log _trim_expired_segments waiting for 104857932 to expire
2013-07-03 21:08:41.812031 7fe318f01700 15 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2013-07-03 21:08:41.812062 7fe318f01700 10 mds.0.locker scatter_tick
2013-07-03 21:08:41.812067 7fe318f01700 10 mds.0.server find_idle_sessions. laggy until 0.000000
2013-07-03 21:08:41.812075 7fe318f01700 20 mds.0.server laggiest active session is client.16961 10.0.1.127:0/1723673625
2013-07-03 21:08:41.812086 7fe318f01700 20 mds.0.server laggiest active session is client.16961 10.0.1.127:0/1723673625 and sufficiently new (2013-07-03 21:08:25.304652)
2013-07-03 21:08:41.812099 7fe318f01700 15 mds.0.bal tick last_sample now 2013-07-03 21:08:41.812097
2013-07-03 21:08:41.812124 7fe318f01700 15 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2013-07-03 21:08:41.812150 7fe318f01700 5 mds.0.bal mds.0 epoch 158 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2013-07-03 21:08:41.812167 7fe318f01700 10 mds.0.snap check_osd_map - version unchanged
2013-07-03 21:08:42.524658 7fe318f01700 10 mds.0.3 beacon_send up:active seq 401 (currently up:active)
2013-07-03 21:08:42.524734 7fe318f01700 1 -- 10.0.5.241:6800/11419 --> 10.0.5.226:6789/0 -- mdsbeacon(16975/0 up:active seq 401 v14) v2 -- ?+0 0x555d8c0 con 0x3108580
2013-07-03 21:08:42.526026 7fe31b107700 1 -- 10.0.5.241:6800/11419 <== mon.0 10.0.5.226:6789/0 428 ==== mdsbeacon(16975/0 up:active seq 401 v14) v2 ==== 103+0+0 (1258120678 0 0) 0x593db00 con 0x3108580
2013-07-03 21:08:42.526057 7fe31b107700 10 mds.0.3 handle_mds_beacon up:active seq 401 rtt 0.001357
2013-07-03 21:08:45.305274 7fe31b107700 1 -- 10.0.5.241:6800/11419 <== client.16961 10.0.1.127:0/1723673625 1447 ==== client_session(request_renewcaps seq 158) ==== 28+0+0 (1870368807 0 0) 0x44c5000 con 0x316a420
2013-07-03 21:08:45.305330 7fe31b107700 20 mds.0.server get_session have 0x6280240 client.16961 10.0.1.127:0/1723673625 state open
2013-07-03 21:08:45.305339 7fe31b107700 3 mds.0.server handle_client_session client_session(request_renewcaps seq 158) from client.16961
2013-07-03 21:08:45.305348 7fe31b107700 1 -- 10.0.5.241:6800/11419 --> 10.0.1.127:0/1723673625 -- client_session(renewcaps seq 158) v1 -- ?+0 0x96bea80 con 0x316a420
2013-07-03 21:08:45.490612 7fe31b107700 1 -- 10.0.5.241:6800/11419 <== client.16923 10.0.1.169:0/2313975262 87 ==== client_session(request_renewcaps seq 454) ==== 28+0+0 (1112809775 0 0) 0x499a000 con 0x316a160
2013-07-03 21:08:45.490670 7fe31b107700 20 mds.0.server get_session have 0x7878900 client.16923 10.0.1.169:0/2313975262 state open
2013-07-03 21:08:45.490679 7fe31b107700 3 mds.0.server handle_client_session client_session(request_renewcaps seq 454) from client.16923
2013-07-03 21:08:45.490689 7fe31b107700 1 -- 10.0.5.241:6800/11419 --> 10.0.1.169:0/2313975262 -- client_session(renewcaps seq 454) v1 -- ?+0 0x44c5000 con 0x316a160
2013-07-03 21:08:46.524860 7fe318f01700 10 mds.0.3 beacon_send up:active seq 402 (currently up:active)
2013-07-03 21:08:46.524929 7fe318f01700 1 -- 10.0.5.241:6800/11419 --> 10.0.5.226:6789/0 -- mdsbeacon(16975/0 up:active seq 402 v14) v2 -- ?+0 0x555d600 con 0x3108580
2013-07-03 21:08:46.526006 7fe31b107700 1 -- 10.0.5.241:6800/11419 <== mon.0 10.0.5.226:6789/0 429 ==== mdsbeacon(16975/0 up:active seq 402 v14) v2 ==== 103+0+0 (3246842447 0 0) 0x593d840 con 0x3108580
2013-07-03 21:08:46.526036 7fe31b107700 10 mds.0.3 handle_mds_beacon up:active seq 402 rtt 0.001138
2013-07-03 21:08:46.811472 7fe318f01700 7 mds.0.cache trim max=100000 cur=17013
2013-07-03 21:08:46.811500 7fe318f01700 10 mds.0.cache trim_client_leases
2013-07-03 21:08:46.812084 7fe318f01700 2 mds.0.cache check_memory_usage total 280452, rss 110384, heap 125004, malloc 78537 mmap 0, baseline 125004, buffers 0, max 1048576, 14210 / 14223 inodes have caps, 25005 caps, 1.75807 caps per inode
2013-07-03 21:08:46.812110 7fe318f01700 10 mds.0.log trim 30 / 30 segments, 41607 / -1 events, 0 (0) expiring, 0 (0) expired
2013-07-03 21:08:46.812118 7fe318f01700 10 mds.0.log _trim_expired_segments waiting for 104857932 to expire
2013-07-03 21:08:46.812164 7fe318f01700 15 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2013-07-03 21:08:46.812195 7fe318f01700 10 mds.0.locker scatter_tick
2013-07-03 21:08:46.812201 7fe318f01700 10 mds.0.server find_idle_sessions. laggy until 0.000000
2013-07-03 21:08:46.812207 7fe318f01700 20 mds.0.server laggiest active session is client.16909 10.0.1.217:0/3323018147
2013-07-03 21:08:46.812217 7fe318f01700 20 mds.0.server laggiest active session is client.16909 10.0.1.217:0/3323018147 and sufficiently new (2013-07-03 21:08:27.600795)
2013-07-03 21:08:46.812230 7fe318f01700 15 mds.0.bal tick last_sample now 2013-07-03 21:08:46.812228
2013-07-03 21:08:46.812234 7fe318f01700 10 mds.0.snap check_osd_map - version unchanged
2013-07-03 21:08:47.602651 7fe31b107700 1 -- 10.0.5.241:6800/11419 <== client.16909 10.0.1.217:0/3323018147 1404 ==== client_session(request_renewcaps seq 540) ==== 28+0+0 (3477502886 0 0) 0x93cf380 con 0x316a9a0
2013-07-03 21:08:47.602724 7fe31b107700 20 mds.0.server get_session have 0x3165b40 client.16909 10.0.1.217:0/3323018147 state open
2013-07-03 21:08:47.602739 7fe31b107700 3 mds.0.server handle_client_session client_session(request_renewcaps seq 540) from client.16909
2013-07-03 21:08:47.602752 7fe31b107700 1 -- 10.0.5.241:6800/11419 --> 10.0.1.217:0/3323018147 -- client_session(renewcaps seq 540) v1 -- ?+0 0x499a000 con 0x316a9a0
2013-07-03 21:08:49.305474 7fe31b107700 1 -- 10.0.5.241:6800/11419 <== client.16924 10.0.1.127:0/3772044916 94 ==== client_session(request_renewcaps seq 454) ==== 28+0+0 (1112809775 0 0) 0x64e0000 con 0x316a580
2013-07-03 21:08:49.305534 7fe31b107700 20 mds.0.server get_session have 0x78786c0 client.16924 10.0.1.127:0/3772044916 state open
2013-07-03 21:08:49.305543 7fe31b107700 3 mds.0.server handle_client_session client_session(request_renewcaps seq 454) from client.16924
2013-07-03 21:08:49.305553 7fe31b107700 1 -- 10.0.5.241:6800/11419 --> 10.0.1.127:0/3772044916 -- client_session(renewcaps seq 454) v1 -- ?+0 0x93cf380 con 0x316a580
2013-07-03 21:08:50.525042 7fe318f01700 10 mds.0.3 beacon_send up:active seq 403 (currently up:active)
2013-07-03 21:08:50.525113 7fe318f01700 1 -- 10.0.5.241:6800/11419 --> 10.0.5.226:6789/0 -- mdsbeacon(16975/0 up:active seq 403 v14) v2 -- ?+0 0x555d340 con 0x3108580
2013-07-03 21:08:50.526319 7fe31b107700 1 -- 10.0.5.241:6800/11419 <== mon.0 10.0.5.226:6789/0 430 ==== mdsbeacon(16975/0 up:active seq 403 v14) v2 ==== 103+0+0 (3098517288 0 0) 0x593d580 con 0x3108580
2013-07-03 21:08:50.526347 7fe31b107700 10 mds.0.3 handle_mds_beacon up:active seq 403 rtt 0.001269
Updated by Greg Farnum almost 11 years ago
Milosz, I think you've run into #2019, which I've reopened. Quan might have seen the same issue but there's not the right output to know if his issue is that or something else.
Updated by Milosz Tanski almost 11 years ago
root@betanode1:/proc/2821# cat stack [<ffffffffa029cbab>] ceph_mdsc_do_request+0xcb/0x1a0 [ceph] [<ffffffffa028a18f>] ceph_do_getattr+0xdf/0x120 [ceph] [<ffffffffa028a1f4>] ceph_getattr+0x24/0x100 [ceph] [<ffffffff811775fd>] vfs_getattr+0x4d/0x80 [<ffffffff81177694>] vfs_fstatat+0x64/0xb0 [<ffffffff8117772e>] vfs_lstat+0x1e/0x20 [<ffffffff81177745>] SYSC_newlstat+0x15/0x30 [<ffffffff8117792e>] SyS_newlstat+0xe/0x10 [<ffffffff8155dd59>] system_call_fastpath+0x16/0x1b [<ffffffffffffffff>] 0xffffffffffffffff
Updated by Zheng Yan almost 11 years ago
I suggest trying test branch ceph-client. At least two bugs that can cause hang like this have been fixed.
Updated by Milosz Tanski almost 11 years ago
Yan,
Even after rebuilding my 3.10 kernel with the missing fix (libceph: call r_unsafe_callback when unsafe reply is received) and I'm still seeing this on one of my clients. Same issue as before with the same stuck place in the kernel.
What can I do from here to debug this issue?
Updated by Zheng Yan almost 11 years ago
was your mds complied from the newest source code? was there mds restart before you saw the hang? if there was, the bug "ceph: reset iov_len when discarding cap release messages" fixes can explain the hang.
did you do what I described in my reply.
find the hang request (and inode) through /sys/kernel/debug/ceph/xxx/mdsc,
use 'ceph mds tell \* dumpcache' to dump mds cache.
open /cachedump.xxx and check the inode's state.
Updated by Herbert XYZ over 10 years ago
I would like to state that we also had this problem, but were unable to reproduce it. A folder got into a 'state' such that ls-ing or autocompleting it would freeze bash or ls. The bash or ls process would also be in the D state (as in /proc/PID/status) and the stack trace would also include ceph_mdsc_do_request, ceph_do_getattr and ceph_getattr. Unfortunately, I don't have a lot of details, some of our server which had the file system mounted and which had some processes accessing it were restarted and this solved the problem, 'unlocking' the folder (unlocking in a sense that the behavior described stopped). The MDS deamon, which we use to mount the ceph, and the monitors were also restarted.
We gave some effort to reproducing this, but failed. We tried to create a python process which would open a file 'w+' and then keep writing to it (while true), and simultaneously opened the file using ls and cat. This did not 'lock' the file (in the sense of the behavior described above). We also accessed the file via symlinks, as this was the case in our original setup.
I am sorry for not being able to give a reproducability report, but I hope this helps. If we experience this bug again we will write something about it here, hopefully with better information.
Updated by Herbert XYZ over 10 years ago
Our MDS log (with MDS in dubug mode) did output this:
[inode 10000013022 [2,head] /path/to/frozen/file auth v34 ap=6+0 s=36 n(v0 b36 1=1+0) (ifile mix->sync) (iversion lock) cr={9726=0-4194304@1,9729=0-4194304@1,9732=0-4194304@1,10155=0-4194304@1} caps={9726=pAsLsXsFr/pAsxXsxFsxcrwb@2,9729=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,9732=pAsLsXsFr/pAsxXsxFsxcrwb@2,10155=pAsLsXsFr/pAsxXsxFsxcrwb@2,10602=pAsLsXsFr/-@1} | request=5 lock=1 caps=1 waiter=1 authpin=1 0x88a7378]
Updated by Zheng Yan over 10 years ago
Herbert XYZ wrote:
Our MDS log (with MDS in dubug mode) did output this:
[inode 10000013022 [2,head] /path/to/frozen/file auth v34 ap=6+0 s=36 n(v0 b36 1=1+0) (ifile mix->sync) (iversion lock) cr={9726=0-4194304@1,9729=0-4194304@1,9732=0-4194304@1,10155=0-4194304@1} caps={9726=pAsLsXsFr/pAsxXsxFsxcrwb@2,9729=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFsxcrwb@2,9732=pAsLsXsFr/pAsxXsxFsxcrwb@2,10155=pAsLsXsFr/pAsxXsxFsxcrwb@2,10602=pAsLsXsFr/-@1} | request=5 lock=1 caps=1 waiter=1 authpin=1 0x88a7378]
there is a bug in 3.10 kernel can cause hang like this. are you using 3.10 kernel?
Actions