Skip to content

Instantly share code, notes, and snippets.

/gist:346e7dd8c63cb3359ae8 Secret

Created June 2, 2011 22:30
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save anonymous/346e7dd8c63cb3359ae8 to your computer and use it in GitHub Desktop.
Save anonymous/346e7dd8c63cb3359ae8 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
gistfile1.txt
2011-06-03 07:29:18.031301 7fb493b3e760 ceph version 0.28.2-3-geaa0938.commit: eaa09386010f18ea840929a466d2b755b7b20fff. process: cosd. pid: 20872
2011-06-03 07:29:18.031482 7fb493b3e760 -- 0.0.0.0:6801/20872 accepter.bind ms_addr is 0.0.0.0:6801/20872 need_addr=1
2011-06-03 07:29:18.031502 7fb493b3e760 -- 0.0.0.0:6802/20872 accepter.bind ms_addr is 0.0.0.0:6802/20872 need_addr=1
2011-06-03 07:29:18.031518 7fb493b3e760 -- 0.0.0.0:6803/20872 accepter.bind ms_addr is 0.0.0.0:6803/20872 need_addr=1
2011-06-03 07:29:18.031632 7fb493b3e760 filestore(/data/osd0) test_mount basedir /data/osd0 journal /data/osd0/journal
2011-06-03 07:29:18.032067 7fb493b3e760 -- 0.0.0.0:6801/20872 messenger.start
2011-06-03 07:29:18.032105 7fb493b3e760 -- 0.0.0.0:6801/20872 accepter.start
2011-06-03 07:29:18.032215 7fb493b3e760 -- 0.0.0.0:6803/20872 messenger.start
2011-06-03 07:29:18.032225 7fb493b3e760 -- 0.0.0.0:6803/20872 accepter.start
2011-06-03 07:29:18.032267 7fb493b3e760 -- 0.0.0.0:6802/20872 messenger.start
2011-06-03 07:29:18.032279 7fb493b3e760 -- 0.0.0.0:6802/20872 accepter.start
2011-06-03 07:29:18.032371 7fb493b3e760 osd0 0 mounting /data/osd0 /data/osd0/journal
2011-06-03 07:29:18.032392 7fb493b3e760 filestore(/data/osd0) basedir /data/osd0 journal /data/osd0/journal
2011-06-03 07:29:18.032455 7fb493b3e760 filestore(/data/osd0) mount FIEMAP ioctl is NOT supported
2011-06-03 07:29:18.032466 7fb493b3e760 filestore(/data/osd0) mount did NOT detect btrfs
2011-06-03 07:29:18.032479 7fb493b3e760 filestore(/data/osd0) mount fsid is 1739958715
2011-06-03 07:29:18.032522 7fb493b3e760 filestore(/data/osd0) mount found snaps <>
2011-06-03 07:29:18.032542 7fb493b3e760 filestore(/data/osd0) mount op_seq is 555723
2011-06-03 07:29:18.032553 7fb493b3e760 filestore(/data/osd0) open_journal at /data/osd0/journal
2011-06-03 07:29:18.032569 7fb493b3e760 filestore(/data/osd0) mount: WRITEAHEAD journal mode explicitly enabled in conf
2011-06-03 07:29:18.032579 7fb493b3e760 filestore(/data/osd0) mount WARNING: not btrfs or ext3; data may be lost
2011-06-03 07:29:18.032615 7fb493b3e760 journal journal_replay fs op_seq 555723
2011-06-03 07:29:18.032625 7fb493b3e760 journal open /data/osd0/journal next_seq 555724
2011-06-03 07:29:18.032635 7fb493b3e760 journal _open journal is not a block device, NOT checking disk write cache on '/data/osd0/journal'
2011-06-03 07:29:18.032649 7fb493b3e760 journal _open /data/osd0/journal fd 11: 1048576000 bytes, block size 4096 bytes, directio = 1
2011-06-03 07:29:18.032653 7fb493b3e760 journal read_header
2011-06-03 07:29:18.062714 7fb493b3e760 journal header: block_size 4096 alignment 4096 max_size 1048576000
2011-06-03 07:29:18.062734 7fb493b3e760 journal header: start 727965696
2011-06-03 07:29:18.062744 7fb493b3e760 journal write_pos 4096
2011-06-03 07:29:18.062754 7fb493b3e760 journal open header.fsid = 1739958715
2011-06-03 07:29:18.083602 7fb493b3e760 journal read_entry 727965696 : seq 555699 1759 bytes
2011-06-03 07:29:18.083668 7fb493b3e760 journal read_entry 727973888 : seq 555700 1628 bytes
2011-06-03 07:29:18.107279 7fb493b3e760 journal read_entry 727982080 : seq 555701 2063 bytes
2011-06-03 07:29:18.107306 7fb493b3e760 journal read_entry 727990272 : seq 555702 1628 bytes
2011-06-03 07:29:18.107323 7fb493b3e760 journal read_entry 727998464 : seq 555703 2063 bytes
2011-06-03 07:29:18.107334 7fb493b3e760 journal read_entry 728006656 : seq 555704 1628 bytes
2011-06-03 07:29:18.107698 7fb493b3e760 journal read_entry 728014848 : seq 555705 2063 bytes
2011-06-03 07:29:18.107721 7fb493b3e760 journal read_entry 728023040 : seq 555706 1628 bytes
2011-06-03 07:29:18.107737 7fb493b3e760 journal read_entry 728031232 : seq 555707 2063 bytes
2011-06-03 07:29:18.107749 7fb493b3e760 journal read_entry 728039424 : seq 555708 1628 bytes
2011-06-03 07:29:18.107760 7fb493b3e760 journal read_entry 728047616 : seq 555709 2063 bytes
2011-06-03 07:29:18.107771 7fb493b3e760 journal read_entry 728055808 : seq 555710 1628 bytes
2011-06-03 07:29:18.107781 7fb493b3e760 journal read_entry 728064000 : seq 555711 2063 bytes
2011-06-03 07:29:18.107792 7fb493b3e760 journal read_entry 728072192 : seq 555712 1628 bytes
2011-06-03 07:29:18.117735 7fb493b3e760 journal read_entry 728080384 : seq 555713 2063 bytes
2011-06-03 07:29:18.117761 7fb493b3e760 journal read_entry 728088576 : seq 555714 1640 bytes
2011-06-03 07:29:18.117776 7fb493b3e760 journal read_entry 728096768 : seq 555715 2075 bytes
2011-06-03 07:29:18.117787 7fb493b3e760 journal read_entry 728104960 : seq 555716 1640 bytes
2011-06-03 07:29:18.117798 7fb493b3e760 journal read_entry 728113152 : seq 555717 2075 bytes
2011-06-03 07:29:18.117809 7fb493b3e760 journal read_entry 728121344 : seq 555718 1640 bytes
2011-06-03 07:29:18.117820 7fb493b3e760 journal read_entry 728129536 : seq 555719 2075 bytes
2011-06-03 07:29:18.117831 7fb493b3e760 journal read_entry 728137728 : seq 555720 1640 bytes
2011-06-03 07:29:18.117844 7fb493b3e760 journal read_entry 728145920 : seq 555721 2075 bytes
2011-06-03 07:29:18.117852 7fb493b3e760 journal read_entry 728154112 : seq 555722 1640 bytes
2011-06-03 07:29:18.117859 7fb493b3e760 journal read_entry 728162304 : seq 555723 2075 bytes
2011-06-03 07:29:18.117865 7fb493b3e760 journal read_entry 728170496 : bad header magic, end of journal
2011-06-03 07:29:18.117869 7fb493b3e760 journal open reached end of journal.
2011-06-03 07:29:18.117874 7fb493b3e760 journal read_entry 728170496 : bad header magic, end of journal
2011-06-03 07:29:18.117882 7fb493b3e760 journal journal_replay: end of journal, done.
2011-06-03 07:29:18.117895 7fb493b3e760 journal _open journal is not a block device, NOT checking disk write cache on '/data/osd0/journal'
2011-06-03 07:29:18.117910 7fb493b3e760 journal _open /data/osd0/journal fd 11: 1048576000 bytes, block size 4096 bytes, directio = 1
2011-06-03 07:29:18.117942 7fb493b3e760 journal journal_start
2011-06-03 07:29:18.117999 7fb48de5a700 journal write_thread_entry start
2011-06-03 07:29:18.118013 7fb48de5a700 journal write_thread_entry going to sleep
2011-06-03 07:29:18.118063 7fb48b655700 filestore(/data/osd0) flusher_entry start
2011-06-03 07:29:18.118074 7fb48b655700 filestore(/data/osd0) flusher_entry sleeping
2011-06-03 07:29:18.118125 7fb48ce58700 filestore(/data/osd0) sync_entry waiting for max_interval 5.000000
2011-06-03 07:29:18.118189 7fb493b3e760 osd0 0 boot
2011-06-03 07:29:18.118218 7fb493b3e760 filestore(/data/osd0) read meta/osd_superblock/0 0~0
2011-06-03 07:29:18.118258 7fb493b3e760 filestore(/data/osd0) lfn_get cid=meta oid=osd_superblock/0 pathname=/data/osd0/current/meta/osd_superblock_0 lfn=osd_superblock_0 is_lfn=0
2011-06-03 07:29:18.118294 7fb493b3e760 filestore(/data/osd0) FileStore::read meta/osd_superblock/0 0~123/123
2011-06-03 07:29:18.118329 7fb493b3e760 osd0 0 read_superblock sb(cccb50e4-85c6-bd07-8f3c-28d179cdfef7 osd0 e38 [1,38] lci=[38,38])
2011-06-03 07:29:18.118377 7fb493b3e760 osd0 0 get_map 38 - loading and decoding 0x29b1000
2011-06-03 07:29:18.118389 7fb493b3e760 filestore(/data/osd0) read meta/osdmap.38/0 0~0
2011-06-03 07:29:18.118396 7fb493b3e760 filestore(/data/osd0) lfn_get cid=meta oid=osdmap.38/0 pathname=/data/osd0/current/meta/osdmap.38_0 lfn=osdmap.38_0 is_lfn=0
2011-06-03 07:29:18.118416 7fb493b3e760 filestore(/data/osd0) FileStore::read meta/osdmap.38/0 0~1196/1196
2011-06-03 07:29:18.118488 7fb493b3e760 osd0 0 add_map 38 0x29b1000
2011-06-03 07:29:18.118500 7fb493b3e760 osd0 38 clear_temp
2011-06-03 07:29:18.118505 7fb493b3e760 filestore(/data/osd0) collection_list /data/osd0/current/temp
2011-06-03 07:29:18.118521 7fb493b3e760 filestore(/data/osd0) collection_list temp sorting 0 objects
2011-06-03 07:29:18.118528 7fb493b3e760 filestore(/data/osd0) collection_list temp = 0 (0 objects)
2011-06-03 07:29:18.118535 7fb493b3e760 osd0 38 0 objects
2011-06-03 07:29:18.118542 7fb493b3e760 filestore(/data/osd0) collection_stat /data/osd0/current/temp
2011-06-03 07:29:18.118548 7fb493b3e760 filestore(/data/osd0) collection_stat /data/osd0/current/temp = 0
2011-06-03 07:29:18.118555 7fb493b3e760 osd0 38 load_pgs
2011-06-03 07:29:18.118561 7fb493b3e760 filestore(/data/osd0) list_collections
2011-06-03 07:29:18.118610 7fb493b3e760 osd0 38 load_pgs done
2011-06-03 07:29:18.118616 7fb493b3e760 osd0 38 superblock: i am osd0
2011-06-03 07:29:18.118622 7fb493b3e760 osd0 38 open_logger
2011-06-03 07:29:18.118705 7fb493b3e760 filestore(/data/osd0) start_logger
2011-06-03 07:29:18.118890 7fb493b3e760 -- 0.0.0.0:6801/20872 --> 192.168.100.7:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x29b4600 con 0x29b5280
2011-06-03 07:29:18.119323 7fb493b3a700 -- 192.168.100.7:6801/20872 learned my addr 192.168.100.7:6801/20872
2011-06-03 07:29:18.119368 7fb493b3a700 osd0 38 OSD::ms_get_authorizer type=mon
2011-06-03 07:29:18.119578 7fb48864f700 osd0 38 ms_handle_connect on mon
2011-06-03 07:29:18.119606 7fb48864f700 osd0 38 send_boot
2011-06-03 07:29:18.119618 7fb48864f700 osd0 38 assuming cluster_addr ip matches client_addr
2011-06-03 07:29:18.119623 7fb48864f700 osd0 38 assuming hb_addr ip matches cluster_addr
2011-06-03 07:29:18.119640 7fb48864f700 osd0 38 client_addr 192.168.100.7:6801/20872, cluster_addr 192.168.100.7:6802/20872, hb addr 192.168.100.7:6803/20872
2011-06-03 07:29:18.119649 7fb48864f700 osd0 38 send_alive up_thru currently 0 want 0
2011-06-03 07:29:18.119661 7fb48864f700 osd0 38 send_pg_stats
2011-06-03 07:29:18.184680 7fb48864f700 -- 192.168.100.7:6801/20872 <== mon0 192.168.100.7:6789/0 1 ==== auth_reply(proto 1 0 Success) v1 ==== 24+0+0 (898536972 0 0) 0x29b4a00 con 0x29b5280
2011-06-03 07:29:18.184728 7fb48864f700 -- 192.168.100.7:6801/20872 --> 192.168.100.7:6789/0 -- mon_subscribe({monmap=0+}) v1 -- ?+0 0x29b7000 con 0x29b5280
2011-06-03 07:29:18.184748 7fb48864f700 -- 192.168.100.7:6801/20872 --> 192.168.100.7:6789/0 -- osd_boot(osd0 v38) v1 -- ?+0 0x29a8c00 con 0x29b5280
2011-06-03 07:29:18.185173 7fb484546700 osd0 38 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:18.185218 7fb484546700 osd0 38 heartbeat: stat(2011-06-03 07:2:18.185030 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:18.185225 7fb484546700 osd0 38 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:18.185235 7fb484546700 osd0 38 i have no heartbeat peers; checking mon for new map
2011-06-03 07:29:18.185248 7fb484546700 -- 192.168.100.7:6801/20872 --> 192.168.100.7:6789/0 -- mon_subscribe({monmap=0+,osdmap=39}) v1 -- ?+0 0x29b71c0 con 0x29b5280
2011-06-03 07:29:18.276701 7fb48864f700 -- 192.168.100.7:6801/20872 <== mon0 192.168.100.7:6789/0 2 ==== mon_map v1 ==== 187+0+0 (1017214062 0 0) 0x29bb000 con 0x29b5280
2011-06-03 07:29:18.276740 7fb48864f700 -- 192.168.100.7:6801/20872 <== mon0 192.168.100.7:6789/0 3 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (2684212871 0 0) 0x29a2180 con 0x29b5280
2011-06-03 07:29:18.276884 7fb48864f700 -- 192.168.100.7:6801/20872 <== mon0 192.168.100.7:6789/0 4 ==== mon_map v1 ==== 187+0+0 (1017214062 0 0) 0x29bb380 con 0x29b5280
2011-06-03 07:29:18.276910 7fb48864f700 -- 192.168.100.7:6801/20872 <== mon0 192.168.100.7:6789/0 5 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (2684212871 0 0) 0x29a2480 con 0x29b5280
2011-06-03 07:29:18.626245 7fb48864f700 -- 192.168.100.7:6801/20872 <== mon0 192.168.100.7:6789/0 6 ==== osd_map(39,39) v1 ==== 149+0+0 (3836566900 0 0) 0x29b4e00 con 0x29b5280
2011-06-03 07:29:18.626265 7fb48864f700 osd0 38 _dispatch 0x29b4e00 osd_map(39,39) v1
2011-06-03 07:29:18.626275 7fb48864f700 osd0 38 handle_osd_map epochs [39,39], i have 38
2011-06-03 07:29:18.626280 7fb48864f700 osd0 38 locking handle_osd_map permissions
2011-06-03 07:29:18.626290 7fb48864f700 osd0 38 handle_osd_map got inc map for epoch 39
2011-06-03 07:29:18.626306 7fb48864f700 osd0 38 add_map_inc_bl 39 117 bytes
2011-06-03 07:29:18.626408 7fb48864f700 osd0 38 add_map 39 0x29b1300
2011-06-03 07:29:18.626428 7fb48864f700 osd0 38 add_map_bl 39 1196 bytes
2011-06-03 07:29:18.626438 7fb48864f700 filestore(/data/osd0) flush
2011-06-03 07:29:18.626443 7fb48864f700 journal flush waiting for finisher
2011-06-03 07:29:18.626447 7fb48864f700 journal flush done
2011-06-03 07:29:18.626453 7fb48864f700 filestore(/data/osd0) flush draining ondisk finisher
2011-06-03 07:29:18.626459 7fb48864f700 filestore(/data/osd0) _flush_op_queue draining op tp
2011-06-03 07:29:18.626463 7fb48864f700 filestore(/data/osd0) _flush_op_queue waiting for apply finisher
2011-06-03 07:29:18.626467 7fb48864f700 filestore(/data/osd0) flush complete
2011-06-03 07:29:18.626473 7fb48864f700 osd0 38 advance to epoch 39 (<= newest 39)
2011-06-03 07:29:18.626484 7fb48864f700 osd0 39 advance_map epoch 39 0 pgs
2011-06-03 07:29:18.626497 7fb48864f700 osd0 39 write_superblock sb(cccb50e4-85c6-bd07-8f3c-28d179cdfef7 osd0 e39 [1,39] lci=[38,38])
2011-06-03 07:29:18.626510 7fb48864f700 filestore(/data/osd0) apply queued
2011-06-03 07:29:18.626519 7fb48864f700 filestore(/data/osd0) queue_transactions new osr 0x29c4000/0x29a6688
2011-06-03 07:29:18.626532 7fb48864f700 journal op_submit_start 555724
2011-06-03 07:29:18.626538 7fb48864f700 filestore(/data/osd0) queue_transactions (writeahead) 555724 0x7fb48864dc50
2011-06-03 07:29:18.626545 7fb48864f700 journal op_journal_transactions 555724 0x7fb48864dc50
2011-06-03 07:29:18.626558 7fb48864f700 journal submit_entry seq 555724 len 1640 (0x29c2150)
2011-06-03 07:29:18.626569 7fb48864f700 journal op_submit_finish 555724
2011-06-03 07:29:18.626634 7fb48de5a700 journal write_thread_entry woke up
2011-06-03 07:29:18.626656 7fb48de5a700 journal room 1048367103 max_size 1048576000 pos 728170496 header.start 727965696 top 4096
2011-06-03 07:29:18.626668 7fb48de5a700 journal check_for_full at 728170496 : 8192 < 1048367103
2011-06-03 07:29:18.626681 7fb48de5a700 journal prepare_single_write 1 will write 728170496 : seq 555724 len 1640 -> 8192 (head 40 pre_pad 4056 ebl 1640 post_pad 2416 tail 40) (ebl alignment 0)
2011-06-03 07:29:18.626710 7fb48de5a700 journal prepare_multi_write queue_pos now 728178688
2011-06-03 07:29:18.626728 7fb48de5a700 journal do_write writing 728170496~8192 + header
2011-06-03 07:29:18.652017 7fb48de5a700 journal do_write latency 0.025277
2011-06-03 07:29:18.652036 7fb48de5a700 journal do_write queueing finishers through seq 555724
2011-06-03 07:29:18.652048 7fb48de5a700 journal queue_completions_thru seq 555724 queueing seq 555724 0x29c2150
2011-06-03 07:29:18.652068 7fb48de5a700 journal put_throttle finished 1 ops and 1640 bytes, now 0 ops and 0 bytes
2011-06-03 07:29:18.652077 7fb48de5a700 journal write_thread_entry going to sleep
2011-06-03 07:29:18.652165 7fb48d659700 filestore(/data/osd0) _journaled_ahead 555724 0x7fb48864dc50
2011-06-03 07:29:18.652185 7fb48d659700 journal op_apply_start 555724
2011-06-03 07:29:18.652201 7fb48d659700 filestore(/data/osd0) queue_op 0x2985f00 seq 555724 1640 bytes (queue has 1 ops and 1640 bytes)
2011-06-03 07:29:18.652222 7fb48d659700 filestore(/data/osd0) queueing ondisk 0x297aca0
2011-06-03 07:29:18.652335 7fb48c657700 filestore(/data/osd0) _do_op 0x2985f00 555724 osr 0x29c4000/0x29a6688 start
2011-06-03 07:29:18.652363 7fb48c657700 filestore(/data/osd0) _do_transaction on 0x7fb48864dc50
2011-06-03 07:29:18.652395 7fb48c657700 filestore(/data/osd0) write meta/inc_osdmap.39/0 0~117
2011-06-03 07:29:18.652418 7fb48c657700 filestore(/data/osd0) lfn_get cid=meta oid=inc_osdmap.39/0 pathname=/data/osd0/current/meta/inc_osdmap.39_0 lfn=inc_osdmap.39_0 is_lfn=0
2011-06-03 07:29:18.652499 7fb48c657700 filestore(/data/osd0) queue_flusher ep 0 fd 13 0~117 qlen 1
2011-06-03 07:29:18.652508 7fb48c657700 filestore(/data/osd0) write meta/inc_osdmap.39/0 0~117 = 117
2011-06-03 07:29:18.652516 7fb48c657700 filestore(/data/osd0) write meta/osdmap.39/0 0~1196
2011-06-03 07:29:18.652522 7fb48c657700 filestore(/data/osd0) lfn_get cid=meta oid=osdmap.39/0 pathname=/data/osd0/current/meta/osdmap.39_0 lfn=osdmap.39_0 is_lfn=0
2011-06-03 07:29:18.652552 7fb48b655700 filestore(/data/osd0) flusher_entry awoke
2011-06-03 07:29:18.652569 7fb48b655700 filestore(/data/osd0) flusher_entry flushing+closing 13 ep 0
2011-06-03 07:29:18.652588 7fb48c657700 filestore(/data/osd0) queue_flusher ep 0 fd 14 0~1196 qlen 2
2011-06-03 07:29:18.652606 7fb48c657700 filestore(/data/osd0) write meta/osdmap.39/0 0~1196 = 1196
2011-06-03 07:29:18.652620 7fb48c657700 filestore(/data/osd0) write meta/osd_superblock/0 0~123
2011-06-03 07:29:18.652627 7fb48c657700 filestore(/data/osd0) lfn_get cid=meta oid=osd_superblock/0 pathname=/data/osd0/current/meta/osd_superblock_0 lfn=osd_superblock_0 is_lfn=0
2011-06-03 07:29:18.652639 7fb48c657700 filestore(/data/osd0) queue_flusher ep 0 fd 15 0~123 qlen 3
2011-06-03 07:29:18.652644 7fb48c657700 filestore(/data/osd0) write meta/osd_superblock/0 0~123 = 123
2011-06-03 07:29:18.652649 7fb48c657700 journal op_apply_finish 555724
2011-06-03 07:29:18.652654 7fb48c657700 filestore(/data/osd0) _do_op 0x2985f00 555724 r = 0, finisher 0x29c21b0 0
2011-06-03 07:29:18.652659 7fb48c657700 filestore(/data/osd0) _finish_op on osr 0x29c4000/0x29a6688
2011-06-03 07:29:18.652664 7fb48c657700 filestore(/data/osd0) _finish_op 555724 next_finish 555724 queueing 0x29c21b0 doing 0
2011-06-03 07:29:18.652683 7fb48b655700 filestore(/data/osd0) flusher_entry flushing+closing 14 ep 0
2011-06-03 07:29:18.652749 7fb48b655700 filestore(/data/osd0) flusher_entry flushing+closing 15 ep 0
2011-06-03 07:29:18.652766 7fb48b655700 filestore(/data/osd0) flusher_entry sleeping
2011-06-03 07:29:18.652783 7fb48864f700 filestore(/data/osd0) apply done r = 0
2011-06-03 07:29:18.652799 7fb48864f700 osd0 39 keep_map_from 40
2011-06-03 07:29:18.652808 7fb48864f700 osd0 39 trim_map_bl_cache up to 40
2011-06-03 07:29:18.652841 7fb48864f700 osd0 39 unlocking map_in_progress
2011-06-03 07:29:19.185125 7fb48ee5c700 osd0 39 tick
2011-06-03 07:29:19.185203 7fb48ee5c700 osd0 39 scrub_should_schedule loadavg 0.01 < max 0.5 = no, randomly backing off
2011-06-03 07:29:19.185219 7fb48ee5c700 osd0 39 do_mon_report
2011-06-03 07:29:19.185232 7fb48ee5c700 osd0 39 send_alive up_thru currently 0 want 0
2011-06-03 07:29:19.185239 7fb48ee5c700 osd0 39 send_pg_stats
2011-06-03 07:29:19.185249 7fb48ee5c700 osd0 39 send_pg_stats - 0 pgs updated
2011-06-03 07:29:19.185260 7fb48ee5c700 -- 192.168.100.7:6801/20872 --> 192.168.100.7:6789/0 -- pg_stats(0 pgs v 39) v1 -- ?+0 0x2992900 con 0x29b5280
2011-06-03 07:29:19.585441 7fb484546700 osd0 39 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:19.585494 7fb484546700 osd0 39 heartbeat: stat(2011-06-03 07:2:19.585392 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:19.585504 7fb484546700 osd0 39 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:19.713183 7fb48864f700 -- 192.168.100.7:6801/20872 <== mon0 192.168.100.7:6789/0 7 ==== osd_map(39,40) v1 ==== 709+0+0 (2388672170 0 0) 0x29b4c00 con 0x29b5280
2011-06-03 07:29:19.713205 7fb48864f700 osd0 39 _dispatch 0x29b4c00 osd_map(39,40) v1
2011-06-03 07:29:19.713218 7fb48864f700 osd0 39 handle_osd_map epochs [39,40], i have 39
2011-06-03 07:29:19.713224 7fb48864f700 osd0 39 locking handle_osd_map permissions
2011-06-03 07:29:19.713232 7fb48864f700 osd0 39 handle_osd_map got inc map for epoch 40
2011-06-03 07:29:19.713243 7fb48864f700 osd0 39 add_map_inc_bl 40 552 bytes
2011-06-03 07:29:19.713303 7fb48864f700 osd0 39 add_map 40 0x29b1c00
2011-06-03 07:29:19.713319 7fb48864f700 osd0 39 add_map_bl 40 1196 bytes
2011-06-03 07:29:19.713326 7fb48864f700 filestore(/data/osd0) flush
2011-06-03 07:29:19.713330 7fb48864f700 journal flush waiting for finisher
2011-06-03 07:29:19.713335 7fb48864f700 journal flush done
2011-06-03 07:29:19.713338 7fb48864f700 filestore(/data/osd0) flush draining ondisk finisher
2011-06-03 07:29:19.713342 7fb48864f700 filestore(/data/osd0) _flush_op_queue draining op tp
2011-06-03 07:29:19.713346 7fb48864f700 filestore(/data/osd0) _flush_op_queue waiting for apply finisher
2011-06-03 07:29:19.713350 7fb48864f700 filestore(/data/osd0) flush complete
2011-06-03 07:29:19.713379 7fb48864f700 osd0 39 advance to epoch 40 (<= newest 40)
2011-06-03 07:29:19.713389 7fb48864f700 osd0 40 advance_map epoch 40 0 pgs
2011-06-03 07:29:19.713401 7fb48864f700 osd0 40 up_epoch is 40
2011-06-03 07:29:19.713405 7fb48864f700 osd0 40 boot_epoch is 40
2011-06-03 07:29:19.713411 7fb48864f700 osd0 40 state: booting -> active
2011-06-03 07:29:19.713418 7fb48864f700 osd0 40 activate_map version 40
2011-06-03 07:29:19.713428 7fb48864f700 osd0 40 trim_map_cache up to MIN(40,40)
2011-06-03 07:29:19.713433 7fb48864f700 osd0 40 trim_map_cache 38 0x29b1000
2011-06-03 07:29:19.713444 7fb48864f700 osd0 40 trim_map_cache 39 0x29b1300
2011-06-03 07:29:19.713457 7fb48864f700 osd0 40 update_heartbeat_peers: hb to: {}
2011-06-03 07:29:19.713465 7fb48864f700 osd0 40 update_heartbeat_peers: hb from: {}
2011-06-03 07:29:19.713496 7fb48864f700 osd0 40 write_superblock sb(cccb50e4-85c6-bd07-8f3c-28d179cdfef7 osd0 e40 [1,40] lci=[40,40])
2011-06-03 07:29:19.713513 7fb48864f700 filestore(/data/osd0) apply queued
2011-06-03 07:29:19.713523 7fb48864f700 filestore(/data/osd0) queue_transactions existing osr 0x29c4000/0x29a6688
2011-06-03 07:29:19.713533 7fb48864f700 journal op_submit_start 555725
2011-06-03 07:29:19.713539 7fb48864f700 filestore(/data/osd0) queue_transactions (writeahead) 555725 0x7fb48864dc50
2011-06-03 07:29:19.713543 7fb48864f700 journal op_journal_transactions 555725 0x7fb48864dc50
2011-06-03 07:29:19.713550 7fb48864f700 journal submit_entry seq 555725 len 2075 (0x298cd50)
2011-06-03 07:29:19.713558 7fb48864f700 journal op_submit_finish 555725
2011-06-03 07:29:19.713577 7fb48de5a700 journal write_thread_entry woke up
2011-06-03 07:29:19.713583 7fb48de5a700 journal room 1048358911 max_size 1048576000 pos 728178688 header.start 727965696 top 4096
2011-06-03 07:29:19.713588 7fb48de5a700 journal check_for_full at 728178688 : 8192 < 1048358911
2011-06-03 07:29:19.713593 7fb48de5a700 journal prepare_single_write 1 will write 728178688 : seq 555725 len 2075 -> 8192 (head 40 pre_pad 4056 ebl 2075 post_pad 1981 tail 40) (ebl alignment 0)
2011-06-03 07:29:19.713606 7fb48de5a700 journal prepare_multi_write queue_pos now 728186880
2011-06-03 07:29:19.713615 7fb48de5a700 journal do_write writing 728178688~8192
2011-06-03 07:29:19.713887 7fb483d45700 osd0 40 OSD::ms_verify_authorizer name=client.admin auid=18446744073709551615
2011-06-03 07:29:19.713913 7fb483d45700 osd0 40 new session 0x29b8120 con=0x29b6c80 addr=192.168.100.2:0/1017516
2011-06-03 07:29:19.727070 7fb48de5a700 journal do_write latency 0.013446
2011-06-03 07:29:19.727090 7fb48de5a700 journal do_write queueing finishers through seq 555725
2011-06-03 07:29:19.727101 7fb48de5a700 journal queue_completions_thru seq 555725 queueing seq 555725 0x298cd50
2011-06-03 07:29:19.727115 7fb48de5a700 journal put_throttle finished 1 ops and 2075 bytes, now 0 ops and 0 bytes
2011-06-03 07:29:19.727125 7fb48de5a700 journal write_thread_entry going to sleep
2011-06-03 07:29:19.727218 7fb48d659700 filestore(/data/osd0) _journaled_ahead 555725 0x7fb48864dc50
2011-06-03 07:29:19.727238 7fb48d659700 journal op_apply_start 555725
2011-06-03 07:29:19.727252 7fb48d659700 filestore(/data/osd0) queue_op 0x29850c0 seq 555725 2075 bytes (queue has 1 ops and 2075 bytes)
2011-06-03 07:29:19.727268 7fb48d659700 filestore(/data/osd0) queueing ondisk 0x29c6040
2011-06-03 07:29:19.727331 7fb48be56700 filestore(/data/osd0) _do_op 0x29850c0 555725 osr 0x29c4000/0x29a6688 start
2011-06-03 07:29:19.727351 7fb48be56700 filestore(/data/osd0) _do_transaction on 0x7fb48864dc50
2011-06-03 07:29:19.727377 7fb48be56700 filestore(/data/osd0) write meta/inc_osdmap.40/0 0~552
2011-06-03 07:29:19.727400 7fb48be56700 filestore(/data/osd0) lfn_get cid=meta oid=inc_osdmap.40/0 pathname=/data/osd0/current/meta/inc_osdmap.40_0 lfn=inc_osdmap.40_0 is_lfn=0
2011-06-03 07:29:19.727488 7fb48be56700 filestore(/data/osd0) queue_flusher ep 0 fd 14 0~552 qlen 1
2011-06-03 07:29:19.727504 7fb48be56700 filestore(/data/osd0) write meta/inc_osdmap.40/0 0~552 = 552
2011-06-03 07:29:19.727516 7fb48b655700 filestore(/data/osd0) flusher_entry awoke
2011-06-03 07:29:19.727530 7fb48b655700 filestore(/data/osd0) flusher_entry flushing+closing 14 ep 0
2011-06-03 07:29:19.727552 7fb48be56700 filestore(/data/osd0) write meta/osdmap.40/0 0~1196
2011-06-03 07:29:19.727572 7fb48be56700 filestore(/data/osd0) lfn_get cid=meta oid=osdmap.40/0 pathname=/data/osd0/current/meta/osdmap.40_0 lfn=osdmap.40_0 is_lfn=0
2011-06-03 07:29:19.727653 7fb48be56700 filestore(/data/osd0) queue_flusher ep 0 fd 15 0~1196 qlen 2
2011-06-03 07:29:19.727669 7fb48be56700 filestore(/data/osd0) write meta/osdmap.40/0 0~1196 = 1196
2011-06-03 07:29:19.727681 7fb48b655700 filestore(/data/osd0) flusher_entry flushing+closing 15 ep 0
2011-06-03 07:29:19.727779 7fb48b655700 filestore(/data/osd0) flusher_entry sleeping
2011-06-03 07:29:19.727794 7fb48be56700 filestore(/data/osd0) write meta/osd_superblock/0 0~123
2011-06-03 07:29:19.727802 7fb48be56700 filestore(/data/osd0) lfn_get cid=meta oid=osd_superblock/0 pathname=/data/osd0/current/meta/osd_superblock_0 lfn=osd_superblock_0 is_lfn=0
2011-06-03 07:29:19.727818 7fb48be56700 filestore(/data/osd0) queue_flusher ep 0 fd 14 0~123 qlen 1
2011-06-03 07:29:19.727829 7fb48be56700 filestore(/data/osd0) write meta/osd_superblock/0 0~123 = 123
2011-06-03 07:29:19.727839 7fb48be56700 journal op_apply_finish 555725
2011-06-03 07:29:19.727849 7fb48be56700 filestore(/data/osd0) _do_op 0x29850c0 555725 r = 0, finisher 0x298cc90 0
2011-06-03 07:29:19.727858 7fb48be56700 filestore(/data/osd0) _finish_op on osr 0x29c4000/0x29a6688
2011-06-03 07:29:19.727867 7fb48be56700 filestore(/data/osd0) _finish_op 555725 next_finish 555725 queueing 0x298cc90 doing 0
2011-06-03 07:29:19.727878 7fb48b655700 filestore(/data/osd0) flusher_entry awoke
2011-06-03 07:29:19.727889 7fb48b655700 filestore(/data/osd0) flusher_entry flushing+closing 14 ep 0
2011-06-03 07:29:19.727914 7fb48b655700 filestore(/data/osd0) flusher_entry sleeping
2011-06-03 07:29:19.727975 7fb48864f700 filestore(/data/osd0) apply done r = 0
2011-06-03 07:29:19.728004 7fb48864f700 osd0 40 keep_map_from 41
2011-06-03 07:29:19.728014 7fb48864f700 osd0 40 trim_map_bl_cache up to 41
2011-06-03 07:29:19.728032 7fb48864f700 osd0 40 unlocking map_in_progress
2011-06-03 07:29:19.728053 7fb48864f700 -- 192.168.100.7:6801/20872 <== mon0 192.168.100.7:6789/0 8 ==== osd_map(39,40) v1 ==== 709+0+0 (2388672170 0 0) 0x29b4e00 con 0x29b5280
2011-06-03 07:29:19.728060 7fb48864f700 osd0 40 _dispatch 0x29b4e00 osd_map(39,40) v1
2011-06-03 07:29:19.728065 7fb48864f700 osd0 40 handle_osd_map epochs [39,40], i have 40
2011-06-03 07:29:19.728069 7fb48864f700 osd0 40 no new maps here, dropping
2011-06-03 07:29:19.728086 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720350 192.168.100.2:0/1017516 1 ==== osd_op(client1720350.0:265 volume-0000001b.rbd [watch 1~0] 3.73c8 RETRY) v2 ==== 134+0+0 (1759681072 0 0) 0x2992b40 con 0x29b6c80
2011-06-03 07:29:19.728093 7fb48864f700 osd0 40 _dispatch 0x2992b40 osd_op(client1720350.0:265 volume-0000001b.rbd [watch 1~0] 3.73c8 RETRY) v2
2011-06-03 07:29:19.728102 7fb48864f700 osd0 40 require_same_or_newer_map 40 (i am 40) 0x2992b40
2011-06-03 07:29:19.728123 7fb48864f700 osd0 40 _share_map_incoming client1720350 192.168.100.2:0/1017516 40
2011-06-03 07:29:19.728133 7fb48864f700 osd0 40 hit non-existent pg 3.8, waiting
2011-06-03 07:29:20.185411 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:20.185469 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = no, randomly backing off
2011-06-03 07:29:20.485695 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:20.485727 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:20.485645 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:20.485735 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:21.185626 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:21.185687 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = no, randomly backing off
2011-06-03 07:29:21.685920 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:21.685953 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:21.685871 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:21.685961 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:21.982053 7fb483b43700 osd0 40 OSD::ms_verify_authorizer name=mds.0 auid=18446744073709551615
2011-06-03 07:29:21.982089 7fb483b43700 osd0 40 new session 0x29b8240 con=0x29c8500 addr=192.168.100.7:6800/3403
2011-06-03 07:29:21.982327 7fb48864f700 -- 192.168.100.7:6801/20872 <== mds0 192.168.100.7:6800/3403 1 ==== osd_op(mds0.4:2 mds0_sessionmap [read 0~0] 1.c60b RETRY) v2 ==== 130+0+0 (2595361008 0 0) 0x2992d80 con 0x29c8500
2011-06-03 07:29:21.982351 7fb48864f700 osd0 40 _dispatch 0x2992d80 osd_op(mds0.4:2 mds0_sessionmap [read 0~0] 1.c60b RETRY) v2
2011-06-03 07:29:21.982360 7fb48864f700 osd0 40 require_same_or_newer_map 40 (i am 40) 0x2992d80
2011-06-03 07:29:21.982369 7fb48864f700 osd0 40 _share_map_incoming mds0 192.168.100.7:6800/3403 40
2011-06-03 07:29:21.982379 7fb48864f700 osd0 40 hit non-existent pg 1.b, waiting
2011-06-03 07:29:21.982390 7fb48864f700 -- 192.168.100.7:6801/20872 <== mds0 192.168.100.7:6800/3403 2 ==== osd_op(mds0.4:1 mds0_inotable [read 0~0] 1.b893 RETRY) v2 ==== 128+0+0 (3151243526 0 0) 0x29c3240 con 0x29c8500
2011-06-03 07:29:21.982397 7fb48864f700 osd0 40 _dispatch 0x29c3240 osd_op(mds0.4:1 mds0_inotable [read 0~0] 1.b893 RETRY) v2
2011-06-03 07:29:21.982401 7fb48864f700 osd0 40 require_same_or_newer_map 40 (i am 40) 0x29c3240
2011-06-03 07:29:21.982407 7fb48864f700 osd0 40 _share_map_incoming mds0 192.168.100.7:6800/3403 40
2011-06-03 07:29:21.982412 7fb48864f700 osd0 40 hit non-existent pg 1.13, waiting
2011-06-03 07:29:21.982422 7fb48864f700 -- 192.168.100.7:6801/20872 <== mds0 192.168.100.7:6800/3403 3 ==== osd_op(mds0.4:5 200.00000000 [read 0~0] 1.3494 RETRY) v2 ==== 127+0+0 (1751485567 0 0) 0x29c3000 con 0x29c8500
2011-06-03 07:29:21.982433 7fb48864f700 osd0 40 _dispatch 0x29c3000 osd_op(mds0.4:5 200.00000000 [read 0~0] 1.3494 RETRY) v2
2011-06-03 07:29:21.982438 7fb48864f700 osd0 40 require_same_or_newer_map 40 (i am 40) 0x29c3000
2011-06-03 07:29:21.982444 7fb48864f700 osd0 40 _share_map_incoming mds0 192.168.100.7:6800/3403 40
2011-06-03 07:29:21.982448 7fb48864f700 osd0 40 hit non-existent pg 1.14, waiting
2011-06-03 07:29:21.982459 7fb48864f700 -- 192.168.100.7:6801/20872 <== mds0 192.168.100.7:6800/3403 4 ==== osd_op(mds0.4:4 mds_snaptable [read 0~0] 1.70ad RETRY) v2 ==== 128+0+0 (1050781132 0 0) 0x29c3900 con 0x29c8500
2011-06-03 07:29:21.982465 7fb48864f700 osd0 40 _dispatch 0x29c3900 osd_op(mds0.4:4 mds_snaptable [read 0~0] 1.70ad RETRY) v2
2011-06-03 07:29:21.982469 7fb48864f700 osd0 40 require_same_or_newer_map 40 (i am 40) 0x29c3900
2011-06-03 07:29:21.982475 7fb48864f700 osd0 40 _share_map_incoming mds0 192.168.100.7:6800/3403 40
2011-06-03 07:29:21.982479 7fb48864f700 osd0 40 hit non-existent pg 1.2d, waiting
2011-06-03 07:29:21.982489 7fb48864f700 -- 192.168.100.7:6801/20872 <== mds0 192.168.100.7:6800/3403 5 ==== osd_op(mds0.4:3 mds_anchortable [read 0~0] 1.f6a7 RETRY) v2 ==== 130+0+0 (2163157891 0 0) 0x29c36c0 con 0x29c8500
2011-06-03 07:29:21.982496 7fb48864f700 osd0 40 _dispatch 0x29c36c0 osd_op(mds0.4:3 mds_anchortable [read 0~0] 1.f6a7 RETRY) v2
2011-06-03 07:29:21.982500 7fb48864f700 osd0 40 require_same_or_newer_map 40 (i am 40) 0x29c36c0
2011-06-03 07:29:21.982505 7fb48864f700 osd0 40 _share_map_incoming mds0 192.168.100.7:6800/3403 40
2011-06-03 07:29:21.982510 7fb48864f700 osd0 40 hit non-existent pg 1.27, waiting
2011-06-03 07:29:22.185825 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:22.185886 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = yes
2011-06-03 07:29:22.185899 7fb48ee5c700 osd0 40 sched_scrub
2011-06-03 07:29:22.185907 7fb48ee5c700 osd0 40 sched_scrub done
2011-06-03 07:29:22.486146 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:22.486178 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:22.486097 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:22.486186 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:22.732389 7fb483941700 osd0 40 OSD::ms_verify_authorizer name=client.admin auid=18446744073709551615
2011-06-03 07:29:22.732420 7fb483941700 osd0 40 new session 0x29b8360 con=0x29c8280 addr=192.168.100.2:0/1018565
2011-06-03 07:29:22.732789 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720602 192.168.100.2:0/1018565 1 ==== osd_op(client1720602.0:1 volume-00000002.rbd [read 0~4096] 3.a7d6 RETRY) v2 ==== 134+0+0 (4171465658 0 0) 0x29c3b40 con 0x29c8280
2011-06-03 07:29:22.732810 7fb48864f700 osd0 40 _dispatch 0x29c3b40 osd_op(client1720602.0:1 volume-00000002.rbd [read 0~4096] 3.a7d6 RETRY) v2
2011-06-03 07:29:22.732818 7fb48864f700 osd0 40 require_same_or_newer_map 40 (i am 40) 0x29c3b40
2011-06-03 07:29:22.732827 7fb48864f700 osd0 40 _share_map_incoming client1720602 192.168.100.2:0/1018565 40
2011-06-03 07:29:22.732835 7fb48864f700 osd0 40 hit non-existent pg 3.16, waiting
2011-06-03 07:29:22.965177 7fb48373f700 osd0 40 OSD::ms_verify_authorizer name=client.admin auid=18446744073709551615
2011-06-03 07:29:22.965212 7fb48373f700 osd0 40 new session 0x29b8480 con=0x29c8dc0 addr=192.168.100.2:0/1005545
2011-06-03 07:29:22.965552 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720518 192.168.100.2:0/1005545 1 ==== osd_op(client1720518.0:5 volume-00000050.rbd [watch 1~0] 3.644d RETRY) v2 ==== 134+0+0 (3737433497 0 0) 0x29c3d80 con 0x29c8dc0
2011-06-03 07:29:22.965572 7fb48864f700 osd0 40 _dispatch 0x29c3d80 osd_op(client1720518.0:5 volume-00000050.rbd [watch 1~0] 3.644d RETRY) v2
2011-06-03 07:29:22.965581 7fb48864f700 osd0 40 require_same_or_newer_map 40 (i am 40) 0x29c3d80
2011-06-03 07:29:22.965590 7fb48864f700 osd0 40 _share_map_incoming client1720518 192.168.100.2:0/1005545 40
2011-06-03 07:29:22.965605 7fb48864f700 osd0 40 hit non-existent pg 3.d, waiting
2011-06-03 07:29:23.118288 7fb48ce58700 filestore(/data/osd0) sync_entry woke after 5.000187
2011-06-03 07:29:23.118310 7fb48ce58700 journal commit_start op_seq 555725, applied_seq 555725, committed_seq 555723
2011-06-03 07:29:23.118321 7fb48ce58700 journal commit_start committing 555725, still blocked
2011-06-03 07:29:23.118327 7fb48ce58700 journal commit_start
2011-06-03 07:29:23.118347 7fb48ce58700 filestore(/data/osd0) sync_entry committing 555725 sync_epoch 1
2011-06-03 07:29:23.118360 7fb48ce58700 journal commit_started committing 555725, unblocking
2011-06-03 07:29:23.118367 7fb48ce58700 filestore(/data/osd0) sync_entry doing a full sync (!)
2011-06-03 07:29:23.186047 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:23.186149 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = no, randomly backing off
2011-06-03 07:29:23.286408 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:23.286469 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:23.286317 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:23.286475 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:23.289365 7fb48353d700 osd0 40 OSD::ms_verify_authorizer name=client.admin auid=18446744073709551615
2011-06-03 07:29:23.289396 7fb48353d700 osd0 40 new session 0x29b85a0 con=0x29c8b40 addr=192.168.100.2:0/1031296
2011-06-03 07:29:23.289730 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720510 192.168.100.2:0/1031296 1 ==== osd_op(client1720510.0:5 volume-00000001.rbd [watch 1~0] 3.5329 RETRY) v2 ==== 134+0+0 (3999927169 0 0) 0x29c9000 con 0x29c8b40
2011-06-03 07:29:23.289750 7fb48864f700 osd0 40 _dispatch 0x29c9000 osd_op(client1720510.0:5 volume-00000001.rbd [watch 1~0] 3.5329 RETRY) v2
2011-06-03 07:29:23.289758 7fb48864f700 osd0 40 require_same_or_newer_map 40 (i am 40) 0x29c9000
2011-06-03 07:29:23.289769 7fb48864f700 osd0 40 _share_map_incoming client1720510 192.168.100.2:0/1031296 40
2011-06-03 07:29:23.289778 7fb48864f700 osd0 40 hit non-existent pg 3.29, waiting
2011-06-03 07:29:23.558718 7fb48ce58700 filestore(/data/osd0) sync_entry commit took 0.440381
2011-06-03 07:29:23.558739 7fb48ce58700 journal commit_finish thru 555725
2011-06-03 07:29:23.558750 7fb48ce58700 journal committed_thru 555725 (last_committed_seq 555723)
2011-06-03 07:29:23.558757 7fb48ce58700 journal header: block_size 4096 alignment 4096 max_size 1048576000
2011-06-03 07:29:23.558763 7fb48ce58700 journal header: start 728186880
2011-06-03 07:29:23.558769 7fb48ce58700 journal write_pos 728186880
2011-06-03 07:29:23.558775 7fb48ce58700 journal committed_thru done
2011-06-03 07:29:23.558781 7fb48ce58700 filestore(/data/osd0) sync_entry committed to op_seq 555725
2011-06-03 07:29:23.558791 7fb48ce58700 filestore(/data/osd0) sync_entry waiting for max_interval 5.000000
2011-06-03 07:29:24.186303 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:24.186367 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = no, randomly backing off
2011-06-03 07:29:24.186382 7fb48ee5c700 osd0 40 do_mon_report
2011-06-03 07:29:24.186390 7fb48ee5c700 osd0 40 send_alive up_thru currently 0 want 0
2011-06-03 07:29:24.186396 7fb48ee5c700 osd0 40 send_pg_stats
2011-06-03 07:29:24.486662 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:24.486694 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:24.486612 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:24.486702 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:25.186546 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:25.186605 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = yes
2011-06-03 07:29:25.186618 7fb48ee5c700 osd0 40 sched_scrub
2011-06-03 07:29:25.186626 7fb48ee5c700 osd0 40 sched_scrub done
2011-06-03 07:29:25.386877 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:25.386909 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:25.386826 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:25.386918 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:26.186776 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:26.186837 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = no, randomly backing off
2011-06-03 07:29:26.187090 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:26.187121 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:26.187041 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:26.187130 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:26.687317 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:26.687349 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:26.687268 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:26.687357 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:27.186987 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:27.187047 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = yes
2011-06-03 07:29:27.187061 7fb48ee5c700 osd0 40 sched_scrub
2011-06-03 07:29:27.187068 7fb48ee5c700 osd0 40 sched_scrub done
2011-06-03 07:29:27.987549 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:27.987581 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:27.987500 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:27.987590 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:28.187193 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:28.187253 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = no, randomly backing off
2011-06-03 07:29:28.487773 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:28.487804 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:28.487724 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:28.487813 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:28.558933 7fb48ce58700 filestore(/data/osd0) sync_entry woke after 5.000138
2011-06-03 07:29:28.558955 7fb48ce58700 journal commit_start op_seq 555725, applied_seq 555725, committed_seq 555725
2011-06-03 07:29:28.558966 7fb48ce58700 journal commit_start nothing to do
2011-06-03 07:29:28.558975 7fb48ce58700 journal commit_start
2011-06-03 07:29:28.558982 7fb48ce58700 filestore(/data/osd0) sync_entry waiting for max_interval 5.000000
2011-06-03 07:29:29.187409 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:29.187468 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = yes
2011-06-03 07:29:29.187482 7fb48ee5c700 osd0 40 sched_scrub
2011-06-03 07:29:29.187489 7fb48ee5c700 osd0 40 sched_scrub done
2011-06-03 07:29:29.187496 7fb48ee5c700 osd0 40 do_mon_report
2011-06-03 07:29:29.187503 7fb48ee5c700 osd0 40 send_alive up_thru currently 0 want 0
2011-06-03 07:29:29.187509 7fb48ee5c700 osd0 40 send_pg_stats
2011-06-03 07:29:29.287990 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:29.288023 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:29.287940 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:29.288031 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:30.187651 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:30.187710 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = no, randomly backing off
2011-06-03 07:29:30.688220 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:30.688252 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:30.688171 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:30.688261 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:31.187873 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:31.187932 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = no, randomly backing off
2011-06-03 07:29:31.588452 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:31.588484 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:31.588403 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:31.588492 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:32.188067 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:32.188144 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = yes
2011-06-03 07:29:32.188158 7fb48ee5c700 osd0 40 sched_scrub
2011-06-03 07:29:32.188165 7fb48ee5c700 osd0 40 sched_scrub done
2011-06-03 07:29:32.488679 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:32.488711 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:32.488630 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:32.488720 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:33.188309 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:33.188368 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = yes
2011-06-03 07:29:33.188382 7fb48ee5c700 osd0 40 sched_scrub
2011-06-03 07:29:33.188389 7fb48ee5c700 osd0 40 sched_scrub done
2011-06-03 07:29:33.388911 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:33.388943 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:33.388860 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:33.388951 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:33.559127 7fb48ce58700 filestore(/data/osd0) sync_entry woke after 5.000142
2011-06-03 07:29:33.559149 7fb48ce58700 journal commit_start op_seq 555725, applied_seq 555725, committed_seq 555725
2011-06-03 07:29:33.559160 7fb48ce58700 journal commit_start nothing to do
2011-06-03 07:29:33.559169 7fb48ce58700 journal commit_start
2011-06-03 07:29:33.559177 7fb48ce58700 filestore(/data/osd0) sync_entry waiting for max_interval 5.000000
2011-06-03 07:29:33.696196 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720350 192.168.100.2:0/1017516 2 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2180 con 0x29b6c80
2011-06-03 07:29:33.696215 7fb48864f700 osd0 40 _dispatch 0x29a2180 ping v1
2011-06-03 07:29:33.696228 7fb48864f700 osd0 40 ping from client1720350
2011-06-03 07:29:34.188535 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:34.188595 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = yes
2011-06-03 07:29:34.188608 7fb48ee5c700 osd0 40 sched_scrub
2011-06-03 07:29:34.188616 7fb48ee5c700 osd0 40 sched_scrub done
2011-06-03 07:29:34.188623 7fb48ee5c700 osd0 40 do_mon_report
2011-06-03 07:29:34.188630 7fb48ee5c700 osd0 40 send_alive up_thru currently 0 want 0
2011-06-03 07:29:34.188636 7fb48ee5c700 osd0 40 send_pg_stats
2011-06-03 07:29:34.789118 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:34.789150 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:34.789069 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:34.789159 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:35.188778 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:35.188846 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = yes
2011-06-03 07:29:35.188860 7fb48ee5c700 osd0 40 sched_scrub
2011-06-03 07:29:35.188867 7fb48ee5c700 osd0 40 sched_scrub done
2011-06-03 07:29:36.089350 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:36.089382 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:36.089301 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:36.089390 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:36.188934 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:36.188976 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = no, randomly backing off
2011-06-03 07:29:36.981502 7fb48864f700 -- 192.168.100.7:6801/20872 <== mds0 192.168.100.7:6800/3403 6 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2480 con 0x29c8500
2011-06-03 07:29:36.981520 7fb48864f700 osd0 40 _dispatch 0x29a2480 ping v1
2011-06-03 07:29:36.981530 7fb48864f700 osd0 40 ping from mds0
2011-06-03 07:29:37.189126 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:37.189188 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0.01 < max 0.5 = no, randomly backing off
2011-06-03 07:29:37.289582 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:37.289614 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:37.289531 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:37.289623 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:37.731503 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720602 192.168.100.2:0/1018565 2 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2600 con 0x29c8280
2011-06-03 07:29:37.731522 7fb48864f700 osd0 40 _dispatch 0x29a2600 ping v1
2011-06-03 07:29:37.731530 7fb48864f700 osd0 40 ping from client1720602
2011-06-03 07:29:37.889814 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:37.889846 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:37.889766 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:37.889854 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:37.915921 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720518 192.168.100.2:0/1005545 2 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2180 con 0x29c8dc0
2011-06-03 07:29:37.915939 7fb48864f700 osd0 40 _dispatch 0x29a2180 ping v1
2011-06-03 07:29:37.915947 7fb48864f700 osd0 40 ping from client1720518
2011-06-03 07:29:38.189320 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:38.189377 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = no, randomly backing off
2011-06-03 07:29:38.288673 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720510 192.168.100.2:0/1031296 2 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2480 con 0x29c8b40
2011-06-03 07:29:38.288693 7fb48864f700 osd0 40 _dispatch 0x29a2480 ping v1
2011-06-03 07:29:38.288701 7fb48864f700 osd0 40 ping from client1720510
2011-06-03 07:29:38.559304 7fb48ce58700 filestore(/data/osd0) sync_entry woke after 5.000123
2011-06-03 07:29:38.559326 7fb48ce58700 journal commit_start op_seq 555725, applied_seq 555725, committed_seq 555725
2011-06-03 07:29:38.559337 7fb48ce58700 journal commit_start nothing to do
2011-06-03 07:29:38.559345 7fb48ce58700 journal commit_start
2011-06-03 07:29:38.559353 7fb48ce58700 filestore(/data/osd0) sync_entry waiting for max_interval 5.000000
2011-06-03 07:29:38.696362 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720350 192.168.100.2:0/1017516 3 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2780 con 0x29b6c80
2011-06-03 07:29:38.696380 7fb48864f700 osd0 40 _dispatch 0x29a2780 ping v1
2011-06-03 07:29:38.696388 7fb48864f700 osd0 40 ping from client1720350
2011-06-03 07:29:38.790044 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:38.790076 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:38.789996 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:38.790093 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:39.189530 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:39.189587 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = no, randomly backing off
2011-06-03 07:29:39.189603 7fb48ee5c700 osd0 40 do_mon_report
2011-06-03 07:29:39.189610 7fb48ee5c700 osd0 40 send_alive up_thru currently 0 want 0
2011-06-03 07:29:39.189616 7fb48ee5c700 osd0 40 send_pg_stats
2011-06-03 07:29:39.290284 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:39.290316 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:39.290234 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:39.290324 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:39.890497 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:39.890529 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:39.890449 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:39.890538 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:40.189761 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:40.189820 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = no, randomly backing off
2011-06-03 07:29:40.490722 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:40.490753 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:40.490674 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:40.490762 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:41.189974 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:41.190034 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = yes
2011-06-03 07:29:41.190047 7fb48ee5c700 osd0 40 sched_scrub
2011-06-03 07:29:41.190055 7fb48ee5c700 osd0 40 sched_scrub done
2011-06-03 07:29:41.190949 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:41.190981 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:41.190902 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:41.190990 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:41.891180 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:41.891212 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:41.891132 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:41.891220 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:41.981659 7fb48864f700 -- 192.168.100.7:6801/20872 <== mds0 192.168.100.7:6800/3403 7 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2a80 con 0x29c8500
2011-06-03 07:29:41.981677 7fb48864f700 osd0 40 _dispatch 0x29a2a80 ping v1
2011-06-03 07:29:41.981685 7fb48864f700 osd0 40 ping from mds0
2011-06-03 07:29:42.190187 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:42.190246 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = no, randomly backing off
2011-06-03 07:29:42.731798 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720602 192.168.100.2:0/1018565 3 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2480 con 0x29c8280
2011-06-03 07:29:42.731819 7fb48864f700 osd0 40 _dispatch 0x29a2480 ping v1
2011-06-03 07:29:42.731831 7fb48864f700 osd0 40 ping from client1720602
2011-06-03 07:29:42.916246 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720518 192.168.100.2:0/1005545 3 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2a80 con 0x29c8dc0
2011-06-03 07:29:42.916267 7fb48864f700 osd0 40 _dispatch 0x29a2a80 ping v1
2011-06-03 07:29:42.916279 7fb48864f700 osd0 40 ping from client1720518
2011-06-03 07:29:43.190400 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:43.190459 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = yes
2011-06-03 07:29:43.190473 7fb48ee5c700 osd0 40 sched_scrub
2011-06-03 07:29:43.190480 7fb48ee5c700 osd0 40 sched_scrub done
2011-06-03 07:29:43.288991 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720510 192.168.100.2:0/1031296 3 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2d80 con 0x29c8b40
2011-06-03 07:29:43.289012 7fb48864f700 osd0 40 _dispatch 0x29a2d80 ping v1
2011-06-03 07:29:43.289024 7fb48864f700 osd0 40 ping from client1720510
2011-06-03 07:29:43.291409 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:43.291441 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:43.291359 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:43.291450 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:43.559498 7fb48ce58700 filestore(/data/osd0) sync_entry woke after 5.000142
2011-06-03 07:29:43.559520 7fb48ce58700 journal commit_start op_seq 555725, applied_seq 555725, committed_seq 555725
2011-06-03 07:29:43.559531 7fb48ce58700 journal commit_start nothing to do
2011-06-03 07:29:43.559540 7fb48ce58700 journal commit_start
2011-06-03 07:29:43.559547 7fb48ce58700 filestore(/data/osd0) sync_entry waiting for max_interval 5.000000
2011-06-03 07:29:43.696618 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720350 192.168.100.2:0/1017516 4 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2600 con 0x29b6c80
2011-06-03 07:29:43.696643 7fb48864f700 osd0 40 _dispatch 0x29a2600 ping v1
2011-06-03 07:29:43.696654 7fb48864f700 osd0 40 ping from client1720350
2011-06-03 07:29:43.991621 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:43.991652 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:43.991573 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:43.991661 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:44.190626 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:44.190686 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = no, randomly backing off
2011-06-03 07:29:44.190701 7fb48ee5c700 osd0 40 do_mon_report
2011-06-03 07:29:44.190708 7fb48ee5c700 osd0 40 send_alive up_thru currently 0 want 0
2011-06-03 07:29:44.190714 7fb48ee5c700 osd0 40 send_pg_stats
2011-06-03 07:29:44.491845 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:44.491877 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:44.491797 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:44.491885 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:44.992073 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:44.992105 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:44.992026 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:44.992113 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:45.190865 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:45.190923 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = no, randomly backing off
2011-06-03 07:29:45.892304 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:45.892336 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:45.892256 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:45.892345 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:46.191054 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:46.191114 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = no, randomly backing off
2011-06-03 07:29:46.792566 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:46.792616 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:46.792486 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:46.792622 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:46.981818 7fb48864f700 -- 192.168.100.7:6801/20872 <== mds0 192.168.100.7:6800/3403 8 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2900 con 0x29c8500
2011-06-03 07:29:46.981839 7fb48864f700 osd0 40 _dispatch 0x29a2900 ping v1
2011-06-03 07:29:46.981847 7fb48864f700 osd0 40 ping from mds0
2011-06-03 07:29:47.191279 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:47.191344 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = yes
2011-06-03 07:29:47.191358 7fb48ee5c700 osd0 40 sched_scrub
2011-06-03 07:29:47.191365 7fb48ee5c700 osd0 40 sched_scrub done
2011-06-03 07:29:47.731929 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720602 192.168.100.2:0/1018565 4 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2180 con 0x29c8280
2011-06-03 07:29:47.731950 7fb48864f700 osd0 40 _dispatch 0x29a2180 ping v1
2011-06-03 07:29:47.731962 7fb48864f700 osd0 40 ping from client1720602
2011-06-03 07:29:47.892813 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:47.892852 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:47.892765 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:47.892861 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:47.916546 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720518 192.168.100.2:0/1005545 4 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2780 con 0x29c8dc0
2011-06-03 07:29:47.916567 7fb48864f700 osd0 40 _dispatch 0x29a2780 ping v1
2011-06-03 07:29:47.916579 7fb48864f700 osd0 40 ping from client1720518
2011-06-03 07:29:48.191510 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:48.191570 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = yes
2011-06-03 07:29:48.191584 7fb48ee5c700 osd0 40 sched_scrub
2011-06-03 07:29:48.191591 7fb48ee5c700 osd0 40 sched_scrub done
2011-06-03 07:29:48.289186 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720510 192.168.100.2:0/1031296 4 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2c00 con 0x29c8b40
2011-06-03 07:29:48.289207 7fb48864f700 osd0 40 _dispatch 0x29a2c00 ping v1
2011-06-03 07:29:48.289219 7fb48864f700 osd0 40 ping from client1720510
2011-06-03 07:29:48.559678 7fb48ce58700 filestore(/data/osd0) sync_entry woke after 5.000127
2011-06-03 07:29:48.559701 7fb48ce58700 journal commit_start op_seq 555725, applied_seq 555725, committed_seq 555725
2011-06-03 07:29:48.559713 7fb48ce58700 journal commit_start nothing to do
2011-06-03 07:29:48.559722 7fb48ce58700 journal commit_start
2011-06-03 07:29:48.559730 7fb48ce58700 filestore(/data/osd0) sync_entry waiting for max_interval 5.000000
2011-06-03 07:29:48.696727 7fb48864f700 -- 192.168.100.7:6801/20872 <== client1720350 192.168.100.2:0/1017516 5 ==== ping v1 ==== 0+0+0 (0 0 0) 0x29a2d80 con 0x29b6c80
2011-06-03 07:29:48.696746 7fb48864f700 osd0 40 _dispatch 0x29a2d80 ping v1
2011-06-03 07:29:48.696754 7fb48864f700 osd0 40 ping from client1720350
2011-06-03 07:29:48.993060 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:48.993092 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:48.993012 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:48.993101 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:48.993108 7fb484546700 osd0 40 i have no heartbeat peers; checking mon for new map
2011-06-03 07:29:48.993128 7fb484546700 -- 192.168.100.7:6801/20872 --> 192.168.100.7:6789/0 -- mon_subscribe({monmap=2+,osdmap=41}) v1 -- ?+0 0x29bb380 con 0x29b5280
2011-06-03 07:29:48.993581 7fb48864f700 -- 192.168.100.7:6801/20872 <== mon0 192.168.100.7:6789/0 9 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (2684212871 0 0) 0x29a2300 con 0x29b5280
2011-06-03 07:29:49.191739 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:49.191798 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = no, randomly backing off
2011-06-03 07:29:49.191813 7fb48ee5c700 osd0 40 do_mon_report
2011-06-03 07:29:49.191820 7fb48ee5c700 osd0 40 send_alive up_thru currently 0 want 0
2011-06-03 07:29:49.191827 7fb48ee5c700 osd0 40 send_pg_stats
2011-06-03 07:29:50.093324 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:50.093356 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:50.093276 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:50.093365 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:50.191951 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:50.192009 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = no, randomly backing off
2011-06-03 07:29:50.693552 7fb484546700 osd0 40 update_osd_stat osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:50.693584 7fb484546700 osd0 40 heartbeat: stat(2011-06-03 07:2:50.693504 oprate=0 qlen=0 recent_qlen=0 rdlat=0 / 0 fshedin=0)
2011-06-03 07:29:50.693592 7fb484546700 osd0 40 heartbeat: osd_stat(15149 MB used, 131 GB avail, 146 GB total, peers []/[])
2011-06-03 07:29:51.192165 7fb48ee5c700 osd0 40 tick
2011-06-03 07:29:51.192225 7fb48ee5c700 osd0 40 scrub_should_schedule loadavg 0 < max 0.5 = no, randomly backing off
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment