RE: segfault in bluestore during random writes

["Ma, Jianpeng" <jianpeng.ma@intel.com>]

I add some debug messges  and the message as followings when bug reproduce:

3305972   -102> 2016-07-07 23:48:12.541535 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) queue_transactions existing 0xac78760 osr(0.4f 0xb6d2d80)
3305973   -101> 2016-07-07 23:48:12.541548 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _txc_create osr 0xac78760 = 0x177b0000 seq 611
3305974   -100> 2016-07-07 23:48:12.541563 7f7f4449c700 15 bluestore(/mnt/ceph/build/dev/osd2) _write 0.4f_head #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# 0x1a0000~10000
3305975    -99> 2016-07-07 23:48:12.541574 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _do_write #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# 0x1a0000~10000 - have 0x400000 (4194304) bytes         in 64 lextents
3305976    -98> 2016-07-07 23:48:12.541581 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _do_write prefer csum_order 12 comp_blob_size 0x40000
3305977    -97> 2016-07-07 23:48:12.541608 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _do_write_big 0x1a0000~10000 max_blob_len 0x10000 compress 0
3305978    -96> 2016-07-07 23:48:12.541617 7f7f4449c700 20 bluestore.BufferSpace(0x12012ea8 in 0xa02f240) _discard 0x0~10000
3305979    -95> 2016-07-07 23:48:12.541626 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _do_write_big  lex 0x1a0000: 0x0~10000->91
3305980    -94> 2016-07-07 23:48:12.541630 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _do_write_big  blob 91:blob([] clen 0x0 ref_map(0x0~10000=1))
3305981    -93> 2016-07-07 23:48:12.541634 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _do_alloc_write txc 0x177b0000 1 blobs
3305982    -92> 2016-07-07 23:48:12.541638 7f7f4449c700 10 bitmapalloc:reserve instance 174395776 num_used 1600847 total 18350080
3305983    -91> 2016-07-07 23:48:12.541641 7f7f4449c700 10 bitmapalloc:allocate instance 174395776 want_size 0x10000 alloc_unit 0x1000 hint 0x0
3305984    -90> 2016-07-07 23:48:12.541642 7f7f55cbf700 10 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_proc txc 0xedfef00 aio_wait
3305985    -89> 2016-07-07 23:48:12.541651 7f7f55cbf700 20 bluestore(/mnt/ceph/build/dev/osd2) _txc_finish_io 0xedfef00
3305986    -88> 2016-07-07 23:48:12.541653 7f7f55cbf700 10 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_proc txc 0xedfef00 io_done
3305987    -87> 2016-07-07 23:48:12.541656 7f7f55cbf700  0 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_procIO_DONE txc 0xedfef00
3305988    -86> 2016-07-07 23:48:12.541659 7f7f55cbf700  0 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_proc onode #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# 0 size=65
3305989    -85> 2016-07-07 23:48:12.541674 7f7f55cbf700 20 bluestore.BufferSpace(0x12012548 in 0xa02f240) finish_write buffer(0x177d7480 space 0x12012548 0x0~10000 writing nocache)
3305990    -84> 2016-07-07 23:48:12.541680 7f7f55cbf700 20 bluestore.BufferSpace(0x12012ea8 in 0xa02f240) finish_write buffer(0x177d75c0 space 0x12012ea8 0x0~10000 writing nocache)
3305991    -83> 2016-07-07 23:48:12.541684 7f7f55cbf700  0 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_proc 2
3305992    -82> 2016-07-07 23:48:12.541715 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _kv_sync_thread wake
3305993    -81> 2016-07-07 23:48:12.541742 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _kv_sync_thread committing 1 cleaning 0
3305994    -80> 2016-07-07 23:48:12.541747 7f7f4ccad700 10 bitmapalloc:commit_start instance 174395776 releasing 65536 in extents 1
3305995    -79> 2016-07-07 23:48:12.541752 7f7f4449c700 20 bitmapalloc:allocate instance 174395776 offset 0xc0520000 length 0x10000
3305996    -78> 2016-07-07 23:48:12.541757 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _do_alloc_write blob 91:blob([0xc0520000~10000] clen 0x0 mutable ref_map(0x0~10000=1)) csum_order 12 csum_length 0x        10000
3305997    -77> 2016-07-07 23:48:12.541784 7f7f4449c700  0 bluestore(/mnt/ceph/build/dev/osd2) _wctx_finish onode #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head#
3305998    -76> 2016-07-07 23:48:12.541795 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _wctx_finish lex_old [0x0~10000->27]
3305999    -75> 2016-07-07 23:48:12.541801 7f7f4449c700 20 bluestore.BufferSpace(0xd2c7c98 in 0xa02f240) _discard 0x0~10000
3306000    -74> 2016-07-07 23:48:12.541804 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _wctx_finish release 0xc06d0000~10000
3306001    -73> 2016-07-07 23:48:12.541807 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _wctx_finish rm blob 27:blob([!~10000] clen 0x0 mutable+csum crc32c/0x1000)
3306002    -72> 2016-07-07 23:48:12.541818 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _write 0.4f_head #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# 0x1a0000~10000 = 0
3306003    -71> 2016-07-07 23:48:12.541829 7f7f4449c700 15 bluestore(/mnt/ceph/build/dev/osd2) _setattrs 0.4f_head #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# 2 keys
3306004    -70> 2016-07-07 23:48:12.541836 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _setattrs 0.4f_head #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# 2 keys = 0
3306005    -69> 2016-07-07 23:48:12.541844 7f7f4449c700 15 bluestore(/mnt/ceph/build/dev/osd2) _omap_setkeys 0.4f_head #0:f2000000::::head#
3306006    -68> 2016-07-07 23:48:12.541856 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _omap_setkeys 0.4f_head #0:f2000000::::head# = 0
3306007    -67> 2016-07-07 23:48:12.541855 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _txc_finalize_kv txc 0xedfef00 allocated 0x[c0510000~10000] released 0x[c06c0000~10000]
3306008    -66> 2016-07-07 23:48:12.541863 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _txc_write_nodes txc 0x177b0000 onodes 0xa662000 bnodes
3306009    -65> 2016-07-07 23:48:12.541864 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _txc_finalize_kv  overlap 0x[], new allocated 0x[c0510000~10000] released 0x[c06c0000~10000]
3306010    -64> 2016-07-07 23:48:12.541868 7f7f4ccad700 10 freelist allocate 0xc0510000~10000
3306011    -63> 2016-07-07 23:48:12.541870 7f7f4ccad700 20 freelist _xor first_key 0xc0500000 last_key 0xc0500000
3306012    -62> 2016-07-07 23:48:12.541881 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _txc_finalize_kv release 0xc06c0000~10000
3306013    -61> 2016-07-07 23:48:12.541884 7f7f4ccad700 10 freelist release 0xc06c0000~10000
3306014    -60> 2016-07-07 23:48:12.541886 7f7f4ccad700 20 freelist _xor first_key 0xc0680000 last_key 0xc0680000
3306015    -59> 2016-07-07 23:48:12.541890 7f7f4ccad700 10 bitmapalloc:release 0xc06c0000~10000
3306016    -58> 2016-07-07 23:48:12.541954 7f7f4ccad700 10 bluestore(/mnt/ceph/build/dev/osd2) _balance_bluefs_freespace bluefs 2868 M free (0.999654) bluestore 65426 M free (0.91276), bluefs_ratio 0.0419945
3306017    -57> 2016-07-07 23:48:12.541967 7f7f4449c700  0 bluestore(/mnt/ceph/build/dev/osd2) _txc_write_nodes  onode #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# is 6551
3306018    -56> 2016-07-07 23:48:12.542026 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_proc txc 0x177b0000 prepare
3306019    -55> 2016-07-07 23:48:12.542031 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _kv_sync_thread committed 1 cleaned 0 in 0.000284
3306020    -54> 2016-07-07 23:48:12.542037 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _txc_aio_submit txc 0x177b0000
3306021    -53> 2016-07-07 23:48:12.542037 7f7f4ccad700 10 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_proc txc 0xedfef00 kv_queued
3306022    -52> 2016-07-07 23:48:12.542044 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _txc_finish_kv txc 0xedfef00
3306023    -51> 2016-07-07 23:48:12.542054 7f7f4ccad700 10 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_proc txc 0xedfef00 finishing
3306024    -50> 2016-07-07 23:48:12.542057 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _txc_finish 0xedfef00 onodes 0xa662000
3306025    -49> 2016-07-07 23:48:12.542059 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _txc_finish onode 0xa662000 had 0xedfef00,0x177b0000
3306026    -48> 2016-07-07 23:48:12.542066 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _osr_reap_done osr 0xac78760
3306027    -47> 2016-07-07 23:48:12.542068 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _osr_reap_done  txc 0xedfef00 done
3306028    -46> 2016-07-07 23:48:12.542074 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _osr_reap_done  txc 0x177b0000 aio_wait
3306029    -45> 2016-07-07 23:48:12.542077 7f7f4ccad700 20 bluestore.2QCache(0xa02f240) trim onodes 140 / 16384 buffers 0 / 536870912
3306030    -44> 2016-07-07 23:48:12.542081 7f7f4ccad700 10 bitmapalloc:commit_finish instance 174395776 released 65536 in extents 1
3306031    -43> 2016-07-07 23:48:12.542084 7f7f4ccad700 20 bitmapalloc:insert_free instance 174395776 off 0xc06b0000 len 0x10000
3306032    -42> 2016-07-07 23:48:12.542090 7f7f4ccad700 10 bluestore(/mnt/ceph/build/dev/osd2) _reap_collections all reaped
3306033    -41> 2016-07-07 23:48:12.542093 7f7f4ccad700 20 bluestore(/mnt/ceph/build/dev/osd2) _kv_sync_thread sleep
3306034    -40> 2016-07-07 23:48:12.542110 7f7f4449c700  5 -- op tracker -- seq: 57709, time: 2016-07-07 23:48:12.542109, event: reached_pg, op: osd_op(client.4112.0:176011 0.de0d304f (undecoded) ack+ondisk+wri        te+known_if_redirected e19)
3306035    -39> 2016-07-07 23:48:12.542168 7f7f4449c700  5 -- op tracker -- seq: 57709, time: 2016-07-07 23:48:12.542167, event: started, op: osd_op(client.4112.0:176011 0.de0d304f rbd_data.100d2ae8944a.0000000        000000095 [write 1769472~65536] snapc 0=[] ack+ondisk+write+known_if_redirected e19)
3306036    -38> 2016-07-07 23:48:12.542248 7f7f4449c700  5 write_log with: dirty_to: 0'0, dirty_from: 4294967295'18446744073709551615, dirty_divergent_priors: false, divergent_priors: 0, writeout_from: 19'604,         trimmed:
3306037    -37> 2016-07-07 23:48:12.542276 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) queue_transactions existing 0xac78760 osr(0.4f 0xb6d2d80)
3306038    -36> 2016-07-07 23:48:12.542288 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _txc_create osr 0xac78760 = 0x1252f980 seq 612
3306039    -35> 2016-07-07 23:48:12.542303 7f7f4449c700 15 bluestore(/mnt/ceph/build/dev/osd2) _write 0.4f_head #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# 0x1b0000~10000
3306040    -34> 2016-07-07 23:48:12.542315 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _do_write #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# 0x1b0000~10000 - have 0x400000 (4194304) bytes         in 64 lextents
3306041    -33> 2016-07-07 23:48:12.542321 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _do_write prefer csum_order 12 comp_blob_size 0x40000
3306042    -32> 2016-07-07 23:48:12.542324 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _do_write_big 0x1b0000~10000 max_blob_len 0x10000 compress 0
3306043    -31> 2016-07-07 23:48:12.542328 7f7f4449c700 20 bluestore.BufferSpace(0x12013358 in 0xa02f240) _discard 0x0~10000
3306044    -30> 2016-07-07 23:48:12.542336 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _do_write_big  lex 0x1b0000: 0x0~10000->92
3306045    -29> 2016-07-07 23:48:12.542339 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _do_write_big  blob 92:blob([] clen 0x0 ref_map(0x0~10000=1))
3306046    -28> 2016-07-07 23:48:12.542344 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _do_alloc_write txc 0x1252f980 1 blobs
3306047    -27> 2016-07-07 23:48:12.542346 7f7f4449c700 10 bitmapalloc:reserve instance 174395776 num_used 1600847 total 18350080
3306048    -26> 2016-07-07 23:48:12.542350 7f7f4449c700 10 bitmapalloc:allocate instance 174395776 want_size 0x10000 alloc_unit 0x1000 hint 0x0
3306049    -25> 2016-07-07 23:48:12.542442 7f7f4449c700 20 bitmapalloc:allocate instance 174395776 offset 0xc0530000 length 0x10000
3306050    -24> 2016-07-07 23:48:12.542455 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _do_alloc_write blob 92:blob([0xc0530000~10000] clen 0x0 mutable ref_map(0x0~10000=1)) csum_order 12 csum_length 0x        10000
3306051    -23> 2016-07-07 23:48:12.542437 7f7f55cbf700 10 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_proc txc 0x177b0000 aio_wait
3306052    -22> 2016-07-07 23:48:12.542482 7f7f4449c700  0 bluestore(/mnt/ceph/build/dev/osd2) _wctx_finish onode #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head#
3306053    -21> 2016-07-07 23:48:12.542488 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _wctx_finish lex_old [0x0~10000->28]
3306054    -20> 2016-07-07 23:48:12.542485 7f7f55cbf700 20 bluestore(/mnt/ceph/build/dev/osd2) _txc_finish_io 0x177b0000
3306055    -19> 2016-07-07 23:48:12.542492 7f7f55cbf700 10 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_proc txc 0x177b0000 io_done
3306056    -18> 2016-07-07 23:48:12.542493 7f7f4449c700 20 bluestore.BufferSpace(0xd661088 in 0xa02f240) _discard 0x0~10000
3306057    -17> 2016-07-07 23:48:12.542495 7f7f55cbf700  0 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_procIO_DONE txc 0x177b0000
3306058    -16> 2016-07-07 23:48:12.542496 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _wctx_finish release 0xc06e0000~10000
3306059    -15> 2016-07-07 23:48:12.542500 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _wctx_finish rm blob 28:blob([!~10000] clen 0x0 mutable+csum crc32c/0x1000)
3306060    -14> 2016-07-07 23:48:12.542499 7f7f55cbf700  0 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_proc onode #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# 0 size=65
3306061    -13> 2016-07-07 23:48:12.542510 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _write 0.4f_head #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# 0x1b0000~10000 = 0
3306062    -12> 2016-07-07 23:48:12.542520 7f7f4449c700 15 bluestore(/mnt/ceph/build/dev/osd2) _setattrs 0.4f_head #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# 2 keys
3306063    -11> 2016-07-07 23:48:12.542527 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _setattrs 0.4f_head #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# 2 keys = 0
3306064    -10> 2016-07-07 23:48:12.542535 7f7f4449c700 15 bluestore(/mnt/ceph/build/dev/osd2) _omap_setkeys 0.4f_head #0:f2000000::::head#
3306065     -9> 2016-07-07 23:48:12.542547 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _omap_setkeys 0.4f_head #0:f2000000::::head# = 0
3306066     -8> 2016-07-07 23:48:12.542553 7f7f4449c700 20 bluestore(/mnt/ceph/build/dev/osd2) _txc_write_nodes txc 0x1252f980 onodes 0xa662000 bnodes
3306067     -7> 2016-07-07 23:48:12.542656 7f7f4449c700  0 bluestore(/mnt/ceph/build/dev/osd2) _txc_write_nodes  onode #0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head# is 6552
3306068     -6> 2016-07-07 23:48:12.542703 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _txc_state_proc txc 0x1252f980 prepare
3306069     -5> 2016-07-07 23:48:12.542712 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) _txc_aio_submit txc 0x1252f980
3306070     -4> 2016-07-07 23:48:12.542800 7f7f4449c700  5 -- op tracker -- seq: 57710, time: 2016-07-07 23:48:12.542800, event: reached_pg, op: osd_op(client.4112.0:176012 0.de0d304f (undecoded) ack+ondisk+wri        te+known_if_redirected e19)
3306071     -3> 2016-07-07 23:48:12.542860 7f7f4449c700  5 -- op tracker -- seq: 57710, time: 2016-07-07 23:48:12.542859, event: started, op: osd_op(client.4112.0:176012 0.de0d304f rbd_data.100d2ae8944a.0000000        000000095 [write 1835008~65536] snapc 0=[] ack+ondisk+write+known_if_redirected e19)
3306072     -2> 2016-07-07 23:48:12.542940 7f7f4449c700  5 write_log with: dirty_to: 0'0, dirty_from: 4294967295'18446744073709551615, dirty_divergent_priors: false, divergent_priors: 0, writeout_from: 19'605,         trimmed:
3306073     -1> 2016-07-07 23:48:12.542979 7f7f4449c700 10 bluestore(/mnt/ceph/build/dev/osd2) queue_transactions existing 0xac78760 osr(0.4f 0xb6d2d80)
3306074      0> 2016-07-07 23:48:12.547121 7f7f55cbf700 -1 *** Caught signal (Segmentation fault) **
3306075  in thread 7f7f55cbf700 thread_name:bstore_aio
3306076 
3306077  ceph version v11.0.0-373-g7dedce8 (7dedce8a6e0474d4d14f9aa509428bab84d075af)
3306078  1: /mnt/ceph/build/bin/ceph-osd() [0xc329ae]
3306079  2: (()+0x10a00) [0x7f7f62923a00]
3306080  3: (BlueStore::_txc_state_proc(BlueStore::TransContext*)+0x8cb) [0xb4798b]
3306081  4: (BlueStore::_txc_finish_io(BlueStore::TransContext*)+0x1bf) [0xb4801f]
3306082  5: (BlueStore::_txc_state_proc(BlueStore::TransContext*)+0x27f) [0xb4733f]
3306083  6: (KernelDevice::_aio_thread()+0x912) [0xc1a872]
3306084  7: (KernelDevice::AioCompletionThread::entry()+0xd) [0xc1d81d]
3306085  8: (()+0x761a) [0x7f7f6291a61a]
3306086  9: (clone()+0x6d) [0x7f7f6059959d]
3306087  NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.


the previous TransContext (3306060)in STATE_IO_DONE and current TransaContext call _write(3306039 ). And they handle the same object(0:f20cb07b:::rbd_data.100d2ae8944a.0000000000000095:head). So the blob_map modify be current TransContext. I always thought: objectstore don't allow the two or more write op for same object.  ObjectContext:: ondisk_write_lock will block the later write op until objectstore call on_commit/on_readable Context.
But in fact, ondisk_write_lock don't prevent other write op. 

I think the simple method is add o->flush().
Or am I missing something?

Thanks!


-----Original Message-----
From: ceph-devel-owner@vger.kernel.org [mailto:ceph-devel-owner@vger.kernel.org] On Behalf Of Somnath Roy
Sent: Wednesday, July 6, 2016 10:48 PM
To: Mark Nelson <mnelson@redhat.com>; Varada Kari <Varada.Kari@sandisk.com>; ceph-devel <ceph-devel@vger.kernel.org>
Subject: RE: segfault in bluestore during random writes

I got it ~6/23 , so we need to look for commits before that..

-----Original Message-----
From: Mark Nelson [mailto:mnelson@redhat.com]
Sent: Wednesday, July 06, 2016 7:45 AM
To: Somnath Roy; Varada Kari; ceph-devel
Subject: Re: segfault in bluestore during random writes

Ah, sorry I missed it.  Do you remember when you first encountered it? 
Might help track down the commit where it first appeared.

Mark

On 07/06/2016 09:32 AM, Somnath Roy wrote:
> Mark,
> This is the same trace I got (and posted in community)  while you were in vacation. I can still reproduce this in my setup easily.
>
> Thanks & Regards
> Somnath
>
> -----Original Message-----
> From: ceph-devel-owner@vger.kernel.org 
> [mailto:ceph-devel-owner@vger.kernel.org] On Behalf Of Mark Nelson
> Sent: Wednesday, July 06, 2016 7:02 AM
> To: Varada Kari; ceph-devel
> Subject: Re: segfault in bluestore during random writes
>
> Oh, sorry, this wasn't memdbstore, this was trim cache on reads which got applied earlier this week.  I was testing 06178de9 with the trim cache on reads PR applied.
>
> Mark
>
> On 07/06/2016 07:00 AM, Mark Nelson wrote:
>> Hi Varada,
>>
>> Ah, this version happens to be with the memstoredb patch applied, 
>> though it is unused in this test.  I don't believe this should be 
>> causing the problem, but I'll verify it is happening without that patch as well.
>>
>> Mark
>>
>> On 07/06/2016 01:45 AM, Varada Kari wrote:
>>> Hi mark,
>>>
>>> I have tried reproducing the issue with latest master, so far no 
>>> luck with 128k and 512k block sizes on a 1000GB rbd image.
>>> I couldn't find #5e07e5a3446ee39189c5b959be624411561175f5 in master, 
>>> are you using any private changes?
>>>
>>> I will try some more time today to reproduce the issue. Seems blob 
>>> map got corrupted in your case.
>>>
>>> Varada
>>>
>>> On Tuesday 05 July 2016 09:06 PM, Mark Nelson wrote:
>>>> Hi Guys,
>>>>
>>>> This is primarily for Varada but if anyone else wants to take a 
>>>> look feel free.  We are hitting segfaults in tc_state_proc during 
>>>> random writes.  I was able to reproduce with logging enabled and 
>>>> got a core dump.  I've only briefly looked at the code/logs, but I 
>>>> haven't really looked through it in earnest yet.  Unfortunately the 
>>>> logs are about 4GB and the core dump is 2GB, so I'll only attach the last 10k lines.
>>>> Hopefully it should be fairly reproducible.  I'll try to see if I 
>>>> can narrow down commits that have touched the write path over the 
>>>> last 4 weeks and see if anything looks relevant.
>>>>
>>>> Varada: let me know if you can reproduce.  Thanks!
>>>>
>>>> gdb bt:
>>>>
>>>>> (gdb) bt
>>>>> #0  0x00007f9c59708fcb in raise (sig=11) at
>>>>> ../nptl/sysdeps/unix/sysv/linux/pt-raise.c:37
>>>>> #1  0x0000000000bd7505 in reraise_fatal (signum=11) at
>>>>> /home/ubuntu/src/markhpc/ceph/src/global/signal_handler.cc:69
>>>>> #2  handle_fatal_signal (signum=11) at
>>>>> /home/ubuntu/src/markhpc/ceph/src/global/signal_handler.cc:133
>>>>> #3  <signal handler called>
>>>>> #4  next_node (node=<synthetic pointer>) at
>>>>> /usr/include/boost/intrusive/detail/tree_algorithms.hpp:446
>>>>> #5  next_node (p=<synthetic pointer>) at
>>>>> /usr/include/boost/intrusive/rbtree_algorithms.hpp:352
>>>>> #6  operator++ (this=<synthetic pointer>) at
>>>>> /usr/include/boost/intrusive/detail/tree_node.hpp:128
>>>>> #7  BlueStore::_txc_state_proc (this=this@entry=0xaff6000,
>>>>> txc=txc@entry=0x192c8c80) at
>>>>> /home/ubuntu/src/markhpc/ceph/src/os/bluestore/BlueStore.cc:4568
>>>>> #8  0x0000000000aeddb7 in BlueStore::_txc_finish_io 
>>>>> (this=this@entry=0xaff6000, txc=txc@entry=0x192c8c80) at
>>>>> /home/ubuntu/src/markhpc/ceph/src/os/bluestore/BlueStore.cc:4669
>>>>> #9  0x0000000000aed23f in BlueStore::_txc_state_proc 
>>>>> (this=0xaff6000, txc=0x192c8c80) at
>>>>> /home/ubuntu/src/markhpc/ceph/src/os/bluestore/BlueStore.cc:4559
>>>>> #10 0x0000000000bc134a in KernelDevice::_aio_thread
>>>>> (this=0xaf20960) at
>>>>> /home/ubuntu/src/markhpc/ceph/src/os/bluestore/KernelDevice.cc:270
>>>>> #11 0x0000000000bc588d in KernelDevice::AioCompletionThread::entry
>>>>> (this=<optimized out>) at
>>>>> /home/ubuntu/src/markhpc/ceph/src/os/bluestore/KernelDevice.h:49
>>>>> #12 0x00007f9c59701dc5 in start_thread (arg=0x7f9c4da2e700) at
>>>>> pthread_create.c:308
>>>>> #13 0x00007f9c575fc28d in clone () at
>>>>> ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
>>>>> (gdb) frame 7
>>>>> #7  BlueStore::_txc_state_proc (this=this@entry=0xaff6000,
>>>>> txc=txc@entry=0x192c8c80) at
>>>>> /home/ubuntu/src/markhpc/ceph/src/os/bluestore/BlueStore.cc:4568
>>>>> 4568for (auto& p : o->blob_map.blob_map) {
>>>> Mark
>>>
>>> PLEASE NOTE: The information contained in this electronic mail 
>>> message is intended only for the use of the designated recipient(s) 
>>> named above. If the reader of this message is not the intended 
>>> recipient, you are hereby notified that you have received this 
>>> message in error and that any review, dissemination, distribution, 
>>> or copying of this message is strictly prohibited. If you have 
>>> received this communication in error, please notify the sender by 
>>> telephone or e-mail (as shown above) immediately and destroy any and 
>>> all copies of this message in your possession (whether hard copies 
>>> or electronically stored copies).
>>>
>> --
>> To unsubscribe from this list: send the line "unsubscribe ceph-devel"
>> in the body of a message to majordomo@vger.kernel.org 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@vger.kernel.org More majordomo 
> info at  http://vger.kernel.org/majordomo-info.html
> PLEASE NOTE: The information contained in this electronic mail message is intended only for the use of the designated recipient(s) named above. If the reader of this message is not the intended recipient, you are hereby notified that you have received this message in error and that any review, dissemination, distribution, or copying of this message is strictly prohibited. If you have received this communication in error, please notify the sender by telephone or e-mail (as shown above) immediately and destroy any and all copies of this message in your possession (whether hard copies or electronically stored copies).
>
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at  http://vger.kernel.org/majordomo-info.html