Project

General

Profile

Bug #23811 ยป slow_rados_object_osd_log.txt

Vaibhav Bhembre, 04/20/2018 05:28 PM

 
# cat ceph-osd.15.log | grep '963088.1.10'
2018-04-20 16:35:53.775454 7f2808e09700 20 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] do_op: op osd_op(client.3997533.0:1 79.1f9 79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head [stat] snapc 0=[] ondisk+read+known_if_redirected e48489) v8
2018-04-20 16:35:53.775483 7f2808e09700 10 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] do_op osd_op(client.3997533.0:1 79.1f9 79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head [stat] snapc 0=[] ondisk+read+known_if_redirected e48489) v8 may_read -> read-ordered flags ondisk+read+known_if_redirected
2018-04-20 16:35:53.775504 7f2808e09700 10 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] get_object_context: 0x7f28a9c6f700 79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head rwstate(none n=0 w=0) oi: 79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head(20058'1496630 client.1007746.0:527366 dirty|omap|data_digest s 0 uv 1496630 dd ffffffff alloc_hint [0 0 0]) exists: 1 ssc: 0x7f28e00ee000 snapset: 0=[]:{}
2018-04-20 16:35:53.775517 7f2808e09700 10 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] find_object_context 79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head @head oi=79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head(20058'1496630 client.1007746.0:527366 dirty|omap|data_digest s 0 uv 1496630 dd ffffffff alloc_hint [0 0 0])
2018-04-20 16:35:53.775529 7f2808e09700 25 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] do_op oi 79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head(20058'1496630 client.1007746.0:527366 dirty|omap|data_digest s 0 uv 1496630 dd ffffffff alloc_hint [0 0 0])
2018-04-20 16:35:53.775538 7f2808e09700 20 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] do_op obc obc(79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head rwstate(read n=1 w=0))
2018-04-20 16:35:53.775554 7f2808e09700 10 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] execute_ctx 79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head [stat] ov 20058'1496630
2018-04-20 16:35:53.775573 7f2808e09700 10 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] do_osd_op 79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head [stat]
2018-04-20 16:35:53.775612 7f2808e09700 15 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] log_op_stats osd_op(client.3997533.0:1 79.1f9 79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head [stat] snapc 0=[] ondisk+read+known_if_redirected e48489) v8 inb 0 outb 16 lat 3.513081


# cat ceph-osd.15.log | grep '0x7f28a6c84400'
2018-04-20 16:35:50.262536 7f28828b9700 15 osd.15 48489 enqueue_op 0x7f28a6c84400 prio 63 cost 0 latency 0.000005 epoch 48489 osd_op(client.3997533.0:1 79.1f9 79.29d01df9 (undecoded) ondisk+read+known_if_redirected e48489) v8
2018-04-20 16:35:50.262542 7f28828b9700 20 osd.15 op_wq(1) _enqueue 79.1f9 PGQueueable(0x7f28a6c84400 prio 63 cost 0 e48489)
2018-04-20 16:35:53.775399 7f2808e09700 20 osd.15 op_wq(1) _process 79.1f9 item PGQueueable(0x7f28a6c84400 prio 63 cost 0 e48489) queued
2018-04-20 16:35:53.775409 7f2808e09700 30 osd.15 op_wq(1) _process 79.1f9 to_process PGQueueable(0x7f28a6c84400 prio 63 cost 0 e48489) waiting_for_pg=0
2018-04-20 16:35:53.775411 7f2808e09700 20 osd.15 op_wq(1) _process 79.1f9 item PGQueueable(0x7f28a6c84400 prio 63 cost 0 e48489) pg 0x7f28b8c10000
2018-04-20 16:35:53.775428 7f2808e09700 10 osd.15 48489 dequeue_op 0x7f28a6c84400 prio 63 cost 0 latency 3.512898 osd_op(client.3997533.0:1 79.1f9 79.29d01df9 (undecoded) ondisk+read+known_if_redirected e48489) v8 pg pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean]
2018-04-20 16:35:53.775443 7f2808e09700 10 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] _handle_message: 0x7f28a6c84400
2018-04-20 16:35:53.775637 7f2808e09700 10 osd.15 48489 dequeue_op 0x7f28a6c84400 finish


# cat ceph-osd.15.log | grep 'client.3997533.0'
2018-04-20 16:35:50.262536 7f28828b9700 15 osd.15 48489 enqueue_op 0x7f28a6c84400 prio 63 cost 0 latency 0.000005 epoch 48489 osd_op(client.3997533.0:1 79.1f9 79.29d01df9 (undecoded) ondisk+read+known_if_redirected e48489) v8
2018-04-20 16:35:53.775428 7f2808e09700 10 osd.15 48489 dequeue_op 0x7f28a6c84400 prio 63 cost 0 latency 3.512898 osd_op(client.3997533.0:1 79.1f9 79.29d01df9 (undecoded) ondisk+read+known_if_redirected e48489) v8 pg pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean]
2018-04-20 16:35:53.775454 7f2808e09700 20 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] do_op: op osd_op(client.3997533.0:1 79.1f9 79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head [stat] snapc 0=[] ondisk+read+known_if_redirected e48489) v8
2018-04-20 16:35:53.775483 7f2808e09700 10 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] do_op osd_op(client.3997533.0:1 79.1f9 79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head [stat] snapc 0=[] ondisk+read+known_if_redirected e48489) v8 may_read -> read-ordered flags ondisk+read+known_if_redirected
2018-04-20 16:35:53.775612 7f2808e09700 15 osd.15 pg_epoch: 48489 pg[79.1f9( v 48489'6739320 (48150'6736227,48489'6739320] local-lis/les=46777/46780 n=471 ec=4179/4179 lis/c 46777/46777 les/c/f 46780/46781/0 46777/46777/45005) [15,3,7] r=0 lpr=46777 crt=48489'6739320 lcod 48489'6739319 mlcod 48489'6739319 active+clean] log_op_stats osd_op(client.3997533.0:1 79.1f9 79:9fb80b94:::.dir.76bcb3c5-9015-4817-8e0b-9ec86fa9a561.963088.1.10:head [stat] snapc 0=[] ondisk+read+known_if_redirected e48489) v8 inb 0 outb 16 lat 3.513081
    (1-1/1)