Ceph » RADOS

-2632> 2022-04-28T20:32:11.034+0000 7f683a737700 10 osd.0 pg_epoch: 593 pg[3.3bs2( v 547'242 (0'0,547'242] local-lis/les=591/592 n=11 ec=548/21 lis/c=591/548 les/c/f=592/549/0 sis=591) [7,2,0]p7(0) r=2 lpr=591 pi=[548,591)/3 luod=0'0 crt=547'242 lcod 0'0 mlcod 0'0 active mbc={} ps=[35~1,63~1,6b~1,6e~6,76~1,7a~1,7c~3,81~2,84~1,86~3,8a~4,90~3,95~1,97~1,99~1]] append_log log((0'0,547'242], crt=547'242) [593'243 (547'242) clone    3:de28928d:::smithi01883722-15:19e by unknown.0.0:0 2022-04-28T20:30:39.964912+0000 0 snaps [19a,199,193,190,18f,18a,182,17e] ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0,593'244 (547'242) modify   3:de28928d:::smithi01883722-15:head by client.4545.0:5158 2022-04-28T20:31:32.988871+0000 0 ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0]
 -2631> 2022-04-28T20:32:11.034+0000 7f683a737700 10 osd.0 pg_epoch: 593 pg[3.3bs2( v 593'243 (0'0,593'243] local-lis/les=591/592 n=11 ec=548/21 lis/c=591/548 les/c/f=592/549/0 sis=591) [7,2,0]p7(0) r=2 lpr=591 pi=[548,591)/3 luod=0'0 lua=547'242 crt=547'242 lcod 0'0 mlcod 0'0 active mbc={} ps=[35~1,63~1,6b~1,6e~6,76~1,7a~1,7c~3,81~2,84~1,86~3,8a~4,90~3,95~1,97~1,99~1]] add_log_entry 593'243 (547'242) clone    3:de28928d:::smithi01883722-15:19e by unknown.0.0:0 2022-04-28T20:30:39.964912+0000 0 snaps [19a,199,193,190,18f,18a,182,17e] ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
 -2630> 2022-04-28T20:32:11.034+0000 7f683a737700 10 osd.0 pg_epoch: 593 pg[3.3bs2( v 593'244 (0'0,593'244] local-lis/les=591/592 n=11 ec=548/21 lis/c=591/548 les/c/f=592/549/0 sis=591) [7,2,0]p7(0) r=2 lpr=591 pi=[548,591)/3 luod=0'0 lua=547'242 crt=547'242 lcod 0'0 mlcod 0'0 active mbc={} ps=[35~1,63~1,6b~1,6e~6,76~1,7a~1,7c~3,81~2,84~1,86~3,8a~4,90~3,95~1,97~1,99~1]] add_log_entry 593'244 (547'242) modify   3:de28928d:::smithi01883722-15:head by client.4545.0:5158 2022-04-28T20:31:32.988871+0000 0 ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
 -2629> 2022-04-28T20:32:11.034+0000 7f683a737700 10 osd.0 pg_epoch: 593 pg[3.3bs2( v 593'244 (0'0,593'244] local-lis/les=591/592 n=11 ec=548/21 lis/c=591/548 les/c/f=592/549/0 sis=591) [7,2,0]p7(0) r=2 lpr=591 pi=[548,591)/3 luod=0'0 lua=547'242 crt=547'242 lcod 0'0 mlcod 0'0 active mbc={} ps=[35~1,63~1,6b~1,6e~6,76~1,7a~1,7c~3,81~2,84~1,86~3,8a~4,90~3,95~1,97~1,99~1]] append_log approx pg log length =  244
 -2628> 2022-04-28T20:32:11.034+0000 7f683a737700 10 osd.0 pg_epoch: 593 pg[3.3bs2( v 593'244 (0'0,593'244] local-lis/les=591/592 n=11 ec=548/21 lis/c=591/548 les/c/f=592/549/0 sis=591) [7,2,0]p7(0) r=2 lpr=591 pi=[548,591)/3 luod=0'0 lua=547'242 crt=547'242 lcod 0'0 mlcod 0'0 active mbc={} ps=[35~1,63~1,6b~1,6e~6,76~1,7a~1,7c~3,81~2,84~1,86~3,8a~4,90~3,95~1,97~1,99~1]] append_log transaction_applied = 1
 -2627> 2022-04-28T20:32:11.034+0000 7f683a737700 10 trim proposed trim_to = 0'0
 -2626> 2022-04-28T20:32:11.034+0000 7f683a737700  6 write_log_and_missing with: dirty_to: 0'0, dirty_from: 4294967295'18446744073709551615, writeout_from: 593'243, trimmed: , trimmed_dups: , clear_divergent_priors: 0
 -2625> 2022-04-28T20:32:11.034+0000 7f683a737700 10 bluestore(/var/lib/ceph/osd/ceph-0) queue_transactions ch 0x56373e000780 3.3bs2_head
 -2624> 2022-04-28T20:32:11.034+0000 7f683a737700 20 bluestore(/var/lib/ceph/osd/ceph-0) _txc_create osr 0x56373de5c9a0 = 0x563749fe3c00 seq 11
 -2623> 2022-04-28T20:32:11.034+0000 7f683a737700 20 bluestore(/var/lib/ceph/osd/ceph-0).collection(3.3bs2_head 0x56373e000780) get_onode oid 2#3:de28928d:::smithi01883722-15:head# key 0x828000000000000003DE28928D'!smithi01883722-15!='0xFFFFFFFFFFFFFFFEFFFFFFFFFFFFFFFF6F
 -2622> 2022-04-28T20:32:11.034+0000 7f683a737700 20 bluestore(/var/lib/ceph/osd/ceph-0).collection(3.3bs2_head 0x56373e000780)  r -2 v.len 0
 -2621> 2022-04-28T20:32:11.034+0000 7f683a737700 10 bluestore(/var/lib/ceph/osd/ceph-0) _txc_add_transaction op 17 got ENOENT on 2#3:de28928d:::smithi01883722-15:head#
 -2620> 2022-04-28T20:32:11.034+0000 7f683a737700 -1 bluestore(/var/lib/ceph/osd/ceph-0) _txc_add_transaction error (2) No such file or directory not handled on operation 17 (op 0, counting from 0)
 -2619> 2022-04-28T20:32:11.034+0000 7f683a737700 -1 bluestore(/var/lib/ceph/osd/ceph-0) ENOENT on clone suggests osd bug
 -2618> 2022-04-28T20:32:11.034+0000 7f683a737700  0 _dump_transaction transaction dump:
{
    "ops": [
        {
            "op_num": 0,
            "op_name": "clone",
            "collection": "3.3bs2_head",
            "src_oid": "2#3:de28928d:::smithi01883722-15:head#",
            "dst_oid": "2#3:de28928d:::smithi01883722-15:19e#" 
        },
        {
            "op_num": 1,
            "op_name": "rmattr",
            "collection": "3.3bs2_head",
            "oid": "2#3:de28928d:::smithi01883722-15:19e#",
            "name": "snapset" 
        },
        {
            "op_num": 2,
            "op_name": "setattrs",
            "collection": "3.3bs2_head",
            "oid": "2#3:de28928d:::smithi01883722-15:19e#",
            "attr_lens": {
                "_": 249
            }
        },

On the primary side

2022-04-28T20:32:11.034+0000 7f123535b700 20 osd.7 pg_epoch: 593 pg[3.3bs0( v 547'242 lc 52'38 (0'0,547'242] local-lis/les=591/592 n=11 ec=548/21 lis/c=591/548 les/c/f=592/549/0 sis=591) [7,2,0]p7(0) r=0 lpr=591 pi=[548,591)/3 crt=547'242 mlcod 0'0 active+recovery_wait+degraded m=31 mbc={0={(0+1)=17},1={(1+0)=17},2={(1+1)=17}} trimq=114 ps=[35~1,63~1,6b~1,6e~6,76~1,7a~1,7c~3,81~2,84~1,86~3,8a~4,90~3,95~1,97~1,99~1]] try_reads_to_commit: 3:de28928d:::smithi01883722-15:head,{}
2022-04-28T20:32:11.034+0000 7f123535b700  1 -- [v2:172.21.15.134:6826/77735,v1:172.21.15.134:6827/77735] --> [v2:172.21.15.18:6821/166234,v1:172.21.15.18:6823/166234] -- MOSDECSubOpWrite(3.3bs2 593/591 ECSubWrite(tid=1141, reqid=client.4545.0:5158, at_version=593'244, trim_to=0'0, roll_forward_to=0'0)) v2 -- 0x560ec8b17100 con 0x560ebf4a6800
2022-04-28T20:32:11.034+0000 7f123535b700  1 -- [v2:172.21.15.134:6826/77735,v1:172.21.15.134:6827/77735] --> [v2:172.21.15.18:6820/77740,v1:172.21.15.18:6822/77740] -- MOSDECSubOpWrite(3.3bs1 593/591 ECSubWrite(tid=1141, reqid=client.4545.0:5158, at_version=593'244, trim_to=0'0, roll_forward_to=0'0)) v2 -- 0x560eb71f9100 con 0x560ebf0e1400
2022-04-28T20:32:11.034+0000 7f123535b700 20 snap_mapper.add_oid 3:de28928d:::smithi01883722-15:19e 17e,182,18a,18f,190,193,199,19a
2022-04-28T20:32:11.034+0000 7f123535b700 15 bluestore(/var/lib/ceph/osd/ceph-7) omap_get_values meta oid #-1:c0371625:::snapmapper:0#
2022-04-28T20:32:11.034+0000 7f123535b700 20 _pin0x560eb6d4a000   #-1:c0371625:::snapmapper:0# pinned
2022-04-28T20:32:11.034+0000 7f123535b700 20 bluestore.onode(0x560eb6eccc80).flush flush done
2022-04-28T20:32:11.034+0000 7f123535b700 10 bluestore(/var/lib/ceph/osd/ceph-7) omap_get_values meta oid #-1:c0371625:::snapmapper:0# = 0
2022-04-28T20:32:11.034+0000 7f123535b700 20 _unpin0x560eb6d4a000   #-1:c0371625:::snapmapper:0# unpinned
2022-04-28T20:32:11.034+0000 7f123535b700 20 snap_mapper.get_snaps 3:de28928d:::smithi01883722-15:19e got.empty()
2022-04-28T20:32:11.034+0000 7f123535b700 20 snap_mapper.set_snaps 3:de28928d:::smithi01883722-15:19e 17e,182,18a,18f,190,193,199,19a
2022-04-28T20:32:11.034+0000 7f123535b700 20 snap_mapper.set_snaps set OBJ_.0_0000000000000003.B741941B.19e.smithi01883722-15..
2022-04-28T20:32:11.034+0000 7f123535b700 20 snap_mapper.add_oid set SNA_3_000000000000017E_.0_0000000000000003.B741941B.19e.smithi01883722-15..
2022-04-28T20:32:11.034+0000 7f123535b700 20 snap_mapper.add_oid set SNA_3_0000000000000182_.0_0000000000000003.B741941B.19e.smithi01883722-15..
2022-04-28T20:32:11.034+0000 7f123535b700 20 snap_mapper.add_oid set SNA_3_000000000000018A_.0_0000000000000003.B741941B.19e.smithi01883722-15..
2022-04-28T20:32:11.034+0000 7f123535b700 20 snap_mapper.add_oid set SNA_3_000000000000018F_.0_0000000000000003.B741941B.19e.smithi01883722-15..
2022-04-28T20:32:11.034+0000 7f123535b700 20 snap_mapper.add_oid set SNA_3_0000000000000190_.0_0000000000000003.B741941B.19e.smithi01883722-15..
2022-04-28T20:32:11.034+0000 7f123535b700 20 snap_mapper.add_oid set SNA_3_0000000000000193_.0_0000000000000003.B741941B.19e.smithi01883722-15..
2022-04-28T20:32:11.034+0000 7f123535b700 20 snap_mapper.add_oid set SNA_3_0000000000000199_.0_0000000000000003.B741941B.19e.smithi01883722-15..
2022-04-28T20:32:11.034+0000 7f123535b700 20 snap_mapper.add_oid set SNA_3_000000000000019A_.0_0000000000000003.B741941B.19e.smithi01883722-15..
2022-04-28T20:32:11.034+0000 7f123535b700 20 earliest_dup_version = 0
2022-04-28T20:32:11.034+0000 7f123535b700 20 trim 593'243 (547'242) clone    3:de28928d:::smithi01883722-15:19e by unknown.0.0:0 2022-04-28T20:30:39.964912+0000 0 snaps [19a,199,193,190,18f,18a,182,17e] ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
2022-04-28T20:32:11.034+0000 7f123535b700 20 trim 593'244 (547'242) modify   3:de28928d:::smithi01883722-15:head by client.4545.0:5158 2022-04-28T20:31:32.988871+0000 0 ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
2022-04-28T20:32:11.034+0000 7f123535b700 10 osd.7 pg_epoch: 593 pg[3.3bs0( v 547'242 lc 52'38 (0'0,547'242] local-lis/les=591/592 n=11 ec=548/21 lis/c=591/548 les/c/f=592/549/0 sis=591) [7,2,0]p7(0) r=0 lpr=591 pi=[548,591)/3 crt=547'242 mlcod 0'0 active+recovery_wait+degraded m=31 mbc={0={(0+1)=17},1={(1+0)=17},2={(1+1)=17}} trimq=114 ps=[35~1,63~1,6b~1,6e~6,76~1,7a~1,7c~3,81~2,84~1,86~3,8a~4,90~3,95~1,97~1,99~1]] append_log log((0'0,547'242], crt=547'242) [593'243 (547'242) clone    3:de28928d:::smithi01883722-15:19e by unknown.0.0:0 2022-04-28T20:30:39.964912+0000 0 snaps [19a,199,193,190,18f,18a,182,17e] ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0,593'244 (547'242) modify   3:de28928d:::smithi01883722-15:head by client.4545.0:5158 2022-04-28T20:31:32.988871+0000 0 ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0]
2022-04-28T20:32:11.034+0000 7f123535b700 10 osd.7 pg_epoch: 593 pg[3.3bs0( v 593'243 lc 52'38 (0'0,593'243] local-lis/les=591/592 n=11 ec=548/21 lis/c=591/548 les/c/f=592/549/0 sis=591) [7,2,0]p7(0) r=0 lpr=591 pi=[548,591)/3 luod=547'242 lua=547'242 crt=547'242 mlcod 0'0 active+recovery_wait+degraded m=31 mbc={0={(0+1)=17},1={(1+0)=17},2={(1+1)=17}} trimq=114 ps=[35~1,63~1,6b~1,6e~6,76~1,7a~1,7c~3,81~2,84~1,86~3,8a~4,90~3,95~1,97~1,99~1]] add_log_entry 593'243 (547'242) clone    3:de28928d:::smithi01883722-15:19e by unknown.0.0:0 2022-04-28T20:30:39.964912+0000 0 snaps [19a,199,193,190,18f,18a,182,17e] ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
2022-04-28T20:32:11.034+0000 7f123535b700 10 osd.7 pg_epoch: 593 pg[3.3bs0( v 593'244 lc 52'38 (0'0,593'244] local-lis/les=591/592 n=11 ec=548/21 lis/c=591/548 les/c/f=592/549/0 sis=591) [7,2,0]p7(0) r=0 lpr=591 pi=[548,591)/3 luod=547'242 lua=547'242 crt=547'242 mlcod 0'0 active+recovery_wait+degraded m=31 mbc={0={(0+1)=17},1={(1+0)=17},2={(1+1)=17}} trimq=114 ps=[35~1,63~1,6b~1,6e~6,76~1,7a~1,7c~3,81~2,84~1,86~3,8a~4,90~3,95~1,97~1,99~1]] add_log_entry 593'244 (547'242) modify   3:de28928d:::smithi01883722-15:head by client.4545.0:5158 2022-04-28T20:31:32.988871+0000 0 ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
2022-04-28T20:32:11.034+0000 7f123535b700 10 osd.7 pg_epoch: 593 pg[3.3bs0( v 593'244 lc 52'38 (0'0,593'244] local-lis/les=591/592 n=11 ec=548/21 lis/c=591/548 les/c/f=592/549/0 sis=591) [7,2,0]p7(0) r=0 lpr=591 pi=[548,591)/3 luod=547'242 lua=547'242 crt=547'242 mlcod 0'0 active+recovery_wait+degraded m=31 mbc={0={(0+1)=17},1={(1+0)=17},2={(1+1)=17}} trimq=114 ps=[35~1,63~1,6b~1,6e~6,76~1,7a~1,7c~3,81~2,84~1,86~3,8a~4,90~3,95~1,97~1,99~1]] append_log approx pg log length =  244
2022-04-28T20:32:11.034+0000 7f123535b700 10 osd.7 pg_epoch: 593 pg[3.3bs0( v 593'244 lc 52'38 (0'0,593'244] local-lis/les=591/592 n=11 ec=548/21 lis/c=591/548 les/c/f=592/549/0 sis=591) [7,2,0]p7(0) r=0 lpr=591 pi=[548,591)/3 luod=547'242 lua=547'242 crt=547'242 mlcod 0'0 active+recovery_wait+degraded m=31 mbc={0={(0+1)=17},1={(1+0)=17},2={(1+1)=17}} trimq=114 ps=[35~1,63~1,6b~1,6e~6,76~1,7a~1,7c~3,81~2,84~1,86~3,8a~4,90~3,95~1,97~1,99~1]] append_log transaction_applied = 1
2022-04-28T20:32:11.034+0000 7f123535b700 10 trim proposed trim_to = 0'0
2022-04-28T20:32:11.034+0000 7f123535b700  6 write_log_and_missing with: dirty_to: 0'0, dirty_from: 4294967295'18446744073709551615, writeout_from: 593'243, trimmed: , trimmed_dups: , clear_divergent_priors: 0
2022-04-28T20:32:11.035+0000 7f123535b700 10 bluestore(/var/lib/ceph/osd/ceph-7) queue_transactions ch 0x560ec8b6c1e0 3.3bs0_head
2022-04-28T20:32:11.035+0000 7f123535b700 20 bluestore(/var/lib/ceph/osd/ceph-7) _txc_create osr 0x560ec8d45760 = 0x560ec7aafc00 seq 22
2022-04-28T20:32:11.035+0000 7f123535b700 20 _pin0x560eb6e8e000   0#3:de28928d:::smithi01883722-15:head# pinned
2022-04-28T20:32:11.035+0000 7f123535b700 20 bluestore(/var/lib/ceph/osd/ceph-7).collection(3.3bs0_head 0x560ec8b6c1e0) get_onode oid 0#3:de28928d:::smithi01883722-15:19e# key 0x808000000000000003DE28928D'!smithi01883722-15!='0x000000000000019EFFFFFFFFFFFFFFFF6F
2022-04-28T20:32:11.035+0000 7f123535b700 20 bluestore(/var/lib/ceph/osd/ceph-7).collection(3.3bs0_head 0x560ec8b6c1e0)  r -2 v.len 0
2022-04-28T20:32:11.035+0000 7f123535b700 20 bluestore.OnodeSpace(0x560ec8b6c320 in 0x560eb6e8e000) add 0#3:de28928d:::smithi01883722-15:19e# 0x560ecc02b680
2022-04-28T20:32:11.035+0000 7f123535b700 20 _add 0x560eb6e8e000 0#3:de28928d:::smithi01883722-15:19e# added, num=25
2022-04-28T20:32:11.035+0000 7f123535b700 15 bluestore(/var/lib/ceph/osd/ceph-7) _clone 3.3bs0_head 0#3:de28928d:::smithi01883722-15:head# -> 0#3:de28928d:::smithi01883722-15:19e#
2022-04-28T20:32:11.035+0000 7f123535b700 20 bluestore(/var/lib/ceph/osd/ceph-7) _assign_nid 3040
2022-04-28T20:32:11.035+0000 7f123535b700 20 bluestore.onode(0x560ed348f400).flush flush done
2022-04-28T20:32:11.035+0000 7f123535b700 15 bluestore(/var/lib/ceph/osd/ceph-7) _do_truncate 3.3bs0_head 0#3:de28928d:::smithi01883722-15:19e# 0x0
2022-04-28T20:32:11.035+0000 7f123535b700 15 bluestore(/var/lib/ceph/osd/ceph-7) _do_clone_range 3.3bs0_head 0#3:de28928d:::smithi01883722-15:head# -> 0#3:de28928d:::smithi01883722-15:19e# 0x0~114000 ->  0x0~114000

/a/nojha-2022-04-28_19:20:30-rados-pacific-distro-basic-smithi/6811513