Re: OSD's slow down to a crawl

[Mark Nelson <mark.nelson@xxxxxxxxxxx>]

On 12/20/2012 09:16 AM, Matthew Anderson wrote:
> Hi All,
>
> I've run into an issue where OSD's slow right down to the point that they no longer appear to be processing write IO and everything grinds to a halt. Once they've stopped performing IO they can be brought back to life by restarting them where they continue on for a while before they slow down again and eventually everything stops again. I'm at a total loss to explain the issue because everything appears to be working correctly yet something is clearly very wrong. Running 'ceph -w' reports everything as clean+active and there are never any slow requests logged.
>
> The problem appears to be more pronounced on the newer 3.7 kernel but happened on previous versions in the same fashion. Weird things like OSD's never completing recovery until they are restarted was also happening occasionally. The cluster would be stuck on a certain percentage degraded and restarting the OSD 3-4 times would eventually see it heal itself with the degraded percentage dropping a little each time. I'm testing with both the kernel CephFS client and QEMU 1.3.0 accessing an RBD, both slow down to a stop in the same manner.
>
> Kernel 3.7.0 mainline (also occurs on 3.7.1 and 3.6.8)
> Ceph version 0.55.1-300-g08c6424 (08c64249eb8cd7922de5c398a9426538918db77c) 	(also occurs on 0.55 and 0.55.1)
> Total of 3 hosts. Two of them with 4 OSD's on an SSD each. The other with 24x 2TB SATA drives. Each host is running a monitor. I have setup two pools in the CRUSHMAP, one for SATA and one for SSD. Both pools have the same problem.
>
> OSD config:
> [osd.24]
>          host = KVM04
>          osd data = /srv/ceph/osd/$name
>          btrfs devs = /dev/sda2
>          btrfs options = rw,noatime,ssd
>          osd journal = /dev/sda1
>
> The log below is when the OSD has stopped processing IO and was then shutdown cleanly. The QEMU guest was partially responsive but the benchmark had frozen waiting for IO to complete.
>
> If I can do anymore debugging to help diagnose the problem please let me know.

Hi Matt,

Yeah, your log is looking pretty sparse!  I imagine Sam will have a lot 
of questions for you.  Out of curiosity have you looked at any 
io/cpu/memory stats when things slow down?  sysprof may come in handy if 
it looks like it's CPU related.  Also, check out the OSD admin socket. 
Sebastien Han made a nice little blog entry describing it:

http://www.sebastien-han.fr/blog/2012/08/14/ceph-admin-socket/

You can get a lot of information about the current state of things.

Mark

> Thanks
> -Matt
> -------------------------------------
>
> 2012-12-20 22:18:06.809863 7fb9e4ff9700 20 journal write_thread_entry aio throttle: aio num 0 bytes 0 ... exp 0 min_new 1 ... pending 5748
> 2012-12-20 22:18:06.809871 7fb9e4ff9700 10 journal room 960479231 max_size 960495616 pos 543215616 header.start 543203328 top 4096
> 2012-12-20 22:18:06.809877 7fb9e4ff9700 10 journal check_for_full at 543215616 : 8192 < 960479231
> 2012-12-20 22:18:06.809880 7fb9e4ff9700 15 journal prepare_single_write 1 will write 543215616 : seq 2087065 len 5748 -> 8192 (head 40 pre_pad 0 ebl 5748 post_pad 2364 tail 40) (ebl alignment -1)
> 2012-12-20 22:18:06.809891 7fb9d57fa700 10 journal op_apply_start 2087065 open_ops 0 -> 1
> 2012-12-20 22:18:06.809897 7fb9d57fa700  5 filestore(/srv/ceph/osd/osd.24) _do_op 0x7fb9b4376570 seq 2087065 osr(6.1fe3 0x21a4f50)/0x21a4f50 start
> 2012-12-20 22:18:06.809901 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) _do_transaction on 0x7fb9b4f5db40
> 2012-12-20 22:18:06.809915 7fb9d57fa700 15 filestore(/srv/ceph/osd/osd.24) write meta/a4c1c2a3/pglog_6.1fe3/0//-1 147735~147
> 2012-12-20 22:18:06.809947 7fb9e4ff9700 20 journal prepare_multi_write queue_pos now 543223808
> 2012-12-20 22:18:06.809953 7fb9e4ff9700 15 journal do_aio_write writing 543215616~8192
> 2012-12-20 22:18:06.809975 7fb9e4ff9700 20 journal write_aio_bl 543215616~8192 seq 2087065
> 2012-12-20 22:18:06.809981 7fb9e4ff9700 20 journal write_aio_bl .. 543215616~8192 in 1
> 2012-12-20 22:18:06.810051 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) write meta/a4c1c2a3/pglog_6.1fe3/0//-1 147735~147 = 147
> 2012-12-20 22:18:06.810065 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) collection_setattr /srv/ceph/osd/osd.24/current/6.1fe3_head 'ondisklog' len 34
> 2012-12-20 22:18:06.810068 7fb9e4ff9700  5 journal put_throttle finished 1 ops and 5748 bytes, now 0 ops and 0 bytes
> 2012-12-20 22:18:06.810077 7fb9e4ff9700 20 journal write_thread_entry going to sleep
> 2012-12-20 22:18:06.810103 7fb9d7fff700 20 journal write_finish_thread_entry waiting for aio(s)
> 2012-12-20 22:18:06.810149 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) collection_setattr /srv/ceph/osd/osd.24/current/6.1fe3_head 'ondisklog' len 34 = 34
> 2012-12-20 22:18:06.810159 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) collection_setattr /srv/ceph/osd/osd.24/current/6.1fe3_head 'info' len 5
> 2012-12-20 22:18:06.810191 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) collection_setattr /srv/ceph/osd/osd.24/current/6.1fe3_head 'info' len 5 = 5
> 2012-12-20 22:18:06.810198 7fb9d57fa700 15 filestore(/srv/ceph/osd/osd.24) truncate meta/8dfefeef/pginfo_6.1fe3/0//-1 size 0
> 2012-12-20 22:18:06.810307 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) truncate meta/8dfefeef/pginfo_6.1fe3/0//-1 size 0 = 0
> 2012-12-20 22:18:06.810317 7fb9d57fa700 15 filestore(/srv/ceph/osd/osd.24) write meta/8dfefeef/pginfo_6.1fe3/0//-1 0~504
> 2012-12-20 22:18:06.810386 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) write meta/8dfefeef/pginfo_6.1fe3/0//-1 0~504 = 504
> 2012-12-20 22:18:06.810394 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) _do_transaction on 0x7fb9b4f5dab8
> 2012-12-20 22:18:06.810399 7fb9d57fa700 15 filestore(/srv/ceph/osd/osd.24) write 6.1fe3_head/42463fe3/rb.0.122c.6b8b4567.000000000357/head//6 3522560~4096
> 2012-12-20 22:18:06.810451 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) write 6.1fe3_head/42463fe3/rb.0.122c.6b8b4567.000000000357/head//6 3522560~4096 = 4096
> 2012-12-20 22:18:06.810497 7fb9d57fa700 15 filestore(/srv/ceph/osd/osd.24) setattrs 6.1fe3_head/42463fe3/rb.0.122c.6b8b4567.000000000357/head//6
> 2012-12-20 22:18:06.810576 7fb9d7fff700 10 journal write_finish_thread_entry aio 543215616~8192 done
> 2012-12-20 22:18:06.810588 7fb9d7fff700 20 journal check_aio_completion
> 2012-12-20 22:18:06.810590 7fb9d7fff700 20 journal check_aio_completion completed seq 2087065 543215616~8192
> 2012-12-20 22:18:06.810594 7fb9d7fff700 20 journal check_aio_completion queueing finishers through seq 2087065
> 2012-12-20 22:18:06.810596 7fb9d7fff700 10 journal queue_completions_thru seq 2087065 queueing seq 2087065 0x7fb9b4f70ac0 lat 0.000761
> 2012-12-20 22:18:06.810631 7fb9d7fff700 20 journal write_finish_thread_entry sleeping
> 2012-12-20 22:18:06.810695 7fb9d5ffb700 10 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 luod=3473'23688 lcod 3473'23688 mlcod 3473'23687 active+clean] op_commit repgather(0x7fb9b47d1050 applying 3473'23689 rep_tid=72 wfack=24,31 wfdisk=24,31 op=osd_op(client.7636.0:100075 rb.0.122c.6b8b4567.000000000357 [write 3522560~4096] 6.42463fe3) v4)
> 2012-12-20 22:18:06.810720 7fb9d5ffb700 10 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean] eval_repop repgather(0x7fb9b47d1050 applying 3473'23689 rep_tid=72 wfack=31 wfdisk=31 op=osd_op(client.7636.0:100075 rb.0.122c.6b8b4567.000000000357 [write 3522560~4096] 6.42463fe3) v4) wants=ad
> 2012-12-20 22:18:06.810992 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) setattrs 6.1fe3_head/42463fe3/rb.0.122c.6b8b4567.000000000357/head//6 = 230
> 2012-12-20 22:18:06.811053 7fb9d57fa700 15 filestore(/srv/ceph/osd/osd.24) setattrs 6.1fe3_head/42463fe3/rb.0.122c.6b8b4567.000000000357/head//6
> 2012-12-20 22:18:06.811083 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) setattrs 6.1fe3_head/42463fe3/rb.0.122c.6b8b4567.000000000357/head//6 = 31
> 2012-12-20 22:18:06.811093 7fb9d57fa700 10 journal op_apply_finish 2087065 open_ops 1 -> 0, max_applied_seq 2087064 -> 2087065
> 2012-12-20 22:18:06.811096 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) _do_op 0x7fb9b4376570 seq 2087065 r = 0, finisher 0x7fb9b5022bb0 0x7fb9b483ce10
> 2012-12-20 22:18:06.811100 7fb9d57fa700 10 filestore(/srv/ceph/osd/osd.24) _finish_op 0x7fb9b4376570 seq 2087065 osr(6.1fe3 0x21a4f50)/0x21a4f50
> 2012-12-20 22:18:06.811136 7fb9c37fe700 10 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean] op_applied repgather(0x7fb9b47d1050 applying 3473'23689 rep_tid=72 wfack=31 wfdisk=31 op=osd_op(client.7636.0:100075 rb.0.122c.6b8b4567.000000000357 [write 3522560~4096] 6.42463fe3) v4)
> 2012-12-20 22:18:06.811205 7fb9c37fe700 10 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean] op_applied mode was rmw(wr=1)
> 2012-12-20 22:18:06.811218 7fb9c37fe700 10 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean] op_applied mode now idle(wr=0 WAKE) (finish_write)
> 2012-12-20 22:18:06.811229 7fb9c37fe700 10 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean] put_object_context 0x7fb9b5248020 42463fe3/rb.0.122c.6b8b4567.000000000357/head//6 1 -> 0
> 2012-12-20 22:18:06.811241 7fb9c37fe700 15 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean]  requeue_ops
> 2012-12-20 22:18:06.811251 7fb9c37fe700 10 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean] put_snapset_context rb.0.122c.6b8b4567.000000000357 1 -> 0
> 2012-12-20 22:18:06.811267 7fb9c37fe700 10 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean] eval_repop repgather(0x7fb9b47d1050 applied 3473'23689 rep_tid=72 wfack=31 wfdisk=31 op=osd_op(client.7636.0:100075 rb.0.122c.6b8b4567.000000000357 [write 3522560~4096] 6.42463fe3) v4) wants=ad
> 2012-12-20 22:18:06.813738 7fb9c0ff9700 20 osd.24 3473 _dispatch 0x7fb9600008f0 osd_sub_op_reply(client.7636.0:100075 6.1fe3 42463fe3/rb.0.122c.6b8b4567.000000000357/head//6 [] ondisk, result = 0) v1
> 2012-12-20 22:18:06.813850 7fb9c0ff9700 15 osd.24 3473 require_same_or_newer_map 3473 (i am 3473) 0x7fb9600008f0
> 2012-12-20 22:18:06.813856 7fb9c0ff9700 20 osd.24 3473 _share_map_incoming osd.31 172.16.0.12:6820/2871 3473
> 2012-12-20 22:18:06.813865 7fb9c0ff9700 15 osd.24 3473 enqueue_op 0x7fb968055650 osd_sub_op_reply(client.7636.0:100075 6.1fe3 42463fe3/rb.0.122c.6b8b4567.000000000357/head//6 [] ondisk,
> result= 0) v1
> 2012-12-20 22:18:06.813934 7fb9bd7f2700 10 osd.24 3473 dequeue_op 0x7fb968055650 osd_sub_op_reply(client.7636.0:100075 6.1fe3 42463fe3/rb.0.122c.6b8b4567.000000000357/head//6 [] ondisk, result = 0) v1 pg pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean]
> 2012-12-20 22:18:06.814005 7fb9bd7f2700  7 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean] repop_ack rep_tid 72 op osd_op(client.7636.0:100075 rb.0.122c.6b8b4567.000000000357 [write 3522560~4096] 6.42463fe3) v4 result 0 ack_type 4 from osd.31
> 2012-12-20 22:18:06.814037 7fb9bd7f2700 10 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean] eval_repop repgather(0x7fb9b47d1050 applied 3473'23689 rep_tid=72 wfack= wfdisk= op=osd_op(client.7636.0:100075 rb.0.122c.6b8b4567.000000000357 [write 3522560~4096] 6.42463fe3) v4) wants=ad
> 2012-12-20 22:18:06.814057 7fb9bd7f2700 15 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean] log_op_stats osd_op(client.7636.0:100075 rb.0.122c.6b8b4567.000000000357 [write 3522560~4096] 6.42463fe3) v4 inb 4239 outb 0 rlat 0.000000 lat 0.005594
> 2012-12-20 22:18:06.814075 7fb9bd7f2700 15 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean] update_stats 3465'46631
> 2012-12-20 22:18:06.814088 7fb9bd7f2700 10 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23687 active+clean]  sending commit on repgather(0x7fb9b47d1050 applied 3473'23689 rep_tid=72 wfack= wfdisk= op=osd_op(client.7636.0:100075 rb.0.122c.6b8b4567.000000000357 [write 3522560~4096] 6.42463fe3) v4) 0x7fb9b4605310
> 2012-12-20 22:18:06.814122 7fb9bd7f2700 10 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23688 active+clean]  removing repgather(0x7fb9b47d1050 applied 3473'23689 rep_tid=72 wfack= wfdisk= op=osd_op(client.7636.0:100075 rb.0.122c.6b8b4567.000000000357 [write 3522560~4096] 6.42463fe3) v4)
> 2012-12-20 22:18:06.814147 7fb9bd7f2700 20 osd.24 pg_epoch: 3473 pg[6.1fe3( v 3473'23689 (3247'22688,3473'23689] local-les=3472 n=12 ec=656 les/c 3472/3473 3465/3465/3465) [24,31] r=0 lpr=3465 mlcod 3473'23688 active+clean]    q front is repgather(0x7fb9b47d1050 applied 3473'23689 rep_tid=72 wfack= wfdisk= op=osd_op(client.7636.0:100075 rb.0.122c.6b8b4567.000000000357 [write 3522560~4096] 6.42463fe3) v4)
> 2012-12-20 22:18:06.814204 7fb9bd7f2700 10 osd.24 3473 dequeue_op 0x7fb968055650 finish
> 2012-12-20 22:18:07.030914 7fb9be7f4700 10 monclient: tick
> 2012-12-20 22:18:07.030929 7fb9be7f4700 10 monclient: _check_auth_rotating renewing rotating keys (they expired before 2012-12-20 22:17:37.030927)
> 2012-12-20 22:18:07.030952 7fb9be7f4700 10 monclient: renew subs? (now: 2012-12-20 22:18:07.030952; renew after: 2012-12-20 22:18:33.322998) -- no
> 2012-12-20 22:18:07.172960 7fb9bafed700 20 osd.24 3473 update_osd_stat osd_stat(21111 MB used, 393 GB avail, 431 GB total, peers [28,29,30,31]/[])
> 2012-12-20 22:18:07.172979 7fb9bafed700  5 osd.24 3473 heartbeat: osd_stat(21111 MB used, 393 GB avail, 431 GB total, peers [28,29,30,31]/[])
> 2012-12-20 22:18:07.173647 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9b400d440 already has epoch 3473
> 2012-12-20 22:18:07.173675 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a002f010 already has epoch 3473
> 2012-12-20 22:18:07.173785 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a00334d0 already has epoch 3473
> 2012-12-20 22:18:07.173875 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a0033fc0 already has epoch 3473
> 2012-12-20 22:18:07.479259 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:07.479311 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 6.36 >= max 0.5 = no, load too high
> 2012-12-20 22:18:07.479326 7fb9e6ffd700  7 osd.24 3473 do_mon_report
> 2012-12-20 22:18:07.479329 7fb9e6ffd700 10 osd.24 3473 send_alive up_thru currently 3465 want 3465
> 2012-12-20 22:18:07.479331 7fb9e6ffd700 20 osd.24 3473 send_pg_stats
> 2012-12-20 22:18:07.479334 7fb9e6ffd700 10 osd.24 3473 send_pg_stats - 2 pgs updated
> 2012-12-20 22:18:07.479343 7fb9e6ffd700 10 monclient: _send_mon_message to mon.KVM03 at 172.16.0.12:6789/0
> 2012-12-20 22:18:07.774794 7fb9bf7f6700 20 osd.24 3473 _share_map_outgoing 0x7fb9a002f010 already has epoch 3473
> 2012-12-20 22:18:07.809251 7fb9e57fa700 20 filestore(/srv/ceph/osd/osd.24) sync_entry woke after 5.000117
> 2012-12-20 22:18:07.809274 7fb9e57fa700 10 journal commit_start max_applied_seq 2087065, open_ops 0
> 2012-12-20 22:18:07.809278 7fb9e57fa700 10 journal commit_start blocked, all open_ops have completed
> 2012-12-20 22:18:07.809279 7fb9e57fa700 10 journal commit_start committing 2087065, still blocked
> 2012-12-20 22:18:07.809282 7fb9e57fa700 10 journal commit_start
> 2012-12-20 22:18:07.809291 7fb9e57fa700 15 filestore(/srv/ceph/osd/osd.24) sync_entry committing 2087065 sync_epoch 19
> 2012-12-20 22:18:07.809339 7fb9e57fa700 10 filestore(/srv/ceph/osd/osd.24) taking async snap 'snap_2087065'
> 2012-12-20 22:18:07.817045 7fb9e57fa700 20 filestore(/srv/ceph/osd/osd.24) async snap create 'snap_2087065' transid 96549
> 2012-12-20 22:18:07.817060 7fb9e57fa700 10 journal commit_started committing 2087065, unblocking
> 2012-12-20 22:18:07.817069 7fb9e57fa700 20 filestore(/srv/ceph/osd/osd.24)  waiting for transid 96549 to complete
> 2012-12-20 22:18:07.836752 7fb9e57fa700 20 filestore(/srv/ceph/osd/osd.24)  done waiting for transid 96549 to complete
> 2012-12-20 22:18:07.836767 7fb9e57fa700 10 filestore(/srv/ceph/osd/osd.24) sync_entry commit took 0.027482, interval was 5.027633
> 2012-12-20 22:18:07.836775 7fb9e57fa700 10 journal commit_finish thru 2087065
> 2012-12-20 22:18:07.836778 7fb9e57fa700  5 journal committed_thru 2087065 (last_committed_seq 2087063)
> 2012-12-20 22:18:07.836781 7fb9e57fa700 10 journal header: block_size 4096 alignment 4096 max_size 960495616
> 2012-12-20 22:18:07.836783 7fb9e57fa700 10 journal header: start 543223808
> 2012-12-20 22:18:07.836784 7fb9e57fa700 10 journal  write_pos 543223808
> 2012-12-20 22:18:07.836788 7fb9e57fa700 10 journal committed_thru done
> 2012-12-20 22:18:07.836793 7fb9e57fa700 10 filestore(/srv/ceph/osd/osd.24) removing snap 'snap_2087061'
> 2012-12-20 22:18:07.836958 7fb9e57fa700 15 filestore(/srv/ceph/osd/osd.24) sync_entry committed to op_seq 2087065
> 2012-12-20 22:18:07.836972 7fb9e57fa700 20 filestore(/srv/ceph/osd/osd.24) sync_entry waiting for max_interval 5.000000
> 2012-12-20 22:18:07.855890 7fb9bf7f6700 20 osd.24 3473 _share_map_outgoing 0x7fb9a0033fc0 already has epoch 3473
> 2012-12-20 22:18:08.221094 7fb9c1ffb700 20 osd.24 3473 _dispatch 0x7fb990002de0 pg_stats_ack(2 pgs tid 18) v1
> 2012-12-20 22:18:08.221105 7fb9c1ffb700 10 osd.24 3473 handle_pg_stats_ack
> 2012-12-20 22:18:08.479450 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:08.479499 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 6.36 >= max 0.5 = no, load too high
> 2012-12-20 22:18:09.479581 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:09.479633 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 6.36 >= max 0.5 = no, load too high
> 2012-12-20 22:18:10.479743 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:10.479808 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 6.36 >= max 0.5 = no, load too high
> 2012-12-20 22:18:11.273304 7fb9bafed700 20 osd.24 3473 update_osd_stat osd_stat(21111 MB used, 393 GB avail, 431 GB total, peers [28,29,30,31]/[])
> 2012-12-20 22:18:11.273324 7fb9bafed700  5 osd.24 3473 heartbeat: osd_stat(21111 MB used, 393 GB avail, 431 GB total, peers [28,29,30,31]/[])
> 2012-12-20 22:18:11.274018 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9b400d440 already has epoch 3473
> 2012-12-20 22:18:11.274081 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a002f010 already has epoch 3473
> 2012-12-20 22:18:11.274101 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a00334d0 already has epoch 3473
> 2012-12-20 22:18:11.274249 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a0033fc0 already has epoch 3473
> 2012-12-20 22:18:11.275112 7fb9bf7f6700 20 osd.24 3473 _share_map_outgoing 0x7fb9a002f010 already has epoch 3473
> 2012-12-20 22:18:11.356141 7fb9bf7f6700 20 osd.24 3473 _share_map_outgoing 0x7fb9a0033fc0 already has epoch 3473
> 2012-12-20 22:18:11.479927 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:11.479976 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 6.36 >= max 0.5 = no, load too high
> 2012-12-20 22:18:12.182095 7fb9bf7f6700 20 osd.24 3473 _share_map_outgoing 0x7fb9a00334d0 already has epoch 3473
> 2012-12-20 22:18:12.373677 7fb9bafed700 20 osd.24 3473 update_osd_stat osd_stat(21111 MB used, 393 GB avail, 431 GB total, peers [28,29,30,31]/[])
> 2012-12-20 22:18:12.373694 7fb9bafed700  5 osd.24 3473 heartbeat: osd_stat(21111 MB used, 393 GB avail, 431 GB total, peers [28,29,30,31]/[])
> 2012-12-20 22:18:12.374496 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9b400d440 already has epoch 3473
> 2012-12-20 22:18:12.374523 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a002f010 already has epoch 3473
> 2012-12-20 22:18:12.374541 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a00334d0 already has epoch 3473
> 2012-12-20 22:18:12.374564 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a0033fc0 already has epoch 3473
> 2012-12-20 22:18:12.480076 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:12.480125 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 6.09 >= max 0.5 = no, load too high
> 2012-12-20 22:18:12.480140 7fb9e6ffd700  7 osd.24 3473 do_mon_report
> 2012-12-20 22:18:12.480142 7fb9e6ffd700 10 osd.24 3473 send_alive up_thru currently 3465 want 3465
> 2012-12-20 22:18:12.480146 7fb9e6ffd700 20 osd.24 3473 send_pg_stats
> 2012-12-20 22:18:12.701202 7fb9bf7f6700 20 osd.24 3473 _share_map_outgoing 0x7fb9b400d440 already has epoch 3473
> 2012-12-20 22:18:12.837067 7fb9e57fa700 20 filestore(/srv/ceph/osd/osd.24) sync_entry woke after 5.000094
> 2012-12-20 22:18:12.837089 7fb9e57fa700 10 journal commit_start max_applied_seq 2087065, open_ops 0
> 2012-12-20 22:18:12.837093 7fb9e57fa700 10 journal commit_start blocked, all open_ops have completed
> 2012-12-20 22:18:12.837095 7fb9e57fa700 10 journal commit_start nothing to do
> 2012-12-20 22:18:12.837100 7fb9e57fa700 10 journal commit_start
> 2012-12-20 22:18:12.837117 7fb9e57fa700 20 filestore(/srv/ceph/osd/osd.24) sync_entry waiting for max_interval 5.000000
> 2012-12-20 22:18:13.480239 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:13.480289 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 6.09 >= max 0.5 = no, load too high
> 2012-12-20 22:18:14.073917 7fb9bafed700 20 osd.24 3473 update_osd_stat osd_stat(21111 MB used, 393 GB avail, 431 GB total, peers [28,29,30,31]/[])
> 2012-12-20 22:18:14.073935 7fb9bafed700  5 osd.24 3473 heartbeat: osd_stat(21111 MB used, 393 GB avail, 431 GB total, peers [28,29,30,31]/[])
> 2012-12-20 22:18:14.074840 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a0033fc0 already has epoch 3473
> 2012-12-20 22:18:14.074868 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a00334d0 already has epoch 3473
> 2012-12-20 22:18:14.074886 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9b400d440 already has epoch 3473
> 2012-12-20 22:18:14.074903 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a002f010 already has epoch 3473
> 2012-12-20 22:18:14.480386 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:14.480443 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 6.09 >= max 0.5 = no, load too high
> 2012-12-20 22:18:15.480571 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:15.480632 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 6.09 >= max 0.5 = no, load too high
> 2012-12-20 22:18:16.282625 7fb9bf7f6700 20 osd.24 3473 _share_map_outgoing 0x7fb9a00334d0 already has epoch 3473
> 2012-12-20 22:18:16.480714 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:16.480763 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 6.09 >= max 0.5 = no, load too high
> 2012-12-20 22:18:16.801391 7fb9bf7f6700 20 osd.24 3473 _share_map_outgoing 0x7fb9b400d440 already has epoch 3473
> 2012-12-20 22:18:17.031056 7fb9be7f4700 10 monclient: tick
> 2012-12-20 22:18:17.031082 7fb9be7f4700 10 monclient: _check_auth_rotating renewing rotating keys (they expired before 2012-12-20 22:17:47.031080)
> 2012-12-20 22:18:17.031124 7fb9be7f4700 10 monclient: renew subs? (now: 2012-12-20 22:18:17.031124; renew after: 2012-12-20 22:18:33.322998) -- no
> 2012-12-20 22:18:17.175266 7fb9bf7f6700 20 osd.24 3473 _share_map_outgoing 0x7fb9a002f010 already has epoch 3473
> 2012-12-20 22:18:17.256256 7fb9bf7f6700 20 osd.24 3473 _share_map_outgoing 0x7fb9a0033fc0 already has epoch 3473
> 2012-12-20 22:18:17.480898 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:17.480952 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 5.84 >= max 0.5 = no, load too high
> 2012-12-20 22:18:17.480969 7fb9e6ffd700  7 osd.24 3473 do_mon_report
> 2012-12-20 22:18:17.480972 7fb9e6ffd700 10 osd.24 3473 send_alive up_thru currently 3465 want 3465
> 2012-12-20 22:18:17.480975 7fb9e6ffd700 20 osd.24 3473 send_pg_stats
> 2012-12-20 22:18:17.837232 7fb9e57fa700 20 filestore(/srv/ceph/osd/osd.24) sync_entry woke after 5.000116
> 2012-12-20 22:18:17.837254 7fb9e57fa700 10 journal commit_start max_applied_seq 2087065, open_ops 0
> 2012-12-20 22:18:17.837258 7fb9e57fa700 10 journal commit_start blocked, all open_ops have completed
> 2012-12-20 22:18:17.837260 7fb9e57fa700 10 journal commit_start nothing to do
> 2012-12-20 22:18:17.837262 7fb9e57fa700 10 journal commit_start
> 2012-12-20 22:18:17.837271 7fb9e57fa700 20 filestore(/srv/ceph/osd/osd.24) sync_entry waiting for max_interval 5.000000
> 2012-12-20 22:18:18.481073 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:18.481133 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 5.84 >= max 0.5 = no, load too high
> 2012-12-20 22:18:19.481247 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:19.481308 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 5.84 >= max 0.5 = no, load too high
> 2012-12-20 22:18:19.974219 7fb9bafed700 20 osd.24 3473 update_osd_stat osd_stat(21111 MB used, 393 GB avail, 431 GB total, peers [28,29,30,31]/[])
> 2012-12-20 22:18:19.974238 7fb9bafed700  5 osd.24 3473 heartbeat: osd_stat(21111 MB used, 393 GB avail, 431 GB total, peers [28,29,30,31]/[])
> 2012-12-20 22:18:19.974899 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a002f010 already has epoch 3473
> 2012-12-20 22:18:19.975070 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a00334d0 already has epoch 3473
> 2012-12-20 22:18:19.975116 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9a0033fc0 already has epoch 3473
> 2012-12-20 22:18:19.975207 7fb9bfff7700 20 osd.24 3473 _share_map_outgoing 0x7fb9b400d440 already has epoch 3473
> 2012-12-20 22:18:20.481425 7fb9e6ffd700  5 osd.24 3473 tick
> 2012-12-20 22:18:20.481487 7fb9e6ffd700 20 osd.24 3473 scrub_should_schedule loadavg 5.84 >= max 0.5 = no, load too high
> 2012-12-20 22:18:21.016361 7fb9e77fe700 -1 osd.24 3473 *** Got signal Terminated ***
> 2012-12-20 22:18:21.016458 7fb9e77fe700 -1 osd.24 3473  pausing thread pools
> 2012-12-20 22:18:21.016462 7fb9e77fe700 -1 osd.24 3473  flushing io
> 2012-12-20 22:18:21.016464 7fb9e77fe700 10 filestore(/srv/ceph/osd/osd.24) sync_and_flush
> 2012-12-20 22:18:21.016467 7fb9e77fe700 10 filestore(/srv/ceph/osd/osd.24) _flush_op_queue draining op tp
> 2012-12-20 22:18:21.016471 7fb9e77fe700 10 filestore(/srv/ceph/osd/osd.24) _flush_op_queue waiting for apply finisher
> 2012-12-20 22:18:21.016481 7fb9e77fe700 10 filestore(/srv/ceph/osd/osd.24) start_sync
> 2012-12-20 22:18:21.016483 7fb9e77fe700 10 filestore(/srv/ceph/osd/osd.24) sync waiting
> 2012-12-20 22:18:21.016523 7fb9e57fa700 20 filestore(/srv/ceph/osd/osd.24) sync_entry woke after 3.179252
> 2012-12-20 22:18:21.016540 7fb9e57fa700 10 journal commit_start max_applied_seq 2087065, open_ops 0
> 2012-12-20 22:18:21.016543 7fb9e57fa700 10 journal commit_start blocked, all open_ops have completed
> 2012-12-20 22:18:21.016545 7fb9e57fa700 10 journal commit_start nothing to do
> 2012-12-20 22:18:21.016548 7fb9e57fa700 10 journal commit_start
> 2012-12-20 22:18:21.016563 7fb9e57fa700 20 filestore(/srv/ceph/osd/osd.24) sync_entry waiting for max_interval 5.000000
> 2012-12-20 22:18:21.016563 7fb9e77fe700 10 filestore(/srv/ceph/osd/osd.24) sync done
> 2012-12-20 22:18:21.016570 7fb9e77fe700 10 filestore(/srv/ceph/osd/osd.24) sync_and_flush done
> 2012-12-20 22:18:21.016572 7fb9e77fe700 -1 osd.24 3473  removing pid file
> 2012-12-20 22:18:21.016665 7fb9e77fe700 -1 osd.24 3473  exit
>
>
>
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@xxxxxxxxxxxxxxx
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html