We are experiencing client connection problems that occur only after
some period of heavy use. Prior to the 'connection refused' error in the
client log the cluster behaves as normal. Restarting Ceph solves the
problem but we are not able to finish long jobs.
Logs attached. I have the full 1 GB MDS log if needed, and included only
the portition of the log in which the client had problems plus about 5
seconds of context on either side of the test.
Thanks,
Noah
Client
====
...
2011-12-04 16:07:58.154523 7f4458314700 -- 192.168.141.123:0/1009375 >>
192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0
l=0).connect 0
2011-12-04 16:07:58.154562 7f4458314700 -- 192.168.141.123:0/1009375 >>
192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0
l=0).connecting to 192.168.141.123:6800/1325
2011-12-04 16:07:58.154605 7f4458314700 -- 192.168.141.123:0/1009375 >>
192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0
l=0).connect error 192.168.141.123:6800/1325, 111: Connection refused
2011-12-04 16:07:58.154620 7f4458314700 -- 192.168.141.123:0/1009375 >>
192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0
l=0).fault 111: Connection refused
2011-12-04 16:07:58.154635 7f4458314700 -- 192.168.141.123:0/1009375 >>
192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0
l=0).fault waiting 3.200000
Full logs attached.
2011-12-04 16:07:55.149410 7f44a328a700 -- :/0 register_entity client.?
2011-12-04 16:07:55.149459 7f44a328a700 -- :/0 register_entity client.? at :/0
2011-12-04 16:07:55.149554 7f44a328a700 -- :/0 messenger.start
2011-12-04 16:07:55.149632 7f44537fe700 -- :/1009375 reaper_entry start
2011-12-04 16:07:55.149686 7f44a328a700 -- :/1009375 ready :/1009375
2011-12-04 16:07:55.149717 7f44537fe700 -- :/1009375 reaper
2011-12-04 16:07:55.149736 7f44537fe700 -- :/1009375 reaper done
2011-12-04 16:07:55.149963 7f44a328a700 -- :/1009375 connect_rank to 192.168.141.123:6789/0, creating pipe and registering
2011-12-04 16:07:55.150048 7f44a328a700 -- :/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=-1 pgs=0 cs=0 l=0).register_pipe
2011-12-04 16:07:55.150100 7f4458516700 -- :/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=-1 pgs=0 cs=0 l=0).writer: state = 1 policy.server=0
2011-12-04 16:07:55.150134 7f44a328a700 -- :/1009375 --> 192.168.141.123:6789/0 -- auth(proto 0 30 bytes) v1 -- ?+0 0x7f445437d020 con 0x7f445437ccc0
2011-12-04 16:07:55.150168 7f4458516700 -- :/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=-1 pgs=0 cs=0 l=0).connect 0
2011-12-04 16:07:55.150195 7f44a328a700 -- :/1009375 submit_message auth(proto 0 30 bytes) v1 remote 192.168.141.123:6789/0
2011-12-04 16:07:55.150225 7f4458516700 -- :/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=0 cs=0 l=0).connecting to 192.168.141.123:6789/0
2011-12-04 16:07:55.150530 7f4458516700 -- :/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=0 cs=0 l=0).connect read peer addr 192.168.141.123:6789/0 on socket 54
2011-12-04 16:07:55.150549 7f4458516700 -- :/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=0 cs=0 l=0).connect peer addr for me is 192.168.141.123:36578/0
2011-12-04 16:07:55.150563 7f4458516700 -- 192.168.141.123:0/1009375 learned my addr 192.168.141.123:0/1009375
2011-12-04 16:07:55.150608 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=0 cs=0 l=0).connect sent my addr 192.168.141.123:0/1009375
2011-12-04 16:07:55.150627 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=0 cs=0 l=0).connect sending gseq=1 cseq=0 proto=15
2011-12-04 16:07:55.150661 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=0 cs=0 l=0).connect wrote (self +) cseq, waiting for reply
2011-12-04 16:07:55.150697 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=0 cs=0 l=0).connect got reply tag 1 connect_seq 1 global_seq 1203 proto 15 flags 1
2011-12-04 16:07:55.150717 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).connect success 1, lossy = 1, features 4090
2011-12-04 16:07:55.150737 7f4458516700 -- 192.168.141.123:0/1009375 >> :/0 pipe(0x7f44542d4bf0 sd=-1 pgs=0 cs=0 l=0).queue_received queuing pipe
2011-12-04 16:07:55.150773 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).connect starting reader
2011-12-04 16:07:55.150820 7f4451ffb700 -- 192.168.141.123:0/1009375 dispatch_entry pipe 0x7f44542d4bf0 dequeued 0
2011-12-04 16:07:55.150890 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.150924 7f4451ffb700 client.-1 ms_handle_connect on 192.168.141.123:6789/0
2011-12-04 16:07:55.150953 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer encoding 1 0x7f445437d020 auth(proto 0 30 bytes) v1
2011-12-04 16:07:55.150991 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader reading tag...
2011-12-04 16:07:55.151022 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer sending 1 0x7f445437d020
2011-12-04 16:07:55.151042 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).write_message 0x7f445437d020
2011-12-04 16:07:55.151094 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.151109 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer sleeping
2011-12-04 16:07:55.151334 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got ACK
2011-12-04 16:07:55.151367 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader reading tag...
2011-12-04 16:07:55.151388 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got MSG
2011-12-04 16:07:55.151423 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got envelope type=18 src mon.0 front=24 data=0 off 0
2011-12-04 16:07:55.151439 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader wants 24 from dispatch throttler 0/104857600
2011-12-04 16:07:55.151467 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got front 24
2011-12-04 16:07:55.151489 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).aborted = 0
2011-12-04 16:07:55.151504 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got 24 + 0 + 0 byte message
2011-12-04 16:07:55.151590 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got message 1 0x422fbc50 auth_reply(proto 1 0 Success) v1
2011-12-04 16:07:55.151618 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).queue_received queuing pipe
2011-12-04 16:07:55.151653 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader reading tag...
2011-12-04 16:07:55.151684 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.151710 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).write_ack 1
2011-12-04 16:07:55.151732 7f4451ffb700 -- 192.168.141.123:0/1009375 dispatch_entry pipe 0x7f445437ca50 dequeued 0x422fbc50
2011-12-04 16:07:55.151758 7f4451ffb700 -- 192.168.141.123:0/1009375 <== mon.0 192.168.141.123:6789/0 1 ==== auth_reply(proto 1 0 Success) v1 ==== 24+0+0 (1949490694 0 0) 0x422fbc50 con 0x7f445437ccc0
2011-12-04 16:07:55.151782 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.151800 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer sleeping
2011-12-04 16:07:55.151846 7f4451ffb700 -- 192.168.141.123:0/1009375 --> 192.168.141.123:6789/0 -- mon_subscribe({mdsmap=0+,monmap=0+,osdmap=0}) v1 -- ?+0 0x7f445437d230 con 0x7f445437ccc0
2011-12-04 16:07:55.151865 7f4451ffb700 -- 192.168.141.123:0/1009375 submit_message mon_subscribe({mdsmap=0+,monmap=0+,osdmap=0}) v1 remote 192.168.141.123:6789/0
2011-12-04 16:07:55.151889 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.151916 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer encoding 2 0x7f445437d230 mon_subscribe({mdsmap=0+,monmap=0+,osdmap=0}) v1
2011-12-04 16:07:55.151948 7f4451ffb700 -- 192.168.141.123:0/1009375 dispatch_throttle_release 24 to dispatch throttler 24/104857600
2011-12-04 16:07:55.151971 7f4451ffb700 -- 192.168.141.123:0/1009375 done calling dispatch on 0x422fbc50
2011-12-04 16:07:55.151997 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer sending 2 0x7f445437d230
2011-12-04 16:07:55.152018 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).write_message 0x7f445437d230
2011-12-04 16:07:55.152041 7f44a328a700 client.6697 mounted: have osdmap 0 and mdsmap 0
2011-12-04 16:07:55.152088 7f44a328a700 client.6697 mds is 0
2011-12-04 16:07:55.152098 7f44a328a700 client.6697 target mds.0 not active, waiting for new mdsmap
2011-12-04 16:07:55.152151 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.152168 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer sleeping
2011-12-04 16:07:55.152262 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got ACK
2011-12-04 16:07:55.152288 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader reading tag...
2011-12-04 16:07:55.152306 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got MSG
2011-12-04 16:07:55.152327 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got envelope type=21 src mon.0 front=535 data=0 off 0
2011-12-04 16:07:55.152341 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader wants 535 from dispatch throttler 0/104857600
2011-12-04 16:07:55.152363 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got front 535
2011-12-04 16:07:55.152383 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).aborted = 0
2011-12-04 16:07:55.152396 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got 535 + 0 + 0 byte message
2011-12-04 16:07:55.152432 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got message 2 0x422fbc50 mdsmap(e 14) v1
2011-12-04 16:07:55.152453 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).queue_received queuing pipe
2011-12-04 16:07:55.152483 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader reading tag...
2011-12-04 16:07:55.152509 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.152533 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).write_ack 2
2011-12-04 16:07:55.152551 7f4451ffb700 -- 192.168.141.123:0/1009375 dispatch_entry pipe 0x7f445437ca50 dequeued 0x422fbc50
2011-12-04 16:07:55.152579 7f4451ffb700 -- 192.168.141.123:0/1009375 <== mon.0 192.168.141.123:6789/0 2 ==== mdsmap(e 14) v1 ==== 535+0+0 (3446747908 0 0) 0x422fbc50 con 0x7f445437ccc0
2011-12-04 16:07:55.152605 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.152626 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer sleeping
2011-12-04 16:07:55.152648 7f4451ffb700 client.6697 handle_mds_map epoch 14
2011-12-04 16:07:55.152678 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got MSG
2011-12-04 16:07:55.152726 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got envelope type=4 src mon.0 front=187 data=0 off 0
2011-12-04 16:07:55.152742 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader wants 187 from dispatch throttler 535/104857600
2011-12-04 16:07:55.152757 7f4451ffb700 -- 192.168.141.123:0/1009375 dispatch_throttle_release 535 to dispatch throttler 722/104857600
2011-12-04 16:07:55.152776 7f4451ffb700 -- 192.168.141.123:0/1009375 done calling dispatch on 0x422fbc50
2011-12-04 16:07:55.152796 7f44a328a700 client.6697 mds is 0
2011-12-04 16:07:55.152817 7f44a328a700 client.6697 opening session to mds.0
2011-12-04 16:07:55.152843 7f44a328a700 -- 192.168.141.123:0/1009375 --> mds.0 192.168.141.123:6800/1325 -- client_session(request_open) v1 -- ?+0 0x7f44544cd800
2011-12-04 16:07:55.152867 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got front 187
2011-12-04 16:07:55.152897 7f44a328a700 -- 192.168.141.123:0/1009375 submit_message client_session(request_open) v1 remote, 192.168.141.123:6800/1325, new pipe.
2011-12-04 16:07:55.152916 7f44a328a700 -- 192.168.141.123:0/1009375 connect_rank to 192.168.141.123:6800/1325, creating pipe and registering
2011-12-04 16:07:55.152940 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).aborted = 0
2011-12-04 16:07:55.152960 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got 187 + 0 + 0 byte message
2011-12-04 16:07:55.152979 7f44a328a700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=-1 pgs=0 cs=0 l=0).register_pipe
2011-12-04 16:07:55.153018 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=-1 pgs=0 cs=0 l=0).writer: state = 1 policy.server=0
2011-12-04 16:07:55.153051 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=-1 pgs=0 cs=0 l=0).connect 0
2011-12-04 16:07:55.153079 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got message 3 0x422fbc50 mon_map v1
2011-12-04 16:07:55.153109 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).queue_received queuing pipe
2011-12-04 16:07:55.153128 7f44a328a700 client.6697 waiting for session to mds.0 to open
2011-12-04 16:07:55.153162 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connecting to 192.168.141.123:6800/1325
2011-12-04 16:07:55.153189 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader reading tag...
2011-12-04 16:07:55.153225 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connect error 192.168.141.123:6800/1325, 111: Connection refused
2011-12-04 16:07:55.153253 7f4451ffb700 -- 192.168.141.123:0/1009375 dispatch_entry pipe 0x7f445437ca50 dequeued 0x422fbc50
2011-12-04 16:07:55.153281 7f4451ffb700 -- 192.168.141.123:0/1009375 <== mon.0 192.168.141.123:6789/0 3 ==== mon_map v1 ==== 187+0+0 (1658340354 0 0) 0x422fbc50 con 0x7f445437ccc0
2011-12-04 16:07:55.153307 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault 111: Connection refused
2011-12-04 16:07:55.153324 7f4451ffb700 -- 192.168.141.123:0/1009375 dispatch_throttle_release 187 to dispatch throttler 187/104857600
2011-12-04 16:07:55.153342 7f4451ffb700 -- 192.168.141.123:0/1009375 done calling dispatch on 0x422fbc50
2011-12-04 16:07:55.153366 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got MSG
2011-12-04 16:07:55.153406 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got envelope type=41 src mon.0 front=6900 data=0 off 0
2011-12-04 16:07:55.153425 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader wants 6900 from dispatch throttler 0/104857600
2011-12-04 16:07:55.153452 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault first fault
2011-12-04 16:07:55.153474 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).writer: state = 1 policy.server=0
2011-12-04 16:07:55.153491 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connect 0
2011-12-04 16:07:55.153515 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.153536 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).write_ack 3
2011-12-04 16:07:55.153558 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.153575 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer sleeping
2011-12-04 16:07:55.153599 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connecting to 192.168.141.123:6800/1325
2011-12-04 16:07:55.153627 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got front 6900
2011-12-04 16:07:55.153647 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connect error 192.168.141.123:6800/1325, 111: Connection refused
2011-12-04 16:07:55.153669 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault 111: Connection refused
2011-12-04 16:07:55.153695 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault waiting 0.200000
2011-12-04 16:07:55.153721 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).aborted = 0
2011-12-04 16:07:55.153738 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got 6900 + 0 + 0 byte message
2011-12-04 16:07:55.153794 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got message 4 0x4227d030 osd_map(48..48 src has 1..48) v2
2011-12-04 16:07:55.153815 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).queue_received queuing pipe
2011-12-04 16:07:55.153838 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader reading tag...
2011-12-04 16:07:55.153864 7f4451ffb700 -- 192.168.141.123:0/1009375 dispatch_entry pipe 0x7f445437ca50 dequeued 0x4227d030
2011-12-04 16:07:55.153891 7f4451ffb700 -- 192.168.141.123:0/1009375 <== mon.0 192.168.141.123:6789/0 4 ==== osd_map(48..48 src has 1..48) v2 ==== 6900+0+0 (1758851646 0 0) 0x4227d030 con 0x7f445437ccc0
2011-12-04 16:07:55.153915 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got MSG
2011-12-04 16:07:55.153945 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.153969 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).write_ack 4
2011-12-04 16:07:55.154011 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got envelope type=16 src mon.0 front=20 data=0 off 0
2011-12-04 16:07:55.154033 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader wants 20 from dispatch throttler 6900/104857600
2011-12-04 16:07:55.154057 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.154078 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer sleeping
2011-12-04 16:07:55.154102 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got front 20
2011-12-04 16:07:55.154126 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).aborted = 0
2011-12-04 16:07:55.154144 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got 20 + 0 + 0 byte message
2011-12-04 16:07:55.154167 7f4451ffb700 -- 192.168.141.123:0/1009375 dispatch_throttle_release 6900 to dispatch throttler 6920/104857600
2011-12-04 16:07:55.154187 7f4451ffb700 -- 192.168.141.123:0/1009375 done calling dispatch on 0x4227d030
2011-12-04 16:07:55.154212 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader got message 5 0x7f44543e82c0 mon_subscribe_ack(300s) v1
2011-12-04 16:07:55.154236 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).queue_received queuing pipe
2011-12-04 16:07:55.154260 7f4458415700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).reader reading tag...
2011-12-04 16:07:55.154283 7f4451ffb700 -- 192.168.141.123:0/1009375 dispatch_entry pipe 0x7f445437ca50 dequeued 0x7f44543e82c0
2011-12-04 16:07:55.154306 7f4451ffb700 -- 192.168.141.123:0/1009375 <== mon.0 192.168.141.123:6789/0 5 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (1384836696 0 0) 0x7f44543e82c0 con 0x7f445437ccc0
2011-12-04 16:07:55.154329 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.154349 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).write_ack 5
2011-12-04 16:07:55.154368 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:55.154385 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer sleeping
2011-12-04 16:07:55.154406 7f4451ffb700 -- 192.168.141.123:0/1009375 dispatch_throttle_release 20 to dispatch throttler 20/104857600
2011-12-04 16:07:55.154419 7f4451ffb700 -- 192.168.141.123:0/1009375 done calling dispatch on 0x7f44543e82c0
2011-12-04 16:07:55.353786 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault done waiting or woke up
2011-12-04 16:07:55.353808 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).writer: state = 1 policy.server=0
2011-12-04 16:07:55.353821 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connect 0
2011-12-04 16:07:55.353847 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connecting to 192.168.141.123:6800/1325
2011-12-04 16:07:55.353891 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connect error 192.168.141.123:6800/1325, 111: Connection refused
2011-12-04 16:07:55.353916 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault 111: Connection refused
2011-12-04 16:07:55.353931 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault waiting 0.400000
2011-12-04 16:07:55.754011 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault done waiting or woke up
2011-12-04 16:07:55.754032 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).writer: state = 1 policy.server=0
2011-12-04 16:07:55.754045 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connect 0
2011-12-04 16:07:55.754070 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connecting to 192.168.141.123:6800/1325
2011-12-04 16:07:55.754109 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connect error 192.168.141.123:6800/1325, 111: Connection refused
2011-12-04 16:07:55.754125 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault 111: Connection refused
2011-12-04 16:07:55.754139 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault waiting 0.800000
2011-12-04 16:07:56.152068 7f4452ffd700 client.6697 renew_caps()
2011-12-04 16:07:56.554233 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault done waiting or woke up
2011-12-04 16:07:56.554268 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).writer: state = 1 policy.server=0
2011-12-04 16:07:56.554281 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connect 0
2011-12-04 16:07:56.554320 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connecting to 192.168.141.123:6800/1325
2011-12-04 16:07:56.554381 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connect error 192.168.141.123:6800/1325, 111: Connection refused
2011-12-04 16:07:56.554398 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault 111: Connection refused
2011-12-04 16:07:56.554413 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault waiting 1.600000
2011-12-04 16:07:58.149960 7f44517fa700 -- 192.168.141.123:0/1009375 send_keepalive con 0x7f445437ccc0, have pipe.
2011-12-04 16:07:58.150013 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:58.150051 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).write_keepalive
2011-12-04 16:07:58.150098 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer: state = 2 policy.server=0
2011-12-04 16:07:58.150113 7f4458516700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6789/0 pipe(0x7f445437ca50 sd=54 pgs=1203 cs=1 l=1).writer sleeping
2011-12-04 16:07:58.154492 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault done waiting or woke up
2011-12-04 16:07:58.154510 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).writer: state = 1 policy.server=0
2011-12-04 16:07:58.154523 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connect 0
2011-12-04 16:07:58.154562 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connecting to 192.168.141.123:6800/1325
2011-12-04 16:07:58.154605 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).connect error 192.168.141.123:6800/1325, 111: Connection refused
2011-12-04 16:07:58.154620 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault 111: Connection refused
2011-12-04 16:07:58.154635 7f4458314700 -- 192.168.141.123:0/1009375 >> 192.168.141.123:6800/1325 pipe(0x7f445437d020 sd=55 pgs=0 cs=0 l=0).fault waiting 3.200000
2011-12-04 16:13:15.385981 7f1403bc5700 mds.0.locker scatter_tick
2011-12-04 16:13:15.385996 7f1403bc5700 mds.0.server find_idle_sessions. laggy until 0.000000
2011-12-04 16:13:15.386014 7f1403bc5700 mds.0.bal tick last_sample now 2011-12-04 16:13:15.386009
2011-12-04 16:13:15.386058 7f1403bc5700 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.01>
2011-12-04 16:13:15.386095 7f1403bc5700 mds.0.bal mds.0 epoch 1645 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.01>
2011-12-04 16:13:15.386109 7f1403bc5700 mds.0.snap check_osd_map - version unchanged
2011-12-04 16:13:16.645132 7f1403bc5700 mds.0.3 beacon_send up:active seq 4130 (currently up:active)
2011-12-04 16:13:16.645175 7f1403bc5700 -- 192.168.141.123:6800/1325 --> 192.168.141.123:6789/0 -- mdsbeacon(5497/a up:active seq 4130 v14) v1 -- ?+0 0x28ff500 con 0x1b518c0
2011-12-04 16:13:16.645529 7f1405ac9700 -- 192.168.141.123:6800/1325 <== mon.0 192.168.141.123:6789/0 4260 ==== mdsbeacon(5497/a up:active seq 4130 v14) v2 ==== 103+0+0 (1047759573 0 0) 0x20f4500 con 0x1b518c0
2011-12-04 16:13:16.645567 7f1405ac9700 mds.0.3 handle_mds_beacon up:active seq 4130 rtt 0.000413
2011-12-04 16:13:20.376569 7f1403bc5700 mds.0.cache trim max=100000 cur=2220
2011-12-04 16:13:20.376602 7f1403bc5700 mds.0.cache trim_client_leases
2011-12-04 16:13:20.385490 7f1403bc5700 mds.0.cache check_memory_usage total 2247420, rss 60632, heap -2019376, malloc 15008 mmap 0, baseline 115192, buffers 0, max 1048576, 0 / 488 inodes have caps, 0 caps, 0 caps per inode
2011-12-04 16:13:20.386041 7f1403bc5700 mds.0.log trim 8 / 30 segments, 12919 / -1 events, 0 (0) expiring, 0 (0) expired
2011-12-04 16:13:20.386080 7f1403bc5700 mds.0.log _trim_expired_segments waiting for 4194304 to expire
2011-12-04 16:13:20.386190 7f1403bc5700 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.01>
2011-12-04 16:13:20.386222 7f1403bc5700 mds.0.locker scatter_tick
2011-12-04 16:13:20.386244 7f1403bc5700 mds.0.server find_idle_sessions. laggy until 0.000000
2011-12-04 16:13:20.386265 7f1403bc5700 mds.0.bal tick last_sample now 2011-12-04 16:13:20.386259
2011-12-04 16:13:20.386280 7f1403bc5700 mds.0.snap check_osd_map - version unchanged
2011-12-04 16:13:20.645259 7f1403bc5700 mds.0.3 beacon_send up:active seq 4131 (currently up:active)
2011-12-04 16:13:20.645307 7f1403bc5700 -- 192.168.141.123:6800/1325 --> 192.168.141.123:6789/0 -- mdsbeacon(5497/a up:active seq 4131 v14) v1 -- ?+0 0x279a780 con 0x1b518c0
2011-12-04 16:13:20.645617 7f1405ac9700 -- 192.168.141.123:6800/1325 <== mon.0 192.168.141.123:6789/0 4261 ==== mdsbeacon(5497/a up:active seq 4131 v14) v2 ==== 103+0+0 (1197143986 0 0) 0x20f4780 con 0x1b518c0
2011-12-04 16:13:20.645646 7f1405ac9700 mds.0.3 handle_mds_beacon up:active seq 4131 rtt 0.000363
2011-12-04 16:13:24.645420 7f1403bc5700 mds.0.3 beacon_send up:active seq 4132 (currently up:active)
2011-12-04 16:13:24.645485 7f1403bc5700 -- 192.168.141.123:6800/1325 --> 192.168.141.123:6789/0 -- mdsbeacon(5497/a up:active seq 4132 v14) v1 -- ?+0 0x279aa00 con 0x1b518c0
2011-12-04 16:13:24.645900 7f1405ac9700 -- 192.168.141.123:6800/1325 <== mon.0 192.168.141.123:6789/0 4262 ==== mdsbeacon(5497/a up:active seq 4132 v14) v2 ==== 103+0+0 (761852790 0 0) 0x2928280 con 0x1b518c0
2011-12-04 16:13:24.645960 7f1405ac9700 mds.0.3 handle_mds_beacon up:active seq 4132 rtt 0.000496
2011-12-04 16:13:25.376640 7f1403bc5700 mds.0.cache trim max=100000 cur=2220
2011-12-04 16:13:25.376668 7f1403bc5700 mds.0.cache trim_client_leases
2011-12-04 16:13:25.385983 7f1403bc5700 mds.0.cache check_memory_usage total 2247420, rss 60632, heap -2019376, malloc 15008 mmap 0, baseline 115192, buffers 0, max 1048576, 0 / 488 inodes have caps, 0 caps, 0 caps per inode
2011-12-04 16:13:25.386029 7f1403bc5700 mds.0.log trim 8 / 30 segments, 12919 / -1 events, 0 (0) expiring, 0 (0) expired
2011-12-04 16:13:25.386047 7f1403bc5700 mds.0.log _trim_expired_segments waiting for 4194304 to expire
2011-12-04 16:13:25.386124 7f1403bc5700 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.25>
2011-12-04 16:13:25.386156 7f1403bc5700 mds.0.locker scatter_tick
2011-12-04 16:13:25.386180 7f1403bc5700 mds.0.server find_idle_sessions. laggy until 0.000000
2011-12-04 16:13:25.386205 7f1403bc5700 mds.0.bal tick last_sample now 2011-12-04 16:13:25.386199
2011-12-04 16:13:25.386257 7f1403bc5700 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.25>
2011-12-04 16:13:25.386300 7f1403bc5700 mds.0.bal mds.0 epoch 1646 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.25>
2011-12-04 16:13:25.386321 7f1403bc5700 mds.0.snap check_osd_map - version unchanged
2011-12-04 16:13:28.645586 7f1403bc5700 mds.0.3 beacon_send up:active seq 4133 (currently up:active)
2011-12-04 16:13:28.645642 7f1403bc5700 -- 192.168.141.123:6800/1325 --> 192.168.141.123:6789/0 -- mdsbeacon(5497/a up:active seq 4133 v14) v1 -- ?+0 0x279ac80 con 0x1b518c0
2011-12-04 16:13:28.646032 7f1405ac9700 -- 192.168.141.123:6800/1325 <== mon.0 192.168.141.123:6789/0 4263 ==== mdsbeacon(5497/a up:active seq 4133 v14) v2 ==== 103+0+0 (1413582353 0 0) 0x2928a00 con 0x1b518c0
2011-12-04 16:13:28.646077 7f1405ac9700 mds.0.3 handle_mds_beacon up:active seq 4133 rtt 0.000458
2011-12-04 16:13:30.376715 7f1403bc5700 mds.0.cache trim max=100000 cur=2220
2011-12-04 16:13:30.376743 7f1403bc5700 mds.0.cache trim_client_leases
2011-12-04 16:13:30.385607 7f1403bc5700 mds.0.cache check_memory_usage total 2247420, rss 60632, heap -2019376, malloc 15008 mmap 0, baseline 115192, buffers 0, max 1048576, 0 / 488 inodes have caps, 0 caps, 0 caps per inode
2011-12-04 16:13:30.386317 7f1403bc5700 mds.0.log trim 8 / 30 segments, 12919 / -1 events, 0 (0) expiring, 0 (0) expired
2011-12-04 16:13:30.386358 7f1403bc5700 mds.0.log _trim_expired_segments waiting for 4194304 to expire
2011-12-04 16:13:30.386432 7f1403bc5700 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.23>
2011-12-04 16:13:30.386463 7f1403bc5700 mds.0.locker scatter_tick
2011-12-04 16:13:30.386485 7f1403bc5700 mds.0.server find_idle_sessions. laggy until 0.000000
2011-12-04 16:13:30.386505 7f1403bc5700 mds.0.bal tick last_sample now 2011-12-04 16:13:30.386500
2011-12-04 16:13:30.386521 7f1403bc5700 mds.0.snap check_osd_map - version unchanged
2011-12-04 16:13:32.645749 7f1403bc5700 mds.0.3 beacon_send up:active seq 4134 (currently up:active)
2011-12-04 16:13:32.645810 7f1403bc5700 -- 192.168.141.123:6800/1325 --> 192.168.141.123:6789/0 -- mdsbeacon(5497/a up:active seq 4134 v14) v1 -- ?+0 0x2826780 con 0x1b518c0
2011-12-04 16:13:32.646164 7f1405ac9700 -- 192.168.141.123:6800/1325 <== mon.0 192.168.141.123:6789/0 4264 ==== mdsbeacon(5497/a up:active seq 4134 v14) v2 ==== 103+0+0 (3745122744 0 0) 0x2928c80 con 0x1b518c0
2011-12-04 16:13:32.646221 7f1405ac9700 mds.0.3 handle_mds_beacon up:active seq 4134 rtt 0.000434
