Actions
Bug #38049
closedrandom osds failing in thread_name:bstore_kv_final
% Done:
0%
Source:
Community (user)
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
Since upgrading to mimic 13.2.4 single osds are randomly failing with the following assert:
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -67> 2019-01-25 15:57:08.414 7eff6730a700 1 get compressor snappy = 0x7effa0dd9240
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -66> 2019-01-25 15:57:08.414 7eff6730a700 10 bluestore(/var/lib/ceph/osd/ceph-225) read 6.141s3_head 3#6:82b4e9d2:::10003f4713e.00000003:head# 0x
0~1000000 = 524288
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -65> 2019-01-25 15:57:08.414 7eff6730a700 10 bluestore(/var/lib/ceph/osd/ceph-225) stat 6.141s3_head 3#6:82b4e9d2:::10003f4713e.00000003:head#
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -64> 2019-01-25 15:57:08.414 7eff6730a700 10 bluestore(/var/lib/ceph/osd/ceph-225) stat 6.141s3_head 3#6:82b4e9e0:::1000cfcc030.0000000e:head#
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -63> 2019-01-25 15:57:08.414 7eff6730a700 20 bluestore(/var/lib/ceph/osd/ceph-225).collection(6.141s3_head 0x7eff8b6fee00) get_onode oid 3#6:82b4
e9e0:::1000cfcc030.0000000e:head# key 0x83800000000000000682b4e9e0213130'00cfcc030.0000000e!='0xfffffffffffffffeffffffffffffffff'o'
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -62> 2019-01-25 15:57:08.414 7eff6730a700 20 bluestore(/var/lib/ceph/osd/ceph-225).collection(6.141s3_head 0x7eff8b6fee00) r 0 v.len 438
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -61> 2019-01-25 15:57:08.414 7eff6730a700 20 bluestore.blob(0x7eff91796770) get_ref 0x0~80000 Blob(0x7eff91796770 blob([0x525f8f10000~70000] clen
0x80000 -> 0x6da33 compressed) use_tracker(0x0 0x0) SharedBlob(0x7eff917967e0 sbid 0x0))
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -60> 2019-01-25 15:57:08.414 7eff6730a700 20 bluestore.blob(0x7eff91796770) get_ref init 0x80000, 80000
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -59> 2019-01-25 15:57:08.414 7eff6730a700 15 bluestore(/var/lib/ceph/osd/ceph-225) getattrs 6.141s3_head 3#6:82b4e9e0:::1000cfcc030.0000000e:head
#
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -58> 2019-01-25 15:57:08.414 7eff6730a700 10 bluestore(/var/lib/ceph/osd/ceph-225) getattrs 6.141s3_head 3#6:82b4e9e0:::1000cfcc030.0000000e:head
# = 0
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -57> 2019-01-25 15:57:08.414 7eff6730a700 15 bluestore(/var/lib/ceph/osd/ceph-225) read 6.141s3_head 3#6:82b4e9e0:::1000cfcc030.0000000e:head# 0x
0~1000000
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -56> 2019-01-25 15:57:08.414 7eff6730a700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_read 0x0~1000000 size 0x80000 (524288)
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -55> 2019-01-25 15:57:08.414 7eff6730a700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_read blob Blob(0x7eff91796770 blob([0x525f8f10000~70000]
clen 0x80000 -> 0x6da33 compressed) use_tracker(0x80000 0x80000) SharedBlob(0x7eff917967e0 sbid 0x0)) need 0x0~80000 cache has 0x[]
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -54> 2019-01-25 15:57:08.414 7eff6730a700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_read blob Blob(0x7eff91796770 blob([0x525f8f10000~70000]
clen 0x80000 -> 0x6da33 compressed) use_tracker(0x80000 0x80000) SharedBlob(0x7eff917967e0 sbid 0x0)) need {<0x0, 0x80000> : [0x0:0~80000]}
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -53> 2019-01-25 15:57:08.434 7eff65b07700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_read blob Blob(0x7eff8e8b60e0 blob([0x164bf7e0000~50000]
csum crc32c/0x1000) use_tracker(0x5*0x10000 0x[10000,10000,10000,10000,10000]) SharedBlob(0x7eff8e8b6150 sbid 0x0)) need 0x{<0x0, 0x50000> : [0x0:0~50000]}
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -52> 2019-01-25 15:57:08.434 7eff65b07700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_read blob Blob(0x7eff8e8b61c0 blob([!~50000,0x164bf830000
~10000] csum+has_unused crc32c/0x1000 unused=0x1fff) use_tracker(0x6*0x10000 0x[0,0,0,0,0,c000]) SharedBlob(0x7eff8e8b6380 sbid 0x0)) need 0x{<0x50000, 0xc000> : [0x50000:50000~c000]}
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -51> 2019-01-25 15:57:08.434 7eff65b07700 10 bluestore(/var/lib/ceph/osd/ceph-225) read 6.36fs6_head 6#6:f6ef61c0:::1000ee9b1a4.0000001b:head# 0x
0~1000000 = 376832
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -50> 2019-01-25 15:57:08.434 7eff65b07700 10 bluestore(/var/lib/ceph/osd/ceph-225) stat 6.36fs6_head 6#6:f6ef61c0:::1000ee9b1a4.0000001b:head#
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -49> 2019-01-25 15:57:08.434 7eff65b07700 10 bluestore(/var/lib/ceph/osd/ceph-225) stat 6.36fs6_head 6#6:f6ef61ec:::10008fb62c4.00000004:head#
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -48> 2019-01-25 15:57:08.434 7eff65b07700 20 bluestore(/var/lib/ceph/osd/ceph-225).collection(6.36fs6_head 0x7eff8b716a00) get_onode oid 6#6:f6ef
61ec:::10008fb62c4.00000004:head# key 0x868000000000000006f6ef61ec213130'008fb62c4.00000004!='0xfffffffffffffffeffffffffffffffff'o'
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -47> 2019-01-25 15:57:08.434 7eff65b07700 20 bluestore(/var/lib/ceph/osd/ceph-225).collection(6.36fs6_head 0x7eff8b716a00) r 0 v.len 438
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -46> 2019-01-25 15:57:08.434 7eff65b07700 20 bluestore.blob(0x7eff8e8b65b0) get_ref 0x0~80000 Blob(0x7eff8e8b65b0 blob([0x164bf9a0000~70000] clen
0x80000 -> 0x69b43 compressed) use_tracker(0x0 0x0) SharedBlob(0x7eff8e8b6620 sbid 0x0))
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -45> 2019-01-25 15:57:08.434 7eff65b07700 20 bluestore.blob(0x7eff8e8b65b0) get_ref init 0x80000, 80000
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -44> 2019-01-25 15:57:08.434 7eff65b07700 15 bluestore(/var/lib/ceph/osd/ceph-225) getattrs 6.36fs6_head 6#6:f6ef61ec:::10008fb62c4.00000004:head
#
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -43> 2019-01-25 15:57:08.434 7eff65b07700 10 bluestore(/var/lib/ceph/osd/ceph-225) getattrs 6.36fs6_head 6#6:f6ef61ec:::10008fb62c4.00000004:head
# = 0
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -42> 2019-01-25 15:57:08.434 7eff65b07700 15 bluestore(/var/lib/ceph/osd/ceph-225) read 6.36fs6_head 6#6:f6ef61ec:::10008fb62c4.00000004:head# 0x
0~1000000
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -41> 2019-01-25 15:57:08.434 7eff65b07700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_read 0x0~1000000 size 0x80000 (524288)
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -40> 2019-01-25 15:57:08.434 7eff65b07700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_read blob Blob(0x7eff8e8b65b0 blob([0x164bf9a0000~70000]
clen 0x80000 -> 0x69b43 compressed) use_tracker(0x80000 0x80000) SharedBlob(0x7eff8e8b6620 sbid 0x0)) need 0x0~80000 cache has 0x[]
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -39> 2019-01-25 15:57:08.434 7eff65b07700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_read blob Blob(0x7eff8e8b65b0 blob([0x164bf9a0000~70000]
clen 0x80000 -> 0x69b43 compressed) use_tracker(0x80000 0x80000) SharedBlob(0x7eff8e8b6620 sbid 0x0)) need {<0x0, 0x80000> : [0x0:0~80000]}
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -38> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.MempoolThread(0x7effa55d1b08) _trim_shards cache_size: 134217728 kv_alloc: 134217728 kv_us
ed: 132811826 meta_alloc: 0 meta_used: 3696326 data_alloc: 0 data_used: 0
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -37> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa730b440) _trim onodes 0 / 0 buffers 0 / 0
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -36> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57131c0) _trim onodes 2 / 0 buffers 0 / 0
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -35> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57131c0) _trim considering 0x7efe17fcbb00
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -34> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.sharedblob(0x7eff91796460) put 0x7eff91796460 removing self from set 0x7eff8b6fef00
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -33> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.BufferSpace(0x7eff91796478 in 0x7effa57131c0) _clear
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -32> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57131c0) _trim considering 0x7efe17fccd00
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -31> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57131c0) _trim 3#6:82b4e9e0:::1000cfcc030.0000000e:head# has 3 refs; skipp
ing
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -30> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57132a0) _trim onodes 5 / 0 buffers 0 / 0
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -29> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57132a0) _trim considering 0x7eff58c1af00
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -28> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57132a0) _trim 2#6:80a659e9:::1000fbf04ab.0000000a:head# has 2 refs; skipp
ing
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -27> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57132a0) _trim considering 0x7efe0d738600
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -26> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57132a0) _trim 2#6:80a63af2:::1000fe25508.00000042:head#b02fa has 2 refs;
skipping
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -25> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57132a0) _trim considering 0x7efe10372300
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -24> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57132a0) _trim 2#6:80a659e9:::1000fbf04ab.0000000a:head#b02fc has 2 refs;
skipping
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -23> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57132a0) _trim considering 0x7efe0d73a100
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -22> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57132a0) _trim 2#6:80800000::::head# has 6 refs; skipping
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -21> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57132a0) _trim considering 0x7eff6409e200
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -20> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa57132a0) _trim 2#6:80a67c40:::1000fecf3fa.000071fb:head# has 5 refs; skipp
ing
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -19> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa5713380) _trim onodes 2 / 0 buffers 0 / 0
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -18> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa5713380) _trim considering 0x7efeeb060400
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -17> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa5713380) _trim 4#6:cb400000::::head# has 3 refs; skipping
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -16> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa5713380) _trim considering 0x7efec813bb00
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -15> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa5713380) _trim 4#6:cb5868b1:::1000ff1ac08.0000450d:head# has 5 refs; skipp
ing
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -14> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa5713460) _trim onodes 4 / 0 buffers 0 / 0
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -13> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa5713460) _trim considering 0x7eff2653dc00
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -12> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.sharedblob(0x7eff8e777d60) put 0x7eff8e777d60 removing self from set 0x7eff8b716b00
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -11> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.BufferSpace(0x7eff8e777d78 in 0x7effa5713460) _clear
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -10> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa5713460) _trim considering 0x7eff2653df00
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -9> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.sharedblob(0x7eff8e8b6000) put 0x7eff8e8b6000 removing self from set 0x7eff8b716b00
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -8> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.BufferSpace(0x7eff8e8b6018 in 0x7effa5713460) _clear
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -7> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa5713460) _trim considering 0x7eff24f5b900
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -6> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.sharedblob(0x7eff8e8b6150) put 0x7eff8e8b6150 removing self from set 0x7eff8b716b00
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -5> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.BufferSpace(0x7eff8e8b6168 in 0x7effa5713460) _clear
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -4> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.sharedblob(0x7eff8e8b6380) put 0x7eff8e8b6380 removing self from set 0x7eff8b716b00
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -3> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.BufferSpace(0x7eff8e8b6398 in 0x7effa5713460) _clear
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -2> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa5713460) _trim considering 0x7eff24f5c800
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1> 2019-01-25 15:57:08.434 7eff97faf700 20 bluestore.2QCache(0x7effa5713460) _trim 6#6:f6ef61ec:::10008fb62c4.00000004:head# has 3 refs; skipping
Jan 25 15:57:08 kaa-115 ceph-osd[24687]: 0> 2019-01-25 15:57:08.434 7eff8fd23700 -1 *** Caught signal (Aborted) **
in thread 7eff8fd23700 thread_name:bstore_kv_final
ceph version 13.2.4 (b10be4d44915a4d78a8e06aa31919e74927b142e) mimic (stable)
1: (()+0x8cc83b) [0x55ebefd5f83b]
2: (()+0x13230) [0x7effa982f230]
3: (gsignal()+0x10b) [0x7effa86cdbcd]
4: (abort()+0x148) [0x7effa86cf298]
5: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x264) [0x7effac667547]
6: (ceph::register_assert_context(CephContext*)+0) [0x7effac6675b0]
7: (StupidAllocator::_insert_free(unsigned long, unsigned long)+0xbc4) [0x55ebefd3a6c0]
8: (StupidAllocator::release(interval_set<unsigned long, std::map<unsigned long, unsigned long, std::less<unsigned long>, std::allocator<std::pair<unsigned long const, unsigned long> > > > const&)+0x6b) [0x55ebefd3a759]
9: (BlueStore::_txc_release_alloc(BlueStore::TransContext*)+0xc4) [0x55ebefc0fd7e]
10: (BlueStore::_txc_finish(BlueStore::TransContext*)+0x447) [0x55ebefc25cb1]
11: (BlueStore::_txc_state_proc(BlueStore::TransContext*)+0x90) [0x55ebefc3472a]
12: (BlueStore::_kv_finalize_thread()+0x47d) [0x55ebefc358a9]
13: (BlueStore::KVFinalizeThread::entry()+0xd) [0x55ebefc8a187]
14: (()+0x75e5) [0x7effa98235e5]
15: (clone()+0x3f) [0x7effa8794e9f]
The affected osds can be restarted manually, but the failures happen quite frequently. Multiple (3-5) osds usually crash in quick succession, and this seems to occur during compression with snappy.
Files
Updated by Igor Fedotov about 5 years ago
Lawrence, can you please run fsck for some of already failed OSDs.
Updated by Igor Fedotov about 5 years ago
Just to record intermediate analysis results:
the failure sequence looks like the following - compressed blob was overwritten with uncompressed one. Previous pextent released. Shortly after onode is being removed and previously released pextent is attempted for removal again. Which result in allocator's assertion as pextent is marked as free.
Updated by Igor Fedotov about 5 years ago
Log extract for competing transactions (T1 - rename A->B, T2 - write A, T3 - remove B:
renaming (TRANSACTION1 !!!!!!!!!!!) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1513> 2019-01-25 15:57:07.914 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) queue_transactions ch 0x7effa5792a00 6.101s2_head Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1512> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_create osr 0x7effa6de99c0 = 0x7efe10374d00 seq 1533 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1507> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225).collection(6.101s2_head 0x7effa5792a00) r 0 v.len 462 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1506> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore.blob(0x7eff90b62ab0) get_ref 0x0~80000 Blob(0x7eff90b62ab0 blob([0x42cd1270000~40000] clen 0x80000 -> 0x3c470 compressed) use_tracker(0x0 0x0) SharedBlob(0x7eff90b62b20 sbid 0x0)) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1505> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore.blob(0x7eff90b62ab0) get_ref init 0x80000, 80000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1504> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225).collection(6.101s2_head 0x7effa5792a00) get_onode oid 2#6:80a63af2:::1000fe25508.00000042:head#b02fa key 0x82800000000000000680a63af2213130'00fe25508.00000042!='0xfffffffffffffffe00000000000b02fa'o' Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1503> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225).collection(6.101s2_head 0x7effa5792a00) r -2 v.len 0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1502> 2019-01-25 15:57:07.914 7eff66b09700 15 bluestore(/var/lib/ceph/osd/ceph-225) _rename 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head# -> 2#6:80a63af2:::1000fe25508.00000042:head#b02fa Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1501> 2019-01-25 15:57:07.914 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _rename 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head# -> 2#6:80a63af2:::1000fe25508.00000042:head#b02fa = 0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1500> 2019-01-25 15:57:07.914 7eff66b09700 15 bluestore(/var/lib/ceph/osd/ceph-225) _omap_setkeys 6.101s2_head 2#6:80800000::::head# Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1499> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _omap_setkeys 0x0000000000001947'.0000564512.00000000000000721658' <- 0000564512.00000000000000721658 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1498> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _omap_setkeys 0x0000000000001947'._fastinfo' <- _fastinfo Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1497> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _omap_setkeys 0x0000000000001947'.can_rollback_to' <- can_rollback_to Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1496> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _omap_setkeys 0x0000000000001947'.rollback_info_trimmed_to' <- rollback_info_trimmed_to Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1495> 2019-01-25 15:57:07.914 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _omap_setkeys 6.101s2_head 2#6:80800000::::head# = 0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1494> 2019-01-25 15:57:07.914 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_calc_cost 0x7efe10374d00 cost 670987 (1 ios * 670000 + 987 bytes) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1493> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_write_nodes txc 0x7efe10374d00 onodes 0x7efe13071000 shared_blobs Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1492> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore.extentmap(0x7efe13071150) update 2#6:80a63af2:::1000fe25508.00000042:head#b02fa Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1491> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _record_onode onode 2#6:80a63af2:::1000fe25508.00000042:head#b02fa is 462 (438 bytes onode + 2 bytes spanning blobs + 22 bytes inline extents) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1490> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finalize_kv txc 0x7efe10374d00 allocated 0x[] released 0x[] Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1489> 2019-01-25 15:57:07.914 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_state_proc txc 0x7efe10374d00 prepare Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1488> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finish_io 0x7efe10374d00 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1487> 2019-01-25 15:57:07.914 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finish_io 0x7efe10374d00 blocked by 0x7efe10374400 aio_wait ... Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -1267> 2019-01-25 15:57:07.954 7eff9d739700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_state_proc txc 0x7efe10374d00 io_done ... Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -974> 2019-01-25 15:57:08.004 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finish txc 0x7efe10374d00 kv_queued writing (TRANSACTION2 !!!!!!!!!!!) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -848> 2019-01-25 15:57:08.034 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) queue_transactions ch 0x7effa5792a00 6.101s2_head Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -847> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_create osr 0x7effa6de99c0 = 0x7eff6409d300 seq 1534 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -846> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225).collection(6.101s2_head 0x7effa5792a00) get_onode oid 2#6:80a63af2:::1000fe25508.00000042:head# key 0x82800000000000000680a63af2213130'00fe25508.00000042!='0xfffffffffffffffeffffffffffffffff'o' Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -845> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225).collection(6.101s2_head 0x7effa5792a00) r 0 v.len 462 ^^^^^^^^^^ wrong onode (=rename target) returned!!!!!!!!!!!!! Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -844> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore.blob(0x7eff90b62c00) get_ref 0x0~80000 Blob(0x7eff90b62c00 blob([0x42cd1270000~40000] clen 0x80000 -> 0x3c470 compressed) use_tracker(0x0 0x0) SharedBlob(0x7eff90b62ce0 sbid 0x0)) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -843> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore.blob(0x7eff90b62c00) get_ref init 0x80000, 80000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -842> 2019-01-25 15:57:08.034 7eff66b09700 15 bluestore(/var/lib/ceph/osd/ceph-225) _touch 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head# Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -841> 2019-01-25 15:57:08.034 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _touch 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head# = 0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -840> 2019-01-25 15:57:08.034 7eff66b09700 15 bluestore(/var/lib/ceph/osd/ceph-225) _setattrs 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head# 2 keys Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -839> 2019-01-25 15:57:08.034 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _setattrs 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head# 2 keys = 0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -838> 2019-01-25 15:57:08.034 7eff66b09700 15 bluestore(/var/lib/ceph/osd/ceph-225) _set_alloc_hint 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head# object_size 0 write_size 0 flags sequential_write+append_only Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -837> 2019-01-25 15:57:08.034 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _set_alloc_hint 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head# object_size 0 write_size 0 flags sequential_write+append_only = 0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -836> 2019-01-25 15:57:08.034 7eff66b09700 15 bluestore(/var/lib/ceph/osd/ceph-225) _write 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head# 0x0~80000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -835> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_write 2#6:80a63af2:::1000fe25508.00000042:head# 0x0~80000 - have 0x80000 (524288) bytes fadvise_flags 0x20 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -834> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _choose_write_options prefer csum_order 12 target_blob_size 0x80000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -833> 2019-01-25 15:57:08.034 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _do_write_big 0x0~80000 target_blob_size 0x80000 compress 0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -832> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore.blob(0x7eff90b62c00) put_ref 0x0~80000 Blob(0x7eff90b62c00 blob([0x42cd1270000~40000] clen 0x80000 -> 0x3c470 compressed) use_tracker(0x80000 0x80000) SharedBlob(0x7eff90b62ce0 sbid 0x0)) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -831> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_alloc_write txc 0x7eff6409d300 1 blobs Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -830> 2019-01-25 15:57:08.034 7eff66b09700 10 stupidalloc 0x0x7effa6da5c80 reserve need 0x80000 num_free 0x2b179760000 num_reserved 0x0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -829> 2019-01-25 15:57:08.034 7eff66b09700 10 stupidalloc 0x0x7effa6da5c80 allocate_int want_size 0x80000 alloc_unit 0x10000 hint 0x0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -828> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_alloc_write prealloc [0x669b03a0000~80000] Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -827> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_alloc_write initialize csum setting for new blob Blob(0x7eff90b62e30 blob([]) use_tracker(0x0 0x0) SharedBlob(0x7eff90b62ea0 sbid 0x0)) csum_type crc32c csum_order 12 csum_length 0x80000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -826> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_alloc_write blob Blob(0x7eff90b62e30 blob([0x669b03a0000~80000] csum crc32c/0x1000) use_tracker(0x0 0x0) SharedBlob(0x7eff90b62ea0 sbid 0x0)) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -825> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore.blob(0x7eff90b62e30) get_ref 0x0~80000 Blob(0x7eff90b62e30 blob([0x669b03a0000~80000] csum crc32c/0x1000) use_tracker(0x0 0x0) SharedBlob(0x7eff90b62ea0 sbid 0x0)) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -824> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore.blob(0x7eff90b62e30) get_ref init 0x80000, 10000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -823> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _do_alloc_write lex 0x0~80000: 0x0~80000 Blob(0x7eff90b62e30 blob([0x669b03a0000~80000] csum crc32c/0x1000) use_tracker(0x8*0x10000 0x[10000,10000,10000,10000,10000,10000,10000,10000]) SharedBlob(0x7eff90b62ea0 sbid 0x0)) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -822> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore.BufferSpace(0x7eff90b62eb8 in 0x7effa57132a0) _discard 0x0~80000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -821> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _wctx_finish lex_old 0x0~80000: 0x0~80000 Blob(0x7eff90b62c00 blob([!~40000] clen 0x80000 -> 0x3c470 compressed) use_tracker(0x80000 0x0) SharedBlob(0x7eff90b62ce0 sbid 0x0)) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -820> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _wctx_finish blob release [0x42cd1270000~40000] Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -819> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore.BufferSpace(0x7eff90b62cf8 in 0x7effa57132a0) _discard 0x0~80000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -818> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _wctx_finish release 0x42cd1270000~40000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -817> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore.sharedblob(0x7eff90b62ce0) put 0x7eff90b62ce0 removing self from set 0x7effa5792b00 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -816> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore.BufferSpace(0x7eff90b62cf8 in 0x7effa57132a0) _clear Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -815> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore.extentmap(0x7eff6409dd50) dirty_range mark inline shard dirty Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -814> 2019-01-25 15:57:08.034 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _write 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head# 0x0~80000 = 0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -813> 2019-01-25 15:57:08.034 7eff66b09700 15 bluestore(/var/lib/ceph/osd/ceph-225) _setattr 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head# hinfo_key (62 bytes) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -812> 2019-01-25 15:57:08.034 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _setattr 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head# hinfo_key (62 bytes) = 0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -811> 2019-01-25 15:57:08.034 7eff66b09700 15 bluestore(/var/lib/ceph/osd/ceph-225) _omap_setkeys 6.101s2_head 2#6:80800000::::head# Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -810> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _omap_setkeys 0x0000000000001947'.0000564512.00000000000000721659' <- 0000564512.00000000000000721659 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -809> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _omap_setkeys 0x0000000000001947'._fastinfo' <- _fastinfo Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -808> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _omap_setkeys 0x0000000000001947'.can_rollback_to' <- can_rollback_to Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -807> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _omap_setkeys 0x0000000000001947'.rollback_info_trimmed_to' <- rollback_info_trimmed_to Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -806> 2019-01-25 15:57:08.034 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _omap_setkeys 6.101s2_head 2#6:80800000::::head# = 0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -805> 2019-01-25 15:57:08.034 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_calc_cost 0x7eff6409d300 cost 1865903 (2 ios * 670000 + 525903 bytes) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -804> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_write_nodes txc 0x7eff6409d300 onodes 0x7eff6409dc00 shared_blobs Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -803> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore.extentmap(0x7eff6409dd50) update 2#6:80a63af2:::1000fe25508.00000042:head# Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -802> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore.extentmap(0x7eff6409dd50) update inline shard 529 bytes from 1 extents Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -801> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _record_onode onode 2#6:80a63af2:::1000fe25508.00000042:head# is 973 (438 bytes onode + 2 bytes spanning blobs + 533 bytes inline extents) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -800> 2019-01-25 15:57:08.034 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finalize_kv txc 0x7eff6409d300 allocated 0x[669b03a0000~80000] released 0x[42cd1270000~40000] ... Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -793> 2019-01-25 15:57:08.034 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_aio_submit txc 0x7eff6409d300 renaming contd(TRANSACTION1 !!!!!!!!!!!) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -706> 2019-01-25 15:57:08.034 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _kv_finalize_thread kv_committed <0x7efe10374d00,0x7efedf1d1a00,0x7efec813a300> Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -705> 2019-01-25 15:57:08.034 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _kv_finalize_thread deferred_stable <> Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -704> 2019-01-25 15:57:08.034 7eff8fd23700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_state_proc txc 0x7efe10374d00 kv_submitted Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -703> 2019-01-25 15:57:08.034 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_committed_kv txc 0x7efe10374d00 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -702> 2019-01-25 15:57:08.034 7eff8fd23700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_state_proc txc 0x7efe10374d00 finishing Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -701> 2019-01-25 15:57:08.034 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finish 0x7efe10374d00 onodes 0x7efe13071000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -700> 2019-01-25 15:57:08.034 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finish txc 0x7efe10374d00 done writing contd(TRANSACTION2 !!!!!!!!!!!) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -699> 2019-01-25 15:57:08.034 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finish txc 0x7eff6409d300 aio_wait Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -698> 2019-01-25 15:57:08.034 7eff8fd23700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_release_alloc(sync) 0x7efe10374d00 [] ... Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -678> 2019-01-25 15:57:08.044 7eff9d739700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_state_proc txc 0x7eff6409d300 aio_wait Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -677> 2019-01-25 15:57:08.044 7eff9d739700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finish_io 0x7eff6409d300 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -676> 2019-01-25 15:57:08.044 7eff9d739700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_state_proc txc 0x7eff6409d300 io_done ... Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -531> 2019-01-25 15:57:08.074 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _kv_finalize_thread kv_committed <0x7eff6409d300,0x7eff6409ee00> Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -530> 2019-01-25 15:57:08.074 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _kv_finalize_thread deferred_stable <> Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -529> 2019-01-25 15:57:08.074 7eff8fd23700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_state_proc txc 0x7eff6409d300 kv_submitted Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -528> 2019-01-25 15:57:08.074 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_committed_kv txc 0x7eff6409d300 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -527> 2019-01-25 15:57:08.074 7eff8fd23700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_state_proc txc 0x7eff6409d300 finishing Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -526> 2019-01-25 15:57:08.074 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finish 0x7eff6409d300 onodes 0x7eff6409dc00 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -525> 2019-01-25 15:57:08.074 7eff8fd23700 20 bluestore.BufferSpace(0x7eff90b62eb8 in 0x7effa57132a0) _finish_write discard buffer(0x7efe140aff20 space 0x7eff90b62eb8 0x0~80000 writing nocache) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -524> 2019-01-25 15:57:08.074 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finish txc 0x7eff6409d300 done Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -523> 2019-01-25 15:57:08.074 7eff8fd23700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finish txc 0x7eff6409ee00 kv_submitted Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -522> 2019-01-25 15:57:08.074 7eff8e521700 1 -- 172.20.10.115:6813/24687 --> 172.20.10.118:6813/190615 -- MOSDECSubOpWriteReply(6.101s0 564512/564377 ECSubWriteReply(tid=47804, last_complete=564512'721659, committed=1, applied=1)) v2 -- 0x7eff5bf10780 con 0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -521> 2019-01-25 15:57:08.074 7eff8fd23700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_release_alloc(sync) 0x7eff6409d300 [42cd1270000~40000] Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -520> 2019-01-25 15:57:08.074 7eff8fd23700 10 stupidalloc 0x0x7effa6da5c80 release 0x42cd1270000~40000 removing initial rename target onode (TRANSACTION3 !!!!!!!!!!!) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -393> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225).collection(6.101s2_head 0x7effa5792a00) get_onode oid 2#6:80a63af2:::1000fe25508.00000042:head#b02fa key 0x82800000000000000680a63af2213130'00fe25508.00000042!='0xfffffffffffffffe00000000000b02fa'o' Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -392> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225).collection(6.101s2_head 0x7effa5792a00) r 0 v.len 462 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -391> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore.blob(0x7eff90b631b0) get_ref 0x0~80000 Blob(0x7eff90b631b0 blob([0x42cd1270000~40000] clen 0x80000 -> 0x3c470 compressed) use_tracker(0x0 0x0) SharedBlob(0x7eff90b63290 sbid 0x0)) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -390> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore.blob(0x7eff90b631b0) get_ref init 0x80000, 80000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -389> 2019-01-25 15:57:08.104 7eff66b09700 15 bluestore(/var/lib/ceph/osd/ceph-225) _remove 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head#b02fa Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -388> 2019-01-25 15:57:08.104 7eff66b09700 15 bluestore(/var/lib/ceph/osd/ceph-225) _do_truncate 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head#b02fa 0x0 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -387> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore.blob(0x7eff90b631b0) put_ref 0x0~80000 Blob(0x7eff90b631b0 blob([0x42cd1270000~40000] clen 0x80000 -> 0x3c470 compressed) use_tracker(0x80000 0x80000) SharedBlob(0x7eff90b63290 sbid 0x0)) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -386> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore.extentmap(0x7efe0d738750) dirty_range mark inline shard dirty Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -385> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _wctx_finish lex_old 0x0~80000: 0x0~80000 Blob(0x7eff90b631b0 blob([!~40000] clen 0x80000 -> 0x3c470 compressed) use_tracker(0x80000 0x0) SharedBlob(0x7eff90b63290 sbid 0x0)) Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -384> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _wctx_finish blob release [0x42cd1270000~40000] Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -383> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore.BufferSpace(0x7eff90b632a8 in 0x7effa57132a0) _discard 0x0~80000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -382> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _wctx_finish release 0x42cd1270000~40000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -381> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore.sharedblob(0x7eff90b63290) put 0x7eff90b63290 removing self from set 0x7effa5792b00 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -380> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore.BufferSpace(0x7eff90b632a8 in 0x7effa57132a0) _clear Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -379> 2019-01-25 15:57:08.104 7eff66b09700 10 bluestore(/var/lib/ceph/osd/ceph-225) _remove 6.101s2_head 2#6:80a63af2:::1000fe25508.00000042:head#b02fa = 0 ... Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -365> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finalize_kv txc 0x7eff58c1a600 allocated 0x[669b04a0000~50000] released 0x[42cd1270000~40000] Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -364> 2019-01-25 15:57:08.104 7eff66b09700 10 freelist allocate 0x669b04a0000~50000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -363> 2019-01-25 15:57:08.104 7eff66b09700 20 freelist _xor first_key 0x669b0000000 last_key 0x669b0000000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -362> 2019-01-25 15:57:08.104 7eff66b09700 20 bluestore(/var/lib/ceph/osd/ceph-225) _txc_finalize_kv release 0x42cd1270000~40000 Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -361> 2019-01-25 15:57:08.104 7eff66b09700 10 freelist release 0x42cd1270000~40000 ... Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -107> 2019-01-25 15:57:08.174 7eff8fd23700 10 bluestore(/var/lib/ceph/osd/ceph-225) _txc_release_alloc(sync) 0x7eff58c1a600 [42cd1270000~40000] Jan 25 15:57:08 kaa-115 ceph-osd[24687]: -106> 2019-01-25 15:57:08.174 7eff8fd23700 10 stupidalloc 0x0x7effa6da5c80 release 0x42cd1270000~40000 ^^^ this has been already released at -520
Updated by Igor Fedotov about 5 years ago
- Status changed from New to 12
- Assignee changed from Igor Fedotov to Sage Weil
@Sage Weil - could you please confirm this is a duplicate for #36541
Updated by Lawrence Smith about 5 years ago
The fsck on a failed osd gives the following:
2019-02-02 10:53:43.170 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: actual store_statfs(0x2f6ffb40000/0x91d7fbfe000, stored 0x64048181f6b/0x61dc1730000, compress 0xebf8152f5e/0x101a0a90000/0x16bcfe10000) != expected store_statfs(0x2f6ffb40000/0x91d7fbfe000, stored 0x64048391f6b/0x61dc1970000, compress 0xebf819ca44/0x101a0ae0000/0x16bcfe90000)
2019-02-02 10:53:47.170 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: free extent 0x27d3e2a0000~80000 intersects allocated blocks
2019-02-02 10:53:48.300 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: free extent 0x6a3f7a20000~10000 intersects allocated blocks
2019-02-02 10:53:48.320 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: free extent 0x6bc8f670000~10000 intersects allocated blocks
2019-02-02 10:53:48.420 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: free extent 0x711627e0000~110000 intersects allocated blocks
2019-02-02 10:53:48.430 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: free extent 0x712cd5c0000~190000 intersects allocated blocks
2019-02-02 10:53:48.460 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: free extent 0x728a4f90000~90000 intersects allocated blocks
2019-02-02 10:53:48.470 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: free extent 0x72e04b70000~10000 intersects allocated blocks
2019-02-02 10:53:48.470 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: free extent 0x730df220000~110000 intersects allocated blocks
2019-02-02 10:53:48.850 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: leaked extent 0x4c063260000~80000
2019-02-02 10:53:48.850 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: leaked extent 0x64e1dfa0000~80000
2019-02-02 10:53:48.850 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: leaked extent 0x65996f50000~50000
2019-02-02 10:53:48.850 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: leaked extent 0x6bc8f640000~30000
2019-02-02 10:53:48.850 7fe00180f240 -1 bluestore(/var/lib/ceph/osd/ceph-305) fsck error: leaked extent 0x72e04b30000~40000
fsck success
Updated by Lawrence Smith about 5 years ago
We have since patched our ceph with https://github.com/ceph/ceph/pull/24686 which fixes Issue #36541. Since then the frequency of the error has reduced, but it still occurs occasionally.
The fsck still reports the same.
Updated by Igor Fedotov about 5 years ago
Lawrence, would you share the log for current crashes please?
Existing failures with fsck are expected as the patch is intended to avoid new bug occurrences but it doesn't remove artifacts from the previous ones.
You may want to try repair (carefully!) later but let's eliminate crashes first.
Updated by Lawrence Smith about 5 years ago
- File ceph-osd.log.gz ceph-osd.log.gz added
After two days of running fine I had set the bluestore and bluefs log level back to default, so I dont know how helpful this log is.
I have now set them back to 20/20 so that I can provide a more detailed log once another osd crashes.
Updated by Sage Weil about 5 years ago
From the first log, this looks like #36541. My guess is the crashes you were seeing after were continued problems from previous occurrences of the bug....
Updated by Lawrence Smith about 5 years ago
We have not experienced any further crashes in over a week (compared to multiple crashes per hour before), so it looks like the issue is fixed with https://github.com/ceph/ceph/pull/24686.
Actions