|
2011-02-09 23:33:21.361554 7f67d1f61700 mds0.cache check_memory_usage total 2146608, rss 2047276, heap 71664, malloc 471282 mmap 0, baseline 70292, buffers 14650, max 1048576, 120584 / 120595 inodes have caps, 120584 caps, 0.999909 caps per inode
|
|
2011-02-09 23:33:21.361585 7f67d1f61700 mds0.server recall_client_state 0.746368, caps per client 100-80000
|
|
2011-02-09 23:33:21.361600 7f67d1f61700 mds0.server session client4105 10.233.55.138:0/2745458521 caps 120584, leases 0
|
|
2011-02-09 23:33:21.361615 7f67d1f61700 mds0.2 send_message_client client4105 10.233.55.138:0/2745458521 client_session(recall_state max_caps 80000 max_leases 0) v1
|
|
2011-02-09 23:33:21.361629 7f67d1f61700 -- 10.202.105.222:6800/18701 --> 10.233.55.138:0/2745458521 -- client_session(recall_state max_caps 80000 max_leases 0) v1 -- ?+0 0x3517b000 con 0x95cc000
|
|
2011-02-09 23:33:21.361685 7f67d1f61700 mds0.log trim 31 / 30 segments, 66677 / -1 events, 0 (0) expiring, 0 (0) expired
|
|
2011-02-09 23:33:21.361702 7f67d1f61700 mds0.journal LogSegment(725615142).try_to_expire
|
|
2011-02-09 23:33:21.361846 7f67d1f61700 mds0.cache.dir(1000001ce07) commit want 0 on [dir 1000001ce07 /bigfiles6/ [2,head] auth pv=455703 v=453659 cv=326549/326549 ap=1022+1410+1410 state=1610612738|complete f(v0 m2011-02-09 23:33:18.200205 112065=112065+0) n(v0 rc2011-02-09 23:33:18.200205 b442003456 112065=112065+0) hs=112065+431,ss=0+0 dirty=32637 | child dirty authpin 0xe91e78]
|
|
2011-02-09 23:33:21.361883 7f67d1f61700 mds0.cache.dir(1000001ce07) auth_pin by 0xe91e78 on [dir 1000001ce07 /bigfiles6/ [2,head] auth pv=455703 v=453659 cv=326549/326549 ap=1023+1410+1410 state=1610612738|complete f(v0 m2011-02-09 23:33:18.200205 112065=112065+0) n(v0 rc2011-02-09 23:33:18.200205 b442003456 112065=112065+0) hs=112065+431,ss=0+0 dirty=32637 | child dirty authpin 0xe91e78] count now 1023 + 1410
|
|
2011-02-09 23:33:21.361906 7f67d1f61700 mds0.cache.dir(1000001ce07) _commit want 453659 on [dir 1000001ce07 /bigfiles6/ [2,head] auth pv=455703 v=453659 cv=326549/326549 ap=1023+1410+1410 state=1610612738|complete f(v0 m2011-02-09 23:33:18.200205 112065=112065+0) n(v0 rc2011-02-09 23:33:18.200205 b442003456 112065=112065+0) hs=112065+431,ss=0+0 dirty=32637 | child dirty authpin 0xe91e78]
|
|
2011-02-09 23:33:21.361927 7f67d1f61700 mds0.cache.dir(1000001ce07) marking committing
|
|
2011-02-09 23:33:21.361936 7f67d1f61700 mds0.cache.snaprealm(1 seq 1 0xe6b6c0) have_past_parents_open [1,head]
|
|
2011-02-09 23:33:21.361947 7f67d1f61700 mds0.cache.dir(1000001ce07) _commit_full
|
|
2011-02-09 23:33:37.324397 7f67cff56700 -- 10.202.105.222:6800/18701 >> 10.233.55.138:0/2745458521 pipe(0x8d25000 sd=14 pgs=15 cs=1 l=0).fault with nothing to send, going to standby
|
|
2011-02-09 23:33:37.381518 7f67d1f61700 -- 10.202.105.222:6800/18701 --> 10.67.65.62:6800/9578 -- osd_op(mds0.2:114824 1000001ce07.00000000 [tmapput 0~42570481,setxattr path (10),setxattr parent (30)] 1.3ea6) v1 -- ?+0 0x59129000 con 0xe70640
|
|
2011-02-09 23:33:37.398755 7f67d1f61700 mds0.log submit_entry 852882591~1457359 : EOpen [metablob 1000001ce07, 3 dirs], 3796 open files
|
|
2011-02-09 23:33:37.400166 7f67d1f61700 mds0.journal try_to_expire waiting for open files to rejournal
|
|
2011-02-09 23:33:37.400185 7f67d1f61700 mds0.journal LogSegment(725615142).try_to_expire waiting
|
|
2011-02-09 23:33:37.400982 7f67d1f61700 -- 10.202.105.222:6800/18701 --> 10.202.105.222:6801/18768 -- osd_op(mds0.2:114825 200.000000cb [write 1438879~1457363] 1.2744) v1 -- ?+0 0x1fc49000 con 0xe5c3c0
|
|
2011-02-09 23:33:37.401205 7f67d1f61700 -- 10.202.105.222:6800/18701 --> 10.202.105.222:6801/18768 -- osd_op(mds0.2:114826 200.00000000 [writefull 0~84] 1.3494) v1 -- ?+0 0x4706b40 con 0xe5c3c0
|
|
2011-02-09 23:33:37.401229 7f67d1f61700 mds0.log try_expire expiring segment 725615142
|
|
2011-02-09 23:33:37.402320 7f67d1f61700 mds0.locker scatter_tick
|
|
2011-02-09 23:33:37.402334 7f67d1f61700 mds0.locker scatter_nudge auth, scatter/unscattering (inest lock w=1022 dirty) on [inode 1 [...2,head] / auth v8839 pv8868 ap=438 snaprealm=0xe6b6c0 f(v1 m2011-02-09 23:24:24.488857 5=0+5) n(v2136 rc2011-02-09 23:33:17.033264 b892796928 229231=229226+5)/n(v0 1=0+1) (inest lock w=1022 dirty) (iversion lock w=29 last_client=4105) caps={4105=pAsLsXsFs/-@8} | dirtyscattered lock dirfrag caps dirty authpin 0xe72000]
|
|
2011-02-09 23:33:37.402367 7f67d1f61700 mds0.locker simple_sync on (inest lock w=1022 dirty) on [inode 1 [...2,head] / auth v8839 pv8868 ap=438 snaprealm=0xe6b6c0 f(v1 m2011-02-09 23:24:24.488857 5=0+5) n(v2136 rc2011-02-09 23:33:17.033264 b892796928 229231=229226+5)/n(v0 1=0+1) (inest lock w=1022 dirty) (iversion lock w=29 last_client=4105) caps={4105=pAsLsXsFs/-@8} | dirtyscattered lock dirfrag caps dirty authpin 0xe72000]
|
|
2011-02-09 23:33:37.402384 7f67d1f61700 mds0.cache.ino(1) auth_pin by 0xe72800 on [inode 1 [...2,head] / auth v8839 pv8868 ap=439 snaprealm=0xe6b6c0 f(v1 m2011-02-09 23:24:24.488857 5=0+5) n(v2136 rc2011-02-09 23:33:17.033264 b892796928 229231=229226+5)/n(v0 1=0+1) (inest lock->sync w=1022 dirty) (iversion lock w=29 last_client=4105) caps={4105=pAsLsXsFs/-@8} | dirtyscattered lock dirfrag caps dirty authpin 0xe72000] now 439+0
|
|
2011-02-09 23:33:37.402422 7f67d1f61700 mds0.locker scatter_nudge auth, waiting for stable (inest lock->sync w=1022 dirty) on [inode 1 [...2,head] / auth v8839 pv8868 ap=439 snaprealm=0xe6b6c0 f(v1 m2011-02-09 23:24:24.488857 5=0+5) n(v2136 rc2011-02-09 23:33:17.033264 b892796928 229231=229226+5)/n(v0 1=0+1) (inest lock->sync w=1022 dirty) (iversion lock w=29 last_client=4105) caps={4105=pAsLsXsFs/-@8} | dirtyscattered lock dirfrag caps dirty authpin 0xe72000]
|
|
2011-02-09 23:33:37.402440 7f67d1f61700 mds0.server find_idle_sessions. laggy until 0.000000
|
|
2011-02-09 23:33:37.404376 7f67d1f61700 mds0.bal mds0 epoch 153 load mdsload<[0,19.0133 38.0267]/[0,5.16922 10.3384], req 0, hr 0, qlen 2122, cpu 1.07>
|
|
2011-02-09 23:33:37.404416 7f67d1f61700 mds0.snap check_osd_map - version unchanged
|
|
2011-02-09 23:33:37.404495 7f67d3064700 mds0.server handle_client_request client_request(client4105:464543 lookup #1000001ce07/8378)
|
|
2011-02-09 23:33:37.404574 7f67d3064700 mds0.cache request_start request(client4105:464543 cr=0x367ec000)
|
|
2011-02-09 23:33:37.404588 7f67d3064700 mds0.server dispatch_client_request client_request(client4105:464543 lookup #1000001ce07/8378)
|
|
2011-02-09 23:33:37.404600 7f67d3064700 mds0.server rdlock_path_pin_ref request(client4105:464543 cr=0x367ec000) #1000001ce07/8378
|
|
2011-02-09 23:33:37.404612 7f67d3064700 mds0.cache traverse: opening base ino 1000001ce07 snap head
|
|
2011-02-09 23:33:37.404678 7f67d3064700 mds0.server reply_request -2 (No such file or directory) client_request(client4105:464543 lookup #1000001ce07/8378)
|
|
2011-02-09 23:33:37.404692 7f67d3064700 mds0.server apply_allocated_inos 0 / [] / 0
|
|
2011-02-09 23:33:37.404708 7f67d3064700 mds0.server set_trace_dist snaprealm snaprealm(1 seq 1 lc 0 cr 0 cps 1 snaps={} 0xe6b6c0) len=48
|
|
2011-02-09 23:33:37.404737 7f67d3064700 mds0.cache.ino(1000001ce07) encode_inodestat issueing pAsLsXsFsx seq 224999
|
|
2011-02-09 23:33:37.404752 7f67d3064700 mds0.cache.ino(1000001ce07) encode_inodestat caps pAsLsXsFsx seq 224999 mseq 0 xattrv 0 len 0
|
|
2011-02-09 23:33:37.404773 7f67d3064700 -- 10.202.105.222:6800/18701 --> 10.233.55.138:0/2745458521 -- client_reply(???:464543 = -2 No such file or directory) v1 -- ?+0 0x41abe780 con 0x95cc000
|
|
2011-02-09 23:33:37.404814 7f67d3064700 mds0.cache request_finish request(client4105:464543 cr=0x367ec000)
|
|
2011-02-09 23:33:37.404890 7f67d3064700 -- 10.202.105.222:6800/18701 <== mon0 10.135.211.78:6789/0 684 ==== mdsmap(e 12) v1 ==== 530+0+0 (399433963 0 0) 0xe3e400 con 0xe373c0
|
|
2011-02-09 23:33:37.404927 7f67d1f61700 mds0.2 beacon_send up:active seq 648 (currently up:active)
|
|
2011-02-09 23:33:37.404953 7f67d1f61700 -- 10.202.105.222:6800/18701 --> mon0 10.135.211.78:6789/0 -- mdsbeacon(4098/srv-an56n up:active seq 648 v11) v1 -- ?+0 0x2de6280
|
|
2011-02-09 23:33:37.404997 7f67d1f61700 mds0.cache trim max=100000 cur=120594
|
|
2011-02-09 23:33:37.405028 7f67d1f61700 mds0.cache trim_client_leases
|
|
2011-02-09 23:33:37.405652 7f67d1f61700 mds0.cache check_memory_usage total 2146608, rss 2050816, heap 71668, malloc 520900 mmap 0, baseline 70292, buffers 60468, max 1048576, 120584 / 120595 inodes have caps, 120584 caps, 0.999909 caps per inode
|
|
2011-02-09 23:33:37.405670 7f67d1f61700 mds0.server recall_client_state 0.746368, caps per client 100-80000
|
|
2011-02-09 23:33:37.405680 7f67d1f61700 mds0.server session client4105 10.233.55.138:0/2745458521 caps 120584, leases 0
|
|
2011-02-09 23:33:37.405689 7f67d1f61700 mds0.2 send_message_client client4105 10.233.55.138:0/2745458521 client_session(recall_state max_caps 80000 max_leases 0) v1
|
|
2011-02-09 23:33:37.405698 7f67d1f61700 -- 10.202.105.222:6800/18701 --> 10.233.55.138:0/2745458521 -- client_session(recall_state max_caps 80000 max_leases 0) v1 -- ?+0 0x353f58c0 con 0x95cc000
|
|
2011-02-09 23:33:37.405746 7f67d1f61700 mds0.log trim 31 / 30 segments, 66678 / -1 events, 1 (2420) expiring, 0 (0) expired
|
|
2011-02-09 23:33:37.405859 7f67d1f61700 mds0.locker scatter_tick
|
|
2011-02-09 23:33:37.405870 7f67d1f61700 mds0.server find_idle_sessions. laggy until 0.000000
|
|
2011-02-09 23:33:37.405877 7f67d1f61700 mds0.snap check_osd_map - version unchanged
|
|
2011-02-09 23:33:37.405885 7f67d1f61700 mds0.2 beacon_kill last_acked_stamp 2011-02-09 23:33:18.354678, setting laggy flag.
|
|
2011-02-09 23:33:37.405912 7f67d3064700 mds0.2 handle_mds_map epoch 12 from mon0
|
|
2011-02-09 23:33:37.405943 7f67d3064700 mds0.2 my compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate objec}
|
|
2011-02-09 23:33:37.405951 7f67d3064700 mds0.2 mdsmap compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate objec}
|
|
2011-02-09 23:33:37.405958 7f67d3064700 mds-1.2 map says i am 10.202.105.222:6800/18701 mds-1 state down:dne
|
|
2011-02-09 23:33:37.405967 7f67d3064700 mds-1.2 handle_mds_map i (10.202.105.222:6800/18701) dne in the mdsmap, respawning myself
|
|
2011-02-09 23:33:37.405973 7f67d3064700 mds-1.2 respawn
|
|
2011-02-09 23:33:37.405978 7f67d3064700 mds-1.2 e: '/usr/bin/cmds'
|
|
2011-02-09 23:33:37.405982 7f67d3064700 mds-1.2 0: '/usr/bin/cmds'
|
|
2011-02-09 23:33:37.405987 7f67d3064700 mds-1.2 1: '-i'
|
|
2011-02-09 23:33:37.405992 7f67d3064700 mds-1.2 2: 'srv-an56n'
|
|
2011-02-09 23:33:37.405996 7f67d3064700 mds-1.2 3: '-c'
|
|
2011-02-09 23:33:37.406001 7f67d3064700 mds-1.2 4: '/etc/ceph/ceph.conf'
|
|
2011-02-09 23:33:37.406027 7f67d3064700 mds-1.2 cwd /
|
|
2011-02-09 23:33:37.554837 --- 18702 opened log /var/log/ceph/mds.srv-an56n.log ---
|
|
ceph version 0.24.2 (commit:)
|
|
2011-02-09 23:33:37.580722 7f0221987700 mds-1.0 ms_handle_connect on 10.135.211.78:6789/0
|
|
2011-02-09 23:33:41.612458 7f0221987700 mds-1.0 handle_mds_map standby
|
|
2011-02-09 23:33:43.049802 7f0221987700 mds-1.0 handle_mds_map standby
|
|
2011-02-09 23:38:07.379780 7f0221987700 mds0.4 handle_mds_map i am now mds0.4
|
|
2011-02-09 23:38:07.379821 7f0221987700 mds0.4 handle_mds_map state change up:standby --> up:replay
|
|
2011-02-09 23:38:07.379837 7f0221987700 mds0.4 replay_start
|
|
2011-02-09 23:38:07.379853 7f0221987700 mds0.4 recovery set is
|
|
2011-02-09 23:38:07.379863 7f0221987700 mds0.4 need osdmap epoch 15, have 14
|
|
2011-02-09 23:38:07.379933 7f0221987700 mds0.cache handle_mds_failure mds0 : recovery peers are
|
|
2011-02-09 23:38:07.387147 7f0221987700 mds0.4 ms_handle_connect on 10.202.105.222:6801/18768
|
|
2011-02-09 23:38:07.388163 7f0221987700 mds0.4 ms_handle_connect on 10.135.211.78:6801/19484
|
|
2011-02-09 23:38:07.388185 7f0221987700 mds0.4 ms_handle_connect on 10.67.65.62:6800/9578
|
|
2011-02-09 23:38:07.388947 7f0221987700 mds0.4 ms_handle_connect on 10.61.136.222:6800/17530
|
|
2011-02-09 23:38:07.554797 7f0221987700 mds0.cache creating system inode with ino:1
|
|
2011-02-09 23:38:08.948135 7f021f07a700 mds0.cache creating system inode with ino:100
|
|
2011-02-09 23:38:11.686505 7f021f07a700 mds0.4 replay_done in=1 failed=0
|
|
2011-02-09 23:38:11.692893 7f0221987700 mds0.4 handle_mds_map state change up:replay --> up:reconnect
|
|
2011-02-09 23:38:11.692920 7f0221987700 mds0.4 reconnect_start
|
|
2011-02-09 23:38:11.692966 7f0221987700 mds0.server reconnect_clients -- 1 sessions
|
|
2011-02-09 23:38:11.791597 7f021e879700 -- 10.202.105.222:6804/18702 >> 10.233.55.138:0/2745458521 pipe(0x4e1f000 sd=26 pgs=0 cs=0 l=0).accept peer addr is really 10.233.55.138:0/2745458521 (socket is 10.233.55.138:47718/0)
|
|
2011-02-09 23:38:12.000058 7f0221987700 log [DBG] : reconnect by client4105 10.233.55.138:0/2745458521 after 0.307026
|
|
2011-02-09 23:38:12.231060 7f0221987700 mds0.4 reconnect_done
|
|
2011-02-09 23:38:12.247722 7f0221987700 mds0.4 handle_mds_map state change up:reconnect --> up:rejoin
|
|
2011-02-09 23:38:12.247777 7f0221987700 mds0.4 rejoin_joint_start
|
|
2011-02-09 23:38:12.722051 7f0221987700 mds0.4 rejoin_done
|
|
2011-02-09 23:38:12.786187 7f0221987700 mds0.4 handle_mds_map state change up:rejoin --> up:active
|
|
2011-02-09 23:38:12.786225 7f0221987700 mds0.4 recovery_done -- successful recovery!
|
|
2011-02-09 23:38:13.075128 7f0221987700 mds0.4 active_start
|
|
2011-02-09 23:38:13.083212 7f0221987700 mds0.4 cluster recovered.
|