Project

General

Profile

Bug #23280 » ceph-mds.txt

鹏 张, 03/14/2018 03:43 AM

 
2018-03-14 11:22:36.372572 9c5cb40 0 set uid:gid to 167:167 (ceph:ceph)
2018-03-14 11:22:36.389205 9c5cb40 0 ceph version 10.2.10 (5dc1e4c05cb68dbf62ae6fce3f0700e4654fdbbe), process ceph-mds, pid 18189
2018-03-14 11:22:36.494066 9c5cb40 0 pidfile_write: ignore empty --pid-file
2018-03-14 11:22:40.412346 11693700 1 mds.0.796 handle_mds_map i am now mds.0.796
2018-03-14 11:22:40.414720 11693700 1 mds.0.796 handle_mds_map state change up:boot --> up:replay
2018-03-14 11:22:40.417866 11693700 1 mds.0.796 replay_start
2018-03-14 11:22:40.423130 11693700 1 mds.0.796 recovery set is
2018-03-14 11:22:40.794472 16e9e700 0 mds.0.cache creating system inode with ino:100
2018-03-14 11:22:40.823957 16e9e700 0 mds.0.cache creating system inode with ino:1
2018-03-14 11:22:40.975130 182a0700 0 mds.0.cache.ino(1) add dirfrag: [dir 1 / [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x176d8690]
2018-03-14 11:22:40.994334 182a0700 0 mds.0.cache.ino(100) add dirfrag: [dir 100 ~mds0/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x176d89c0]
2018-03-14 11:22:41.092693 182a0700 0 mds.0.cache.ino(600) add dirfrag: [dir 600 ~mds0/stray0/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x176d8cf0]
2018-03-14 11:22:41.097565 182a0700 0 mds.0.journal dentry is: [inode 10000002d4f [2,head] ~mds0/stray0/10000002d4f auth v166128 dirtyparent s=0 nl=0 n(v0 1=1+0) (iversion lock) cr={262694=0-4194304@1} | dirtyparent=1 dirty=1 0x176a0be0]
2018-03-14 11:22:41.115520 182a0700 0 mds.0.journal dentry is: [inode 10000002d50 [2,head] ~mds0/stray0/10000002d50 auth v166132 dirtyparent s=0 nl=0 n(v0 1=1+0) (iversion lock) cr={262694=0-4194304@1} | dirtyparent=1 dirty=1 0x176a11b0]
2018-03-14 11:22:41.138097 182a0700 0 mds.0.journal dentry is: [inode 10000002d52 [2,head] ~mds0/stray0/10000002d52 auth v166144 dirtyparent s=0 nl=0 n(v0 1=1+0) (iversion lock) cr={262694=0-4194304@1} | dirtyparent=1 dirty=1 0x176a0be0]
2018-03-14 11:22:41.139138 182a0700 0 mds.0.journal dentry is: [inode 10000002d51 [2,head] ~mds0/stray0/10000002d51 auth v166146 dirtyparent s=0 nl=0 n(v0 1=1+0) (iversion lock) cr={262694=0-4194304@1} | dirtyparent=1 dirty=1 0x176a11b0]
2018-03-14 11:22:41.141381 182a0700 0 mds.0.journal dentry is: [inode 10000002d53 [2,head] ~mds0/stray0/10000002d53 auth v166148 dirtyparent s=0 nl=0 n(v0 1=1+0) (iversion lock) cr={262694=0-4194304@1} | dirtyparent=1 dirty=1 0x176a1d50]
2018-03-14 11:22:41.154721 182a0700 1 mds.0.796 replay_done
2018-03-14 11:22:41.156607 182a0700 1 mds.0.796 making mds journal writeable
2018-03-14 11:22:41.301251 11693700 1 mds.0.796 handle_mds_map i am now mds.0.796
2018-03-14 11:22:41.301441 11693700 1 mds.0.796 handle_mds_map state change up:replay --> up:reconnect
2018-03-14 11:22:41.302412 11693700 1 mds.0.796 reconnect_start
2018-03-14 11:22:41.303862 11693700 1 mds.0.796 reopen_log
2018-03-14 11:22:41.307661 11693700 1 mds.0.server reconnect_clients -- 2 sessions
2018-03-14 11:22:41.428155 12695700 1 mds.client.guest ms_verify_authorizer: cannot decode auth caps bl of length 0
2018-03-14 11:22:41.476655 12695700 0 log_channel(cluster) log [DBG] : reconnect by client.209342 10.0.20.34:0/2574572044 after 0.155111
2018-03-14 11:22:41.509783 10691700 1 mds.client.guest ms_verify_authorizer: cannot decode auth caps bl of length 0
2018-03-14 11:22:41.512751 10691700 0 log_channel(cluster) log [DBG] : reconnect by client.262694 10.0.20.33:0/347290937 after 0.205098
2018-03-14 11:22:41.518373 10691700 1 mds.0.796 reconnect_done
2018-03-14 11:22:42.381798 11693700 1 mds.0.796 handle_mds_map i am now mds.0.796
2018-03-14 11:22:42.381930 11693700 1 mds.0.796 handle_mds_map state change up:reconnect --> up:rejoin
2018-03-14 11:22:42.383407 11693700 1 mds.0.796 rejoin_start
2018-03-14 11:22:42.395919 11693700 1 mds.0.796 rejoin_joint_start
2018-03-14 11:22:42.424138 11693700 1 mds.0.796 rejoin_done
2018-03-14 11:22:43.423192 11693700 1 mds.0.796 handle_mds_map i am now mds.0.796
2018-03-14 11:22:43.423254 11693700 1 mds.0.796 handle_mds_map state change up:rejoin --> up:active
2018-03-14 11:22:43.424163 11693700 1 mds.0.796 recovery_done -- successful recovery!
2018-03-14 11:22:43.442733 11693700 0 mds.0.cache.dir(100) fetch on [dir 100 ~mds0/ [2,head] auth v=53788 cv=0/0 dir_auth=0 state=1610612736 f(v0 10=0+10) n(v318 rc2018-03-14 10:54:20.662294 b8442880 533=523+10) hs=1+0,ss=0+0 dirty=1 | child=1 subtree=1 subtreetemp=0 dirty=1 0x176d89c0]
2018-03-14 11:22:43.453004 11693700 0 mds.0.cache.dir(100) want dn is:
2018-03-14 11:22:43.463785 11693700 1 mds.0.796 active_start
2018-03-14 11:22:43.497795 11693700 1 mds.0.796 cluster recovered.
2018-03-14 11:22:43.557266 15e9c700 0 mds.0.cache.dir(1) fetch on [dir 1 / [2,head] auth v=166128 cv=0/0 dir_auth=0 state=1610612736 f(v0 m2018-03-14 10:54:20.662294 2=0+2) n(v380 rc2018-03-14 10:54:20.662294 2=0+2) hs=0+4,ss=0+0 dirty=4 | child=1 subtree=1 subtreetemp=0 dirty=1 0x176d8690]
2018-03-14 11:22:43.558212 15e9c700 0 mds.0.cache.dir(1) want dn is:
2018-03-14 11:22:43.571842 15e9c700 0 mds.0.cache.ino(601) add dirfrag: [dir 601 ~mds0/stray1/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x176d9020]
2018-03-14 11:22:43.572966 15e9c700 0 mds.0.cache.dir(601) fetch on [dir 601 ~mds0/stray1/ [2,head] auth v=0 cv=0/0 state=1073774592 f() n() hs=0+0,ss=0+0 | sticky=1 0x176d9020]
2018-03-14 11:22:43.576995 15e9c700 0 mds.0.cache.dir(601) want dn is:
2018-03-14 11:22:43.590666 15e9c700 0 mds.0.cache.ino(602) add dirfrag: [dir 602 ~mds0/stray2/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x176d9350]
2018-03-14 11:22:43.590860 15e9c700 0 mds.0.cache.dir(602) fetch on [dir 602 ~mds0/stray2/ [2,head] auth v=0 cv=0/0 state=1073774592 f() n() hs=0+0,ss=0+0 | sticky=1 0x176d9350]
2018-03-14 11:22:43.591072 15e9c700 0 mds.0.cache.dir(602) want dn is:
2018-03-14 11:22:43.604883 15e9c700 0 mds.0.cache.ino(603) add dirfrag: [dir 603 ~mds0/stray3/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x176d9680]
2018-03-14 11:22:43.605080 15e9c700 0 mds.0.cache.dir(603) fetch on [dir 603 ~mds0/stray3/ [2,head] auth v=0 cv=0/0 state=1073774592 f() n() hs=0+0,ss=0+0 | sticky=1 0x176d9680]
2018-03-14 11:22:43.605272 15e9c700 0 mds.0.cache.dir(603) want dn is:
2018-03-14 11:22:43.608342 15e9c700 0 mds.0.cache.ino(604) add dirfrag: [dir 604 ~mds0/stray4/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x176d99b0]
2018-03-14 11:22:43.608520 15e9c700 0 mds.0.cache.dir(604) fetch on [dir 604 ~mds0/stray4/ [2,head] auth v=0 cv=0/0 state=1073774592 f() n() hs=0+0,ss=0+0 | sticky=1 0x176d99b0]
2018-03-14 11:22:43.608712 15e9c700 0 mds.0.cache.dir(604) want dn is:
2018-03-14 11:22:43.611612 15e9c700 0 mds.0.cache.ino(605) add dirfrag: [dir 605 ~mds0/stray5/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x176d9ce0]
2018-03-14 11:22:43.611790 15e9c700 0 mds.0.cache.dir(605) fetch on [dir 605 ~mds0/stray5/ [2,head] auth v=0 cv=0/0 state=1073774592 f() n() hs=0+0,ss=0+0 | sticky=1 0x176d9ce0]
2018-03-14 11:22:43.611973 15e9c700 0 mds.0.cache.dir(605) want dn is:
2018-03-14 11:22:43.614893 15e9c700 0 mds.0.cache.ino(606) add dirfrag: [dir 606 ~mds0/stray6/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x176da010]
2018-03-14 11:22:43.615087 15e9c700 0 mds.0.cache.dir(606) fetch on [dir 606 ~mds0/stray6/ [2,head] auth v=0 cv=0/0 state=1073774592 f() n() hs=0+0,ss=0+0 | sticky=1 0x176da010]
2018-03-14 11:22:43.615271 15e9c700 0 mds.0.cache.dir(606) want dn is:
2018-03-14 11:22:43.618672 15e9c700 0 mds.0.cache.ino(607) add dirfrag: [dir 607 ~mds0/stray7/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x176da340]
2018-03-14 11:22:43.618860 15e9c700 0 mds.0.cache.dir(607) fetch on [dir 607 ~mds0/stray7/ [2,head] auth v=0 cv=0/0 state=1073774592 f() n() hs=0+0,ss=0+0 | sticky=1 0x176da340]
2018-03-14 11:22:43.619058 15e9c700 0 mds.0.cache.dir(607) want dn is:
2018-03-14 11:22:43.622326 15e9c700 0 mds.0.cache.ino(608) add dirfrag: [dir 608 ~mds0/stray8/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x176da670]
2018-03-14 11:22:43.622617 15e9c700 0 mds.0.cache.dir(608) fetch on [dir 608 ~mds0/stray8/ [2,head] auth v=0 cv=0/0 state=1073774592 f() n() hs=0+0,ss=0+0 | sticky=1 0x176da670]
2018-03-14 11:22:43.622920 15e9c700 0 mds.0.cache.dir(608) want dn is:
2018-03-14 11:22:43.640481 15e9c700 0 mds.0.cache.ino(609) add dirfrag: [dir 609 ~mds0/stray9/ [2,head] auth v=0 cv=0/0 state=1073741824 f() n() hs=0+0,ss=0+0 0x176da9a0]
2018-03-14 11:22:43.640656 15e9c700 0 mds.0.cache.dir(609) fetch on [dir 609 ~mds0/stray9/ [2,head] auth v=0 cv=0/0 state=1073774592 f() n() hs=0+0,ss=0+0 | sticky=1 0x176da9a0]
2018-03-14 11:22:43.640872 15e9c700 0 mds.0.cache.dir(609) want dn is:
2018-03-14 11:22:43.655989 15e9c700 0 mds.0.cache populate_mydir done
2018-03-14 11:22:43.658546 15e9c700 0 mds.0.cache scan stray dir fetch: 0x176d8cf0
2018-03-14 11:22:43.659959 15e9c700 0 mds.0.cache.dir(600) fetch on [dir 600 ~mds0/stray0/ [2,head] auth v=166165 cv=0/0 state=1610645504 f(v74 m2018-03-14 10:54:20.662294) n(v77 rc2018-03-14 10:54:20.662294) hs=0+5,ss=0+0 dirty=5 | child=1 sticky=1 dirty=1 0x176d8cf0]
2018-03-14 11:22:43.660378 15e9c700 0 mds.0.cache.dir(600) want dn is:
2018-03-14 11:22:43.789191 15e9c700 0 mds.0.cache dentry is [dentry #100/stray0/10000002d50 [2,head] auth NULL (dversion lock) v=166138 inode=0 | inodepin=0 dirty=1 0x176e1990]
2018-03-14 11:22:43.797950 15e9c700 0 mds.0.cache.strays num: 1
2018-03-14 11:22:43.806504 15e9c700 0 mds.0.cache dentry is [dentry #100/stray0/10000002d4f [2,head] auth NULL (dversion lock) v=166136 inode=0 | inodepin=0 dirty=1 0x176e1800]
2018-03-14 11:22:43.806641 15e9c700 0 mds.0.cache.strays num: 2
2018-03-14 11:22:43.806677 15e9c700 0 mds.0.cache dentry is [dentry #100/stray0/10000002d51 [2,head] auth NULL (dversion lock) v=166150 inode=0 | inodepin=0 dirty=1 0x176e1fd0]
2018-03-14 11:22:43.806829 15e9c700 0 mds.0.cache.strays num: 3
2018-03-14 11:22:43.806880 15e9c700 0 mds.0.cache dentry is [dentry #100/stray0/10000002d52 [2,head] auth NULL (dversion lock) v=166152 inode=0 | inodepin=0 dirty=1 0x176e1e40]
2018-03-14 11:22:43.807018 15e9c700 0 mds.0.cache.strays num: 4
2018-03-14 11:22:43.807053 15e9c700 0 mds.0.cache dentry is [dentry #100/stray0/10000002d53 [2,head] auth NULL (dversion lock) v=166160 inode=0 | inodepin=0 dirty=1 0x176e2160]
2018-03-14 11:22:43.807233 15e9c700 0 mds.0.cache.strays num: 5
(2-2/2)