bi-list-osd-log.txt

gistfile1.txt

2018-02-06 23:41:38.298212 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:41:40.298325 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:41:42.298401 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:41:44.298531 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:41:46.298670 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:41:48.298812 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:41:50.298897 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:41:52.298983 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:41:54.299063 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:41:56.299197 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:41:58.299331 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:42:00.299469 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:42:02.299569 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:42:04.299654 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:42:06.041129 7fd53082c700 20 osd.767 op_wq(1) _process 5.2572 item PGQueueable(0x55c760865200 prio 63 cost 28 e1289584) queued
2018-02-06 23:42:06.041160 7fd53082c700 20 osd.767 op_wq(1) _process 5.2572 item PGQueueable(0x55c760865200 prio 63 cost 28 e1289584) pg 0x55c75792e000
2018-02-06 23:42:06.041164 7fd53082c700 10 osd.767 1289584 dequeue_op 0x55c760865200 prio 63 cost 28 latency 0.000131 osd_op(client.508909870.0:73 5.2572 5.9c102572 (undecoded) ondisk+read+known_if_redirected e1289584) v8 pg pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean]
2018-02-06 23:42:06.041189 7fd53082c700 20 osd.767 1289584 share_map client.508909870 [REDACTED-SUBNET::5752]:0/1595815216 1289584
2018-02-06 23:42:06.041198 7fd53082c700 20 osd.767 1289584 should_share_map client.508909870 [REDACTED-SUBNET::5752]:0/1595815216 1289584
2018-02-06 23:42:06.041208 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] _handle_message: 0x55c760865200
2018-02-06 23:42:06.041230 7fd53082c700 20 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_op: op osd_op(client.508909870.0:73 5.2572 5:4ea40839:::.dir.default.108827874.21752:head [call rgw.bi_list] snapc 0=[] ondisk+read+known_if_redirected e1289584) v8
2018-02-06 23:42:06.041252 7fd53082c700 10 osd.767 1289584 class rgw method bi_list flags=r
2018-02-06 23:42:06.041257 7fd53082c700 20 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] op_has_sufficient_caps session=0x55c75e1a7c00 pool=5 (.rgw.data.1 ) owner=18446744073709551615 need_read_cap=0 need_write_cap=0 classes=[class rgw rd 1 wr 0 wl 1] -> yes
2018-02-06 23:42:06.041277 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_op osd_op(client.508909870.0:73 5.2572 5:4ea40839:::.dir.default.108827874.21752:head [call rgw.bi_list] snapc 0=[] ondisk+read+known_if_redirected e1289584) v8 may_read -> read-ordered flags ondisk+read+known_if_redirected
2018-02-06 23:42:06.041300 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] get_object_context: found obc in cache: 0x55c75ed55340
2018-02-06 23:42:06.041311 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] get_object_context: 0x55c75ed55340 5:4ea40839:::.dir.default.108827874.21752:head rwstate(none n=0 w=0) oi: 5:4ea40839:::.dir.default.108827874.21752:head(820185'130593 osd.719.0:99447 data_digest|omap_digest s 0 uv 67597 dd ffffffff od 24d4531b alloc_hint [0 0 0]) exists: 1 ssc: 0x55c75db09e60 snapset: 0=[]:{}
2018-02-06 23:42:06.041329 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] find_object_context 5:4ea40839:::.dir.default.108827874.21752:head @head oi=5:4ea40839:::.dir.default.108827874.21752:head(820185'130593 osd.719.0:99447 data_digest|omap_digest s 0 uv 67597 dd ffffffff od 24d4531b alloc_hint [0 0 0])
2018-02-06 23:42:06.041349 7fd53082c700 20 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_op obc obc(5:4ea40839:::.dir.default.108827874.21752:head rwstate(read n=1 w=0))
2018-02-06 23:42:06.041361 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] execute_ctx 0x55c751552700
2018-02-06 23:42:06.041372 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] execute_ctx 5:4ea40839:::.dir.default.108827874.21752:head [call rgw.bi_list] ov 820185'130593
2018-02-06 23:42:06.041385 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean]  taking ondisk_read_lock
2018-02-06 23:42:06.041396 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op 5:4ea40839:::.dir.default.108827874.21752:head [call rgw.bi_list]
2018-02-06 23:42:06.041406 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op  call rgw.bi_list
2018-02-06 23:42:06.041415 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] call method rgw.bi_list
2018-02-06 23:42:06.041432 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op 5:4ea40839:::.dir.default.108827874.21752:head [omap-get-vals]
2018-02-06 23:42:06.041445 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op  omap-get-vals
2018-02-06 23:42:06.041461 7fd53082c700 20 <cls> /tmp/release/Ubuntu/WORKDIR/ceph-12.2.2-353-g8b8b388/src/cls/rgw/cls_rgw.cc:2512: found 0 plain entries
2018-02-06 23:42:06.041467 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op 5:4ea40839:::.dir.default.108827874.21752:head [omap-get-vals-by-keys]
2018-02-06 23:42:06.041477 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op  omap-get-vals-by-keys
2018-02-06 23:42:06.041491 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op 5:4ea40839:::.dir.default.108827874.21752:head [omap-get-vals]
2018-02-06 23:42:06.041502 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op  omap-get-vals
2018-02-06 23:42:06.041517 7fd53082c700 20 <cls> /tmp/release/Ubuntu/WORKDIR/ceph-12.2.2-353-g8b8b388/src/cls/rgw/cls_rgw.cc:2365: list_instance_entries(): start_key=�1000_ first_instance_idx=�1000_\u0000i keys.size()=0
2018-02-06 23:42:06.041520 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op 5:4ea40839:::.dir.default.108827874.21752:head [omap-get-vals-by-keys]
2018-02-06 23:42:06.041529 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op  omap-get-vals-by-keys
2018-02-06 23:42:06.041538 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op 5:4ea40839:::.dir.default.108827874.21752:head [omap-get-vals]
2018-02-06 23:42:06.041548 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op  omap-get-vals
2018-02-06 23:42:06.041558 7fd53082c700 20 <cls> /tmp/release/Ubuntu/WORKDIR/ceph-12.2.2-353-g8b8b388/src/cls/rgw/cls_rgw.cc:2441: list_olh_entries(): start_key=�1001_ first_instance_idx=�1001_ keys.size()=0
2018-02-06 23:42:06.041562 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] method called response length=11
2018-02-06 23:42:06.041573 7fd53082c700 10 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean]  dropping ondisk_read_lock
2018-02-06 23:42:06.041586 7fd53082c700 15 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] do_osd_op_effects client.508909870 con 0x55c74fea7000
2018-02-06 23:42:06.041602 7fd53082c700 15 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] log_op_stats osd_op(client.508909870.0:73 5.2572 5:4ea40839:::.dir.default.108827874.21752:head [call rgw.bi_list] snapc 0=[] ondisk+read+known_if_redirected e1289584) v8 inb 0 outb 11 lat 0.000567
2018-02-06 23:42:06.041619 7fd53082c700 15 osd.767 pg_epoch: 1289584 pg[5.2572( v 1289575'392565 (1287681'391046,1289575'392565] local-lis/les=1289580/1289582 n=39729 ec=22869/22869 lis/c 1289580/1289580 les/c/f 1289582/1289582/0 1289580/1289580/1289580) [767,1500,1347] r=0 lpr=1289580 crt=1289575'392565 lcod 0'0 mlcod 0'0 active+clean] publish_stats_to_osd 1289584:1514184
2018-02-06 23:42:06.041660 7fd53082c700 10 osd.767 1289584 dequeue_op 0x55c760865200 finish
2018-02-06 23:42:06.041685 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting
2018-02-06 23:42:08.041773 7fd53082c700 20 osd.767 op_wq(1) _process empty q, waiting