this is mds log when "debug_mds=10"
---------------------------------------------------------------------------------------------------------------------------------------------------------------
2018-03-10 16:38:23.794988 7f59e6b0d700 10 mds.0.locker eval done
2018-03-10 16:38:23.794991 7f59e6b0d700 7 mds.0.server
dispatch_client_request client_request(client.26217:7596 create
#1/.testshiqi.swp 2018-03-10 16:38:23.791799) v2
2018-03-10 16:38:23.794998 7f59e6b0d700 7 mds.0.server open w/
O_CREAT on #1/.testshiqi.swp
2018-03-10 16:38:23.795000 7f59e6b0d700 10 mds.0.server
rdlock_path_xlock_dentry mutation(0x56404b18e300) #1/.testshiqi.swp
2018-03-10 16:38:23.795004 7f59e6b0d700 10 mds.0.server
traverse_to_auth_dir dirpath #1 dname .testshiqi.swp
2018-03-10 16:38:23.795007 7f59e6b0d700 7 mds.0.cache traverse:
opening base ino 1 snap head
2018-03-10 16:38:23.795010 7f59e6b0d700 10 mds.0.cache path_traverse
finish on snapid head
2018-03-10 16:38:23.795012 7f59e6b0d700 10 mds.0.server
traverse_to_auth_dir [dir 1 / [2,head] auth v=424949 cv=0/0 dir_auth=0
state=1610612738|complete f(v0 m2018-03-10 15:45:43.404182 3=2+1)
n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328715=28719166+7609549) hs=3+2,ss=0+0 dirty=2 | child=1 subtree=1
subtreetemp=0 dirty=1 waiter=0 authpin=0 0x563fedfca000]
2018-03-10 16:38:23.795068 7f59e6b0d700 10 mds.0.server
rdlock_path_xlock_dentry dir [dir 1 / [2,head] auth v=424949 cv=0/0
dir_auth=0 state=1610612738|complete f(v0 m2018-03-10 15:45:43.404182
3=2+1) n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328715=28719166+7609549) hs=3+2,ss=0+0 dirty=2 | child=1 subtree=1
subtreetemp=0 dirty=1 waiter=0 authpin=0 0x563fedfca000]
2018-03-10 16:38:23.795083 7f59e6b0d700 10 mds.0.server
prepare_null_dentry .testshiqi.swp in [dir 1 / [2,head] auth v=424949
cv=0/0 dir_auth=0 state=1610612738|complete f(v0 m2018-03-10
15:45:43.404182 3=2+1) n(v35010 rc2018-03-10 15:45:43.404182
b4176238075083 36328715=28719166+7609549) hs=3+2,ss=0+0 dirty=2 |
child=1 subtree=1 subtreetemp=0 dirty=1 waiter=0 authpin=0
0x563fedfca000]
2018-03-10 16:38:23.795103 7f59e6b0d700 10 mds.0.locker acquire_locks
mutation(0x56404b18e300)
2018-03-10 16:38:23.795111 7f59e6b0d700 10 mds.0.locker must authpin
[inode 1 [...2,head] / auth v183815 snaprealm=0x563fedd81180 f(v0
m2018-03-10 15:45:43.404182 3=2+1) n(v35010 rc2018-03-10
15:45:43.404182 b4176238075083 36328716=28719166+7609550)/n(v0 1=0+1)
(inest lock) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXsFs/-@4},l=26217
| dirtyscattered=0 request=0 lock=0 dirfrag=1 caps=1 dirty=1 authpin=0
0x563feddb25d0]
2018-03-10 16:38:23.795134 7f59e6b0d700 10 mds.0.locker must authpin
[dentry #1/.testshiqi.swp [2,head] auth NULL (dversion lock) v=424947
inode=0 | inodepin=0 dirty=1 0x563ff3010730]
2018-03-10 16:38:23.795141 7f59e6b0d700 10 mds.0.locker auth_pinning
[inode 1 [...2,head] / auth v183815 snaprealm=0x563fedd81180 f(v0
m2018-03-10 15:45:43.404182 3=2+1) n(v35010 rc2018-03-10
15:45:43.404182 b4176238075083 36328716=28719166+7609550)/n(v0 1=0+1)
(inest lock) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXsFs/-@4},l=26217
| dirtyscattered=0 request=0 lock=0 dirfrag=1 caps=1 dirty=1 authpin=0
0x563feddb25d0]
2018-03-10 16:38:23.795162 7f59e6b0d700 10 mds.0.cache.ino(1) auth_pin
by 0x56404b18e300 on [inode 1 [...2,head] / auth v183815 ap=1+0
snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182 3=2+1)
n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (inest lock) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXsFs/-@4},l=26217
| dirtyscattered=0 request=0 lock=0 dirfrag=1 caps=1 dirty=1 authpin=1
0x563feddb25d0] now 1+0
2018-03-10 16:38:23.795221 7f59e6b0d700 10 mds.0.locker auth_pinning
[dentry #1/.testshiqi.swp [2,head] auth NULL (dversion lock) v=424947
inode=0 | inodepin=0 dirty=1 0x563ff3010730]
2018-03-10 16:38:23.795228 7f59e6b0d700 10 mds.0.cache.den(1
.testshiqi.swp) auth_pin by 0x56404b18e300 on [dentry
#1/.testshiqi.swp [2,head] auth NULL (dversion lock) v=424947 ap=1+0
inode=0 | inodepin=0 dirty=1 authpin=1 0x563ff3010730] now 1+0
2018-03-10 16:38:23.795237 7f59e6b0d700 7 mds.0.locker
local_wrlock_start on (dversion lock) on [dentry #1/.testshiqi.swp
[2,head] auth NULL (dversion lock) v=424947 ap=1+0 inode=0 |
inodepin=0 dirty=1 authpin=1 0x563ff3010730]
2018-03-10 16:38:23.795245 7f59e6b0d700 10 mds.0.locker got wrlock on
(dversion lock w=1 last_client=26217) [dentry #1/.testshiqi.swp
[2,head] auth NULL (dversion lock w=1 last_client=26217) v=424947
ap=1+0 inode=0 | lock=1 inodepin=0 dirty=1 authpin=1 0x563ff3010730]
2018-03-10 16:38:23.795295 7f59e6b0d700 7 mds.0.locker xlock_start on
(dn sync) on [dentry #1/.testshiqi.swp [2,head] auth NULL (dversion
lock w=1 last_client=26217) v=424947 ap=1+0 inode=0 | lock=1
inodepin=0 dirty=1 authpin=1 0x563ff3010730]
2018-03-10 16:38:23.795303 7f59e6b0d700 7 mds.0.locker simple_lock on
(dn sync) on [dentry #1/.testshiqi.swp [2,head] auth NULL (dversion
lock w=1 last_client=26217) v=424947 ap=1+0 inode=0 | lock=1
inodepin=0 dirty=1 authpin=1 0x563ff3010730]
2018-03-10 16:38:23.795310 7f59e6b0d700 7 mds.0.locker simple_xlock
on (dn lock) on [dentry #1/.testshiqi.swp [2,head] auth NULL (dn lock)
(dversion lock w=1 last_client=26217) v=424947 ap=1+0 inode=0 |
request=1 lock=1 inodepin=0 dirty=1 authpin=1 0x563ff3010730]
2018-03-10 16:38:23.795245 7f59e6b0d700 10 mds.0.locker got wrlock on
(dversion lock w=1 last_client=26217) [dentry #1/.testshiqi.swp
[2,head] auth NULL (dversion lock w=1 last_client=26217) v=424947
ap=1+0 inode=0 | lock=1 inodepin=0 dirty=1 authpin=1 0x563ff3010730]
2018-03-10 16:38:23.795295 7f59e6b0d700 7 mds.0.locker xlock_start on
(dn sync) on [dentry #1/.testshiqi.swp [2,head] auth NULL (dversion
lock w=1 last_client=26217) v=424947 ap=1+0 inode=0 | lock=1
inodepin=0 dirty=1 authpin=1 0x563ff3010730]
2018-03-10 16:38:23.795303 7f59e6b0d700 7 mds.0.locker simple_lock on
(dn sync) on [dentry #1/.testshiqi.swp [2,head] auth NULL (dversion
lock w=1 last_client=26217) v=424947 ap=1+0 inode=0 | lock=1
inodepin=0 dirty=1 authpin=1 0x563ff3010730]
2018-03-10 16:38:23.795310 7f59e6b0d700 7 mds.0.locker simple_xlock
on (dn lock) on [dentry #1/.testshiqi.swp [2,head] auth NULL (dn lock)
(dversion lock w=1 last_client=26217) v=424947 ap=1+0 inode=0 |
request=1 lock=1 inodepin=0 dirty=1 authpin=1 0x563ff3010730]
2018-03-10 16:38:23.795318 7f59e6b0d700 10 mds.0.cache.den(1
.testshiqi.swp) auth_pin by 0x563ff3010838 on [dentry
#1/.testshiqi.swp [2,head] auth NULL (dn lock) (dversion lock w=1
last_client=26217) v=424947 ap=2+0 inode=0 | request=1 lock=1
inodepin=0 dirty=1 authpin=1 0x563ff3010730] now 2+0
2018-03-10 16:38:23.795328 7f59e6b0d700 10 mds.0.locker got xlock on
(dn xlock x=1 by 0x56404b18e300) [dentry #1/.testshiqi.swp [2,head]
auth NULL (dn xlock x=1 by 0x56404b18e300) (dversion lock w=1
last_client=26217) v=424947 ap=2+0 inode=0 | request=1 lock=2
inodepin=0 dirty=1 authpin=1 0x563ff3010730]
2018-03-10 16:38:23.795338 7f59e6b0d700 7 mds.0.locker rdlock_start
on (isnap sync) on [inode 1 [...2,head] / auth v183815 ap=1+0
snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182 3=2+1)
n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (inest lock) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXsFs/-@4},l=26217
| dirtyscattered=0 request=0 lock=0 dirfrag=1 caps=1 dirty=1 authpin=1
0x563feddb25d0]
2018-03-10 16:38:23.795367 7f59e6b0d700 10 mds.0.locker got rdlock on
(isnap sync r=1) [inode 1 [...2,head] / auth v183815 ap=1+0
snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182 3=2+1)
n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXsFs/-@4},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1
0x563feddb25d0]
2018-03-10 16:38:23.795392 7f59e6b0d700 10 mds.0.locker wrlock_start
(ifile sync) on [inode 1 [...2,head] / auth v183815 ap=1+0
snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182 3=2+1)
n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXsFs/-@4},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1
0x563feddb25d0]
2018-03-10 16:38:23.795416 7f59e6b0d700 7 mds.0.locker scatter_mix
(ifile sync) on [inode 1 [...2,head] / auth v183815 ap=1+0
snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182 3=2+1)
n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXsFs/-@4},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1
0x563feddb25d0]
2018-03-10 16:38:23.795478 7f59e6b0d700 7 mds.0.locker issue_caps
loner client.26217 allowed=pAsLsXsFrl, xlocker allowed=pAsLsXsFrl,
others allowed=pAsLsXsFrl on [inode 1 [...2,head] / auth v183815
ap=1+0 snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182
3=2+1) n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(ifile sync->mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXsFs/-@4},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1
0x563feddb25d0]
2018-03-10 16:38:23.795510 7f59e6b0d700 7 mds.0.locker sending
MClientCaps to client.26337 seq 5 new pending pAsLsXs was pAsLsXsFs
2018-03-10 16:38:23.795535 7f59e6b0d700 10 mds.0.20816
send_message_client_counted client.26337 seq 1 client_caps(revoke ino
1 222378799 seq 5 caps=pAsLsXs dirty=- wanted=- follows 0 size 0/0
mtime 2018-03-10 15:45:43.404182) v8
2018-03-10 16:38:23.795653 7f59e6b0d700 10 mds.0.cache.ino(1) auth_pin
by 0x563feddb2a90 on [inode 1 [...2,head] / auth v183815 ap=2+0
snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182 3=2+1)
n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(ifile sync->mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/pAsLsXsFs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1
0x563feddb25d0] now 2+0
2018-03-10 16:38:23.795680 7f59e6b0d700 7 mds.0.locker wrlock_start
waiting on (ifile sync->mix) on [inode 1 [...2,head] / auth v183815
ap=2+0 snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182
3=2+1) n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(ifile sync->mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/pAsLsXsFs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=1
0x563feddb25d0]
2018-03-10 16:38:23.795706 7f59e6b0d700 10 mds.0.cache.ino(1)
add_waiter tag 2000000040000000 0x564009216d50 !ambig 1 !frozen 1
!freezing 1
2018-03-10 16:38:23.795712 7f59e6b0d700 10 mds.0.locker nudge_log
(ifile sync->mix) on [inode 1 [...2,head] / auth v183815 ap=2+0
snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182 3=2+1)
n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(ifile sync->mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/pAsLsXsFs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 waiter=1
authpin=1 0x563feddb25d0]
2018-03-10 16:38:23.796523 7f59e6b0d700 7 mds.0.locker
handle_client_caps on 1 tid 0 follows 0 op update
2018-03-10 16:38:23.796528 7f59e6b0d700 10 mds.0.locker cap inode
[inode 1 [...2,head] / auth v183815 ap=2+0 snaprealm=0x563fedd81180
f(v0 m2018-03-10 15:45:43.404182 3=2+1) n(v35010 rc2018-03-10
15:45:43.404182 b4176238075083 36328716=28719166+7609550)/n(v0 1=0+1)
(isnap sync r=1) (inest lock) (ifile sync->mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/pAsLsXsFs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 waiter=1
authpin=1 0x563feddb25d0]
2018-03-10 16:38:23.796590 7f59e6b0d700 10 mds.0.locker follows 0
retains pAsLsXs dirty - on [inode 1 [...2,head] / auth v183815 ap=2+0
snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182 3=2+1)
n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(ifile sync->mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 waiter=1
authpin=1 0x563feddb25d0]
2018-03-10 16:38:23.796618 7f59e6b0d700 10 mds.0.locker _do_cap_update
dirty - issued pAsLsXs wanted - on [inode 1 [...2,head] / auth v183815
ap=2+0 snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182
3=2+1) n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(ifile sync->mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 waiter=1
authpin=1 0x563feddb25d0]
2018-03-10 16:38:23.796644 7f59e6b0d700 10 mds.0.locker eval 2496
[inode 1 [...2,head] / auth v183815 ap=2+0 snaprealm=0x563fedd81180
f(v0 m2018-03-10 15:45:43.404182 3=2+1) n(v35010 rc2018-03-10
15:45:43.404182 b4176238075083 36328716=28719166+7609550)/n(v0 1=0+1)
(isnap sync r=1) (inest lock) (ifile sync->mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 waiter=1
authpin=1 0x563feddb25d0]
2018-03-10 16:38:23.796666 7f59e6b0d700 10 mds.0.locker eval set loner
to client.26217
2018-03-10 16:38:23.796669 7f59e6b0d700 10 mds.0.locker eval_gather
(ifile sync->mix) on [inode 1 [...2,head] / auth v183815 ap=2+0
snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182 3=2+1)
n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(ifile sync->mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 waiter=1
authpin=1 0x563feddb25d0]
2018-03-10 16:38:23.796694 7f59e6b0d700 10 mds.0.locker next state is
mix issued/allows loner /rwl xlocker /rwl other /rwl
2018-03-10 16:38:23.796700 7f59e6b0d700 7 mds.0.locker eval_gather
finished gather on (ifile sync->mix) on [inode 1 [...2,head] / auth
v183815 ap=2+0 snaprealm=0x563fedd81180 f(v0 m2018-03-10
15:45:43.404182 3=2+1) n(v35010 rc2018-03-10 15:45:43.404182
b4176238075083 36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1)
(inest lock) (ifile sync->mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 waiter=1
authpin=1 0x563feddb25d0]
2018-03-10 16:38:23.796729 7f59e6b0d700 10 mds.0.cache.ino(1)
start_scatter (ifile sync->mix) on [inode 1 [...2,head] / auth v183815
ap=2+0 snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182
3=2+1) n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(ifile sync->mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 waiter=1
authpin=1 0x563feddb25d0]
2018-03-10 16:38:23.796753 7f59e6b0d700 10 mds.0.cache.ino(1)
finish_scatter_update * accounted (ifile sync->mix) scatter stat
unchanged at v0
2018-03-10 16:38:23.796757 7f59e6b0d700 10 mds.0.cache.ino(1)
auth_unpin by 0x563feddb2a90 on [inode 1 [...2,head] / auth v183815
ap=1+0 snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182
3=2+1) n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(ifile mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 waiter=1
authpin=1 0x563feddb25d0] now 1+0
2018-03-10 16:38:23.796788 7f59e6b0d700 7 mds.0.locker file_eval
wanted=sx loner_wanted=sx other_wanted= filelock=(ifile mix) on
[inode 1 [...2,head] / auth v183815 ap=1+0 snaprealm=0x563fedd81180
f(v0 m2018-03-10 15:45:43.404182 3=2+1) n(v35010 rc2018-03-10
15:45:43.404182 b4176238075083 36328716=28719166+7609550)/n(v0 1=0+1)
(isnap sync r=1) (inest lock) (ifile mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 waiter=0
authpin=1 0x563feddb25d0]
2018-03-10 16:38:23.796817 7f59e6b0d700 10 mds.0.locker simple_eval
(iauth sync) on [inode 1 [...2,head] / auth v183815 ap=1+0
snaprealm=0x563fedd81180 f(v0 m2018-03-10 15:45:43.404182 3=2+1)
n(v35010 rc2018-03-10 15:45:43.404182 b4176238075083
36328716=28719166+7609550)/n(v0 1=0+1) (isnap sync r=1) (inest lock)
(ifile mix) (iversion lock)
caps={26049=pAsLsXs/-@0,26217=pAsLsXs/pAsLsXsFsx@2,26337=pAsLsXs/-@5},l=26217
| dirtyscattered=0 request=0 lock=1 dirfrag=1 caps=1 dirty=1 waiter=0
authpin=1 0x563feddb25d0]
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
2018-03-10 9:09 GMT+08:00 Yan, Zheng <ukernel@xxxxxxxxx>:
> The op dump does not show what happened. please set debug_mds=10 for a
> short period of time, gather some mds log. you said mds use 200% cpu,
> that's close to single mds's processing power.
>
>
> On Fri, Mar 9, 2018 at 9:11 PM, qi Shi <m13913886148@xxxxxxxxx> wrote:
>> 1, when I use "ls" command
>> ---------------------------------------------------------------------
>> [root@JXQ-240-27-10 mycephfs]# time ls
>> gpu testshiqi tiger
>>
>> real 0m3.325s
>> user 0m0.000s
>> sys 0m0.008s
>> ---------------------------------------------------------------------
>>
>>
>> 2, When I use vi to quickly open or close files.
>> ------------------------------------------------------------------------
>> [root@JXQ-240-27-10 mycephfs]# time vi testshiqi
>> real 0m7.529s
>> user 0m0.002s
>> sys 0m0.012s
>> ----------------------------------------------------------------------
>> Sometimes executing "vi xxxfile" command will delay for a few seconds
>> Sometimes executing "q!" command to close file will delay for a few seconds
>> "testshiqi" is a test file and only I am using it alone
>>
>> 2018-03-09 21:00 GMT+08:00 qi Shi <m13913886148@xxxxxxxxx>:
>>> User response:
>>> 1, Using the vi tool to open the file is very slow.
>>> 2, Using "ls" and "du" commands is very slow.
>>>
>>> How to solve this problem?
>>>
>>> The ceph-mds operation log I collected:
>>> ------------------------------------------------------------------------------------------------------------
>>> "description": "client_request(client.26337:550474 open
>>> #100018f693d\/zj_12345067041514269333_20171227031708_6503737997126613699_120.wav
>>> 2018-03-09 19:40:01.664683)",
>>> "initiated_at": "2018-03-09 19:40:01.665946",
>>> "age": 30.520671,
>>> "duration": 10.221127,
>>> "type_data": [
>>> "done",
>>> "client.26337:550474",
>>> "client_request",
>>> {
>>> "client": "client.26337",
>>> "tid": 550474
>>> },
>>> [
>>> {
>>> "time": "2018-03-09 19:40:01.665946",
>>> "event": "initiated"
>>> },
>>> {
>>> "time": "2018-03-09 19:40:11.885465",
>>> "event": "acquired locks"
>>> },
>>> {
>>> "time": "2018-03-09 19:40:11.885772",
>>> "event": "replying"
>>> },
>>> {
>>> "time": "2018-03-09 19:40:11.885991",
>>> "event": "finishing request"
>>> },
>>> {
>>> "time": "2018-03-09 19:40:11.887036",
>>> "event": "cleaned up request"
>>> },
>>> {
>>> "time": "2018-03-09 19:40:11.887073",
>>> "event": "done"
>>> }
>>> ]
>>> ----------------------------------------------------------------------------------------------------
>>> I found a 10 second delay between "initiated" and "acquired locks" events
>>>
>>>
>>> My hardware configuration:
>>> 1, All osds of hard disk is SSD.
>>> 2, osds: 64
>>> 3, memory : 256G
>>> 4, cpus : 48
>>> 5, network: 20000Mb/s
>>> 6, ceph version : 10.2.6
>>> 7, linux kernel version: 4.13
>>>
>>> ceph-mds usage:
>>> 1,ceph-mds memory usage: 4G
>>> 2,ceph-mds cpu usage rate: 200%
>>> 3, files : 30 million small files in cephfs
>>> 4, objects: 100 million objects in cephfs_data pool
>>> 5, 10 users are operating in their own private folder, data is not shared
>>> 6, Every user uses the AI program to read, write, and search training
>>> files, and he also uses vi tool to edit script files.
>>>
>>> ceph osd perf:
>>> ---------------------------------------------------------------------------------------------------
>>> osd fs_commit_latency(ms) fs_apply_latency(ms)
>>> 9 0 2
>>> 8 1 3
>>> 7 0 2
>>> 63 0 2
>>> 62 0 1
>>> 61 0 2
>>> 60 0 2
>>> 6 0 2
>>> 59 1 2
>>> 58 1 2
>>> 57 1 2
>>> 56 1 2
>>> 55 1 3
>>> 54 0 2
>>> 53 1 2
>>> ---------------------------------------------------------------------------------------------------
>>> So I think delay is not the reason for osd
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
