Could you strace apacha process, check which syscall waits for a long time.
On Sat, Aug 25, 2018 at 3:04 AM Stefan Kooman <ste...@bit.nl> wrote:
>
> Quoting Gregory Farnum (gfar...@redhat.com):
>
> > Hmm, these aren't actually the start and end times to the same operation.
> > put_inode() is literally adjusting a refcount, which can happen for reasons
> > ranging from the VFS doing something that drops it to an internal operation
> > completing to a response coming back from the MDS. You should be able to
> > find requests coming in from the kernel and a response going back out (the
> > function names will be prefixed with "ll_", eg "ll_lookup").
>
> Ok, next try. One page visit and grepped "sess_". See results below:
>
> 2018-08-25 11:10:42.142 7ff2a0c2c700 3 client.15224195 ll_lookup
> 0x1000068547c.head sess_bss8rh5bug6bffvj6s67vnsce5
> 2018-08-25 11:10:42.142 7ff2a0c2c700 10 client.15224195 _lookup concluded
> ENOENT locally for 0x1000068547c.head(faked_ino=0 ref=2 ll_ref=4 cap_refs={}
> open={} mode=40755 size=0/0 nlink=1 btime=2018-08-23 14:23:09.291832
> mtime=2018-08-25 11:08:11.025085 ctime=2018-08-25 11:08:11.025085
> caps=pAsLsXsFs(0=pAsLsXsFs) COMPLETE parents=0x100005218bb.head["sessions"]
> 0x557ddecc6100) dn 'sess_bss8rh5bug6bffvj6s67vnsce5'
> 2018-08-25 11:10:42.142 7ff2a0c2c700 3 client.15224195 ll_lookup
> 0x1000068547c.head sess_bss8rh5bug6bffvj6s67vnsce5 -> -2 (0)
> 2018-08-25 11:10:42.142 7ff2a142d700 3 client.15224195 ll_lookup
> 0x1000068547c.head sess_bss8rh5bug6bffvj6s67vnsce5
> 2018-08-25 11:10:42.142 7ff2a142d700 10 client.15224195 _lookup concluded
> ENOENT locally for 0x1000068547c.head(faked_ino=0 ref=2 ll_ref=5 cap_refs={}
> open={} mode=40755 size=0/0 nlink=1 btime=2018-08-23 14:23:09.291832
> mtime=2018-08-25 11:08:11.025085 ctime=2018-08-25 11:08:11.025085
> caps=pAsLsXsFs(0=pAsLsXsFs) COMPLETE parents=0x100005218bb.head["sessions"]
> 0x557ddecc6100) dn 'sess_bss8rh5bug6bffvj6s67vnsce5'
> 2018-08-25 11:10:42.142 7ff2a142d700 3 client.15224195 ll_lookup
> 0x1000068547c.head sess_bss8rh5bug6bffvj6s67vnsce5 -> -2 (0)
> 2018-08-25 11:10:42.142 7ff2a0c2c700 8 client.15224195 _ll_create
> 0x1000068547c.head sess_bss8rh5bug6bffvj6s67vnsce5 0100600 131138, uid 5003,
> gid 5003
> 2018-08-25 11:10:42.142 7ff2a0c2c700 10 client.15224195 _lookup concluded
> ENOENT locally for 0x1000068547c.head(faked_ino=0 ref=2 ll_ref=5 cap_refs={}
> open={} mode=40755 size=0/0 nlink=1 btime=2018-08-23 14:23:09.291832
> mtime=2018-08-25 11:08:11.025085 ctime=2018-08-25 11:08:11.025085
> caps=pAsLsXsFs(0=pAsLsXsFs) COMPLETE parents=0x100005218bb.head["sessions"]
> 0x557ddecc6100) dn 'sess_bss8rh5bug6bffvj6s67vnsce5'
>
> ^^ check for existing session file, which does not exist, yet.
>
> 2018-08-25 11:10:42.142 7ff2a0c2c700 8 client.15224195 _create(0x1000068547c
> sess_bss8rh5bug6bffvj6s67vnsce5, 0100600)
> 2018-08-25 11:10:42.142 7ff2a0c2c700 20 client.15224195 get_or_create
> 0x1000068547c.head(faked_ino=0 ref=3 ll_ref=5 cap_refs={} open={} mode=40755
> size=0/0 nlink=1 btime=2018-08-23 14:23:09.291832 mtime=2018-08-25
> 11:08:11.025085 ctime=2018-08-25 11:08:11.025085 caps=pAsLsXsFs(0=pAsLsXsFs)
> COMPLETE parents=0x100005218bb.head["sessions"] 0x557ddecc6100) name
> sess_bss8rh5bug6bffvj6s67vnsce5
> 2018-08-25 11:10:42.142 7ff2a0c2c700 15 client.15224195 link dir
> 0x557ddecc6100 'sess_bss8rh5bug6bffvj6s67vnsce5' to inode 0 dn 0x557ddf053de0
> (new dn)
> 2018-08-25 11:10:42.142 7ff2a0c2c700 20 client.15224195 choose_target_mds
> inode dir hash is 2 on sess_bss8rh5bug6bffvj6s67vnsce5 => 3288169645
> 2018-08-25 11:10:42.142 7ff2a0c2c700 10 client.15224195 send_request
> client_request(unknown.0:872 create
> #0x1000068547c/sess_bss8rh5bug6bffvj6s67vnsce5 2018-08-25 11:10:42.148081
> caller_uid=5003, caller_gid=5003{5003,}) v4 to mds.0
> 2018-08-25 11:10:42.142 7ff2a0c2c700 1 -- [2001:7b8:81:6::18]:0/4024171085
> --> [2001:7b8:80:3:0:2c:3:2]:6800/1086374448 -- client_request(unknown.0:872
> create #0x1000068547c/sess_bss8rh5bug6bffvj6s67vnsce5 2018-08-25
> 11:10:42.148081 caller_uid=5003, caller_gid=5003{5003,}) v4 -- 0x557ddf884080
> con 0
> 2018-08-25 11:10:42.142 7ff2a5c36700 12 client.15224195 insert_dentry_inode
> 'sess_bss8rh5bug6bffvj6s67vnsce5' vino 0x100006d9844.head in dir
> 0x1000068547c.head dn 0x557ddf053de0
> 2018-08-25 11:10:42.142 7ff2a5c36700 15 client.15224195 link dir
> 0x557ddecc6100 'sess_bss8rh5bug6bffvj6s67vnsce5' to inode 0x557ddfaa0680 dn
> 0x557ddf053de0 (old dn)
> 2018-08-25 11:10:42.142 7ff2a5c36700 10 client.15224195 put_inode on
> 0x100006d9844.head(faked_ino=0 ref=3 ll_ref=0 cap_refs={} open={} mode=100600
> size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081 mtime=2018-08-25
> 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:42.142 7ff2a5c36700 20 client.15224195 link inode
> 0x557ddfaa0680 parents now
> 0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"]
> 2018-08-25 11:10:42.142 7ff2a5c36700 10 client.15224195 put_inode on
> 0x100006d9844.head(faked_ino=0 ref=2 ll_ref=0 cap_refs={} open={} mode=100600
> size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081 mtime=2018-08-25
> 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:42.142 7ff2a5c36700 10 client.15224195 got dentry lease on
> sess_bss8rh5bug6bffvj6s67vnsce5 dur 30000ms ttl 2018-08-25 11:11:12.148118
> 2018-08-25 11:10:42.142 7ff2a0c2c700 20 client.15224195 make_request target
> is 0x100006d9844.head(faked_ino=0 ref=3 ll_ref=0 cap_refs={} open={}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:42.142 7ff2a0c2c700 10 break_deleg: breaking delegs on
> 0x100006d9844.head(faked_ino=0 ref=3 ll_ref=0 cap_refs={} open={3=1}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:42.142 7ff2a0c2c700 10 delegations_broken: delegations empty
> on 0x100006d9844.head(faked_ino=0 ref=3 ll_ref=0 cap_refs={} open={3=1}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
>
> ^^ I interpret these as requesting the MDS for a new inode and update
> it's dentry for the "session" directory holding this file. Breaking
> delegations because directory content is going to change.
>
> 2018-08-25 11:10:42.142 7ff2a0c2c700 10 client.15224195 put_inode on
> 0x100006d9844.head(faked_ino=0 ref=5 ll_ref=0 cap_refs={} open={3=1}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:42.142 7ff2a0c2c700 8 client.15224195
> create(#0x1000068547c/sess_bss8rh5bug6bffvj6s67vnsce5, 0100600 layout 0 0 0)
> = 0
> 2018-08-25 11:10:42.142 7ff2a0c2c700 8 client.15224195 _ll_create
> 0x1000068547c.head sess_bss8rh5bug6bffvj6s67vnsce5 0100600 131138 = 0
> (0x557ddf727c20 100006d9844)
> 2018-08-25 11:10:42.142 7ff2a0c2c700 10 client.15224195 put_inode on
> 0x100006d9844.head(faked_ino=0 ref=5 ll_ref=1 cap_refs={} open={3=1}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:42.146 7ff2a042b700 20 client.15224195 choose_target_mds
> starting with req->inode 0x100006d9844.head(faked_ino=0 ref=5 ll_ref=1
> cap_refs={} open={3=1} mode=100600 size=0/4194304 nlink=1 btime=2018-08-25
> 11:10:42.148081 mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25
> 11:10:42.148081 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb)
> objectset[0x100006d9844 ts 0/0 objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:42.146 7ff2a042b700 20 client.15224195 choose_target_mds
> 0x100006d9844.head(faked_ino=0 ref=5 ll_ref=1 cap_refs={} open={3=1}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> is_hash=0 hash=0
> 2018-08-25 11:10:42.146 7ff2a042b700 10 client.15224195 choose_target_mds
> from caps on inode 0x100006d9844.head(faked_ino=0 ref=5 ll_ref=1 cap_refs={}
> open={3=1} mode=100600 size=0/4194304 nlink=1 btime=2018-08-25
> 11:10:42.148081 mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25
> 11:10:42.148081 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb)
> objectset[0x100006d9844 ts 0/0 objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:42.146 7ff2a5c36700 10 client.15224195 put_inode on
> 0x100006d9844.head(faked_ino=0 ref=5 ll_ref=1 cap_refs={} open={3=1}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
>
> ^^ Actually creating the file on reserved inode.
>
> 2018-08-25 11:10:42.462 7ff2a5c36700 10 client.15224195
> update_inode_file_time 0x100006d9844.head(faked_ino=0 ref=4 ll_ref=1
> cap_refs={} open={3=1} mode=100600 size=0/4194304 nlink=1 btime=2018-08-25
> 11:10:42.148081 mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25
> 11:10:42.148081 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb)
> objectset[0x100006d9844 ts 0/0 objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> pAsxLsXsxFsxcrwb ctime 2018-08-25 11:10:42.148081 mtime 2018-08-25
> 11:10:42.148081
>
> ^^ Adjust mtime of inode
>
> 2018-08-25 11:10:42.462 7ff2a5c36700 10 client.15224195 put_inode on
> 0x100006d9844.head(faked_ino=0 ref=4 ll_ref=1 cap_refs={} open={3=1}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:44.654 7ff2a142d700 10 client.15224195 _flush:
> 0x557ddf727c20 on inode 0x100006d9844.head(faked_ino=0 ref=3 ll_ref=1
> cap_refs={} open={3=1} mode=100600 size=0/4194304 nlink=1 btime=2018-08-25
> 11:10:42.148081 mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25
> 11:10:42.148081 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb)
> objectset[0x100006d9844 ts 0/0 objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> no async_err state
>
> ^^ flush cache? This does take quite some time.
>
> 2018-08-25 11:10:44.658 7ff29ec28700 8 client.15224195 _release_fh
> 0x557ddf727c20 mode 3 on 0x100006d9844.head(faked_ino=0 ref=3 ll_ref=1
> cap_refs={} open={3=1} mode=100600 size=0/4194304 nlink=1 btime=2018-08-25
> 11:10:42.148081 mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25
> 11:10:42.148081 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb)
> objectset[0x100006d9844 ts 0/0 objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:44.658 7ff29ec28700 10 client.15224195 _flush
> 0x100006d9844.head(faked_ino=0 ref=4 ll_ref=1 cap_refs={} open={3=0}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:44.658 7ff29ec28700 10 client.15224195 put_inode on
> 0x100006d9844.head(faked_ino=0 ref=4 ll_ref=1 cap_refs={} open={3=0}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:44.658 7ff29ec28700 10 client.15224195 check_caps on
> 0x100006d9844.head(faked_ino=0 ref=3 ll_ref=1 cap_refs={} open={3=0}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> wanted - used - issued pAsxLsXsxFsxcrwb revoking - flags=0
> 2018-08-25 11:10:44.658 7ff29ec28700 10 client.15224195 cap_delay_requeue on
> 0x100006d9844.head(faked_ino=0 ref=3 ll_ref=1 cap_refs={} open={3=0}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:44.658 7ff29ec28700 20 client.15224195 choose_target_mds
> starting with req->inode 0x100006d9844.head(faked_ino=0 ref=4 ll_ref=1
> cap_refs={} open={3=0} mode=100600 size=0/4194304 nlink=1 btime=2018-08-25
> 11:10:42.148081 mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25
> 11:10:42.148081 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb)
> objectset[0x100006d9844 ts 0/0 objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:44.658 7ff29ec28700 20 client.15224195 choose_target_mds
> 0x100006d9844.head(faked_ino=0 ref=4 ll_ref=1 cap_refs={} open={3=0}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> is_hash=0 hash=0
> 2018-08-25 11:10:44.658 7ff29ec28700 10 client.15224195 choose_target_mds
> from caps on inode 0x100006d9844.head(faked_ino=0 ref=4 ll_ref=1 cap_refs={}
> open={3=0} mode=100600 size=0/4194304 nlink=1 btime=2018-08-25
> 11:10:42.148081 mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25
> 11:10:42.148081 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb)
> objectset[0x100006d9844 ts 0/0 objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:44.658 7ff29ec28700 10 client.15224195 _release_fh
> 0x557ddf727c20 on inode 0x100006d9844.head(faked_ino=0 ref=4 ll_ref=1
> cap_refs={} open={3=0} mode=100600 size=0/4194304 nlink=1 btime=2018-08-25
> 11:10:42.148081 mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25
> 11:10:42.148081 caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb)
> objectset[0x100006d9844 ts 0/0 objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> no async_err state
> 2018-08-25 11:10:44.658 7ff29ec28700 10 client.15224195 put_inode on
> 0x100006d9844.head(faked_ino=0 ref=4 ll_ref=1 cap_refs={} open={3=0}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:44.658 7ff2a5c36700 10 client.15224195 put_inode on
> 0x100006d9844.head(faked_ino=0 ref=3 ll_ref=1 cap_refs={} open={3=0}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> 2018-08-25 11:10:50.414 7ff2a6c38700 10 client.15224195 check_caps on
> 0x100006d9844.head(faked_ino=0 ref=2 ll_ref=1 cap_refs={} open={3=0}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> wanted - used - issued pAsxLsXsxFsxcrwb revoking - flags=1
> 2018-08-25 11:10:50.414 7ff2a6c38700 10 client.15224195 send_cap
> 0x100006d9844.head(faked_ino=0 ref=2 ll_ref=1 cap_refs={} open={3=0}
> mode=100600 size=0/4194304 nlink=1 btime=2018-08-25 11:10:42.148081
> mtime=2018-08-25 11:10:42.148081 ctime=2018-08-25 11:10:42.148081
> caps=pAsxLsXsxFsxcrwb(0=pAsxLsXsxFsxcrwb) objectset[0x100006d9844 ts 0/0
> objects 0 dirty_or_tx 0]
> parents=0x1000068547c.head["sess_bss8rh5bug6bffvj6s67vnsce5"] 0x557ddfaa0680)
> mds.0 seq 2 async used - want - flush - retain pAsLsXsFs held
> pAsxLsXsxFsxcrwb revoking - dropping AxXxFxcrwb
>
> ^^ Obtaining new caps?
>
> Please let me now if I'm misinterpreting this. Is this Enough info to figure
> out what action is taking so much time?
>
> Thanks for looking into it.
>
> Gr. Stefan
>
> --
> | BIT BV http://www.bit.nl/ Kamer van Koophandel 09090351
> | GPG: 0xD14839C6 +31 318 648 688 / i...@bit.nl
> _______________________________________________
> ceph-users mailing list
> ceph-users@lists.ceph.com
> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
_______________________________________________
ceph-users mailing list
ceph-users@lists.ceph.com
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
