Ceph » bluestore

This looks like a BitmapAllocator bug:

First, during mount,

2018-06-21 20:18:55.667 7f2cd2963a00 10 freelist enumerate_next 0x4800000~100000
2018-06-21 20:18:55.667 7f2cd2963a00 10 fbmap_alloc 0x0x561a576fe490 init_add_free 0x4800000~100000
2018-06-21 20:18:55.667 7f2cd2963a00 10 fbmap_alloc 0x0x561a576fe490 init_add_free done
2018-06-21 20:18:55.667 7f2cd2963a00 10 freelist enumerate_next 0x4980000~c000
2018-06-21 20:18:55.667 7f2cd2963a00 10 fbmap_alloc 0x0x561a576fe490 init_add_free 0x4980000~c000
2018-06-21 20:18:55.667 7f2cd2963a00 10 fbmap_alloc 0x0x561a576fe490 init_add_free done
2018-06-21 20:18:55.667 7f2cd2963a00 10 freelist enumerate_next 0x4a00000~100000
2018-06-21 20:18:55.667 7f2cd2963a00 10 fbmap_alloc 0x0x561a576fe490 init_add_free 0x4a00000~100000
2018-06-21 20:18:55.667 7f2cd2963a00 10 fbmap_alloc 0x0x561a576fe490 init_add_free done
2018-06-21 20:18:55.667 7f2cd2963a00 10 freelist enumerate_next 0x4bc0000~c000

then we pull out the bluefs pieces,

2018-06-21 20:18:55.667 7f2cd2963a00 10 fbmap_alloc 0x0x561a576fe490 init_rm_free 0x4800000~100000
2018-06-21 20:18:55.667 7f2cd2963a00 10 fbmap_alloc 0x0x561a576fe490 init_rm_free done
2018-06-21 20:18:55.667 7f2cd2963a00 10 fbmap_alloc 0x0x561a576fe490 init_rm_free 0x4a00000~100000
2018-06-21 20:18:55.667 7f2cd2963a00 10 fbmap_alloc 0x0x561a576fe490 init_rm_free done

Then, a bit later, we make an overlapping allocation:

2018-06-21 20:19:09.447 7f2c77040700 10 bluestore(bluestore.test_temp_dir) _balance_bluefs_freespace gifting 2097152 (2 MiB)
2018-06-21 20:19:09.447 7f2c77040700 10 fbmap_alloc 0x0x561a576fe490 allocate0x200000/100000,0,0
2018-06-21 20:19:09.447 7f2c77040700 10 fbmap_alloc 0x0x561a576fe490 allocate 0x4900000~200000/100000,0,0
2018-06-21 20:19:09.447 7f2c77040700  1 bluestore(bluestore.test_temp_dir) _balance_bluefs_freespace gifting 0x4900000~200000 to bluefs

/a/sage-2018-06-21_18:19:30-rados-wip-24598-distro-basic-smithi/2687069

A bit more detail:

0       2018-06-21 20:18:54.503 7f2c77841700 10 fbmap_alloc 0x0x561a5412e940 release 0x4980000~c000
0       2018-06-21 20:18:55.179 7f2cd2963a00 10 freelist enumerate_next 0x4980000~c000
0       2018-06-21 20:18:55.179 7f2cd2963a00 10 fbmap_alloc 0x0x561a54193590 init_add_free 0x4980000~c000
0       2018-06-21 20:18:55.243 7f2cd2963a00 10 freelist enumerate_next 0x4980000~c000
0       2018-06-21 20:18:55.667 7f2cd2963a00 10 freelist enumerate_next 0x4980000~c000
0       2018-06-21 20:18:55.667 7f2cd2963a00 10 fbmap_alloc 0x0x561a576fe490 init_add_free 0x4980000~c000
0       2018-06-21 20:18:55.827 7f2cd2963a00 10 fbmap_alloc 0x0x561a576fe490 allocate 0x4980000~c000/4000,24000,0
0       2018-06-21 20:18:55.827 7f2cd2963a00 20 bluestore(bluestore.test_temp_dir) _do_alloc_write prealloc [0x4788000~8000,0x4980000~c000,0x4bc0000~c000,0x4be0000~4000]
0       2018-06-21 20:18:55.827 7f2cd2963a00 20 bluestore(bluestore.test_temp_dir) _do_alloc_write blob Blob(0x561a608ad330 blob([0x478c000~4000,0x4980000~c000,0x4bc0000~c000] csum crc32c/0x1000) use_tracker(0x0 0x0) SharedBlob(0x561a608ad100 sbid 0x0))
0       2018-06-21 20:18:55.827 7f2cd2963a00 20 bluestore.blob(0x561a608ad330) get_ref 0x0~1c000 Blob(0x561a608ad330 blob([0x478c000~4000,0x4980000~c000,0x4bc0000~c000] csum crc32c/0x1000) use_tracker(0x0 0x0) SharedBlob(0x561a608ad100 sbid 0x0))
0       2018-06-21 20:18:55.827 7f2cd2963a00 20 bluestore(bluestore.test_temp_dir) _do_alloc_write  lex 0x10000~1c000: 0x0~1c000 Blob(0x561a608ad330 blob([0x478c000~4000,0x4980000~c000,0x4bc0000~c000] csum crc32c/0x1000) use_tracker(0x7*0x4000 0x[4000,4000,4000,4000,4000,4000,4000]) SharedBlob(0x561a608ad100 sbid 0x0))
0       2018-06-21 20:18:55.827 7f2cd2963a00 20 bluestore(bluestore.test_temp_dir) _txc_finalize_kv txc 0x561a63a90d00 allocated 0x[4788000~8000,4980000~c000,4bc0000~c000,4be0000~4000] released 0x[]
0       2018-06-21 20:18:55.827 7f2cd2963a00 10 freelist allocate 0x4980000~c000
0       2018-06-21 20:18:55.887 7f2cb50bc700 20 bluestore(bluestore.test_temp_dir) _do_read  blob Blob(0x561a608ad330 blob([0x478c000~4000,0x4980000~c000,0x4bc0000~c000] csum crc32c/0x1000) use_tracker(0x7*0x4000 0x[4000,4000,4000,4000,4000,4000,4000]) SharedBlob(0x561a608ad100 sbid 0x0)) need 0x0~1c000 cache has 0x[0~1c000]
0       2018-06-21 20:19:02.523 7f2cd2963a00 20 bluestore.blob(0x561a54423100) get_ref 0x0~1c000 Blob(0x561a54423100 blob([0x478c000~4000,0x4980000~c000,0x4bc0000~c000] csum crc32c/0x1000) use_tracker(0x0 0x0) SharedBlob(0x561a544202a0 sbid 0x0))
0       2018-06-21 20:19:02.523 7f2cd2963a00 20 bluestore.blob(0x561a54423100) put_ref 0x0~1c000 Blob(0x561a54423100 blob([0x478c000~4000,0x4980000~c000,0x4bc0000~c000] csum crc32c/0x1000) use_tracker(0x7*0x4000 0x[4000,4000,4000,4000,4000,4000,4000]) SharedBlob(0x561a544202a0 sbid 0x0))
0       2018-06-21 20:19:02.523 7f2cd2963a00 20 bluestore(bluestore.test_temp_dir) _wctx_finish  blob release [0x478c000~4000,0x4980000~c000,0x4bc0000~c000]
0       2018-06-21 20:19:02.523 7f2cd2963a00 20 bluestore(bluestore.test_temp_dir) _wctx_finish  release 0x4980000~c000
0       2018-06-21 20:19:02.523 7f2cd2963a00 20 bluestore(bluestore.test_temp_dir) _txc_finalize_kv txc 0x561a6b9c4900 allocated 0x[] released 0x[110000~4000,120000~4000,128000~4000,6e8000~8000,133c000~4000,1358000~8000,1514000~4000,2774000~8000,2fcc000~8000,3cd0000~8000,41d8000~4000,42bc000~4000,4788000~8000,4980000~c000,4bc0000~c000,4bdc000~8000,4c78000~4000,4cdc000~8000,4d00000~c000,5128000~1c000,5600000~8000,5c08000~4000,6078000~4000,60d0000~8000,6760000~8000,6a0c000~4000,6a8c000~8000,7048000~4000,7064000~8000,7170000~18000,73f8000~10000,7928000~1c000]
0       2018-06-21 20:19:02.523 7f2cd2963a00 20 bluestore(bluestore.test_temp_dir) _txc_finalize_kv release 0x4980000~c000
0       2018-06-21 20:19:02.523 7f2cd2963a00 10 freelist release 0x4980000~c000
0       2018-06-21 20:19:02.555 7f2c7683f700 10 bluestore(bluestore.test_temp_dir) _txc_release_alloc(sync) 0x561a6b9c4900 [110000~4000,120000~4000,128000~4000,6e8000~8000,133c000~4000,1358000~8000,1514000~4000,2774000~8000,2fcc000~8000,3cd0000~8000,41d8000~4000,42bc000~4000,4788000~8000,4980000~c000,4bc0000~c000,4bdc000~8000,4c78000~4000,4cdc000~8000,4d00000~c000,5128000~1c000,5600000~8000,5c08000~4000,6078000~4000,60d0000~8000,6760000~8000,6a0c000~4000,6a8c000~8000,7048000~4000,7064000~8000,7170000~18000,73f8000~10000,7928000~1c000]
0       2018-06-21 20:19:02.555 7f2c7683f700 10 fbmap_alloc 0x0x561a576fe490 release 0x4980000~c000
80000   2018-06-21 20:19:09.447 7f2c77040700 10 fbmap_alloc 0x0x561a576fe490 allocate 0x4900000~200000/100000,0,0
80000   2018-06-21 20:19:09.447 7f2c77040700  1 bluestore(bluestore.test_temp_dir) _balance_bluefs_freespace gifting 0x4900000~200000 to bluefs

(that's the output of ceph.git/src/script/bdev_grep.pl 0x4980000 on that portion of the log). That last allocation of
0x4900000~200000 looks wrong since 0x4a00000~100000 is allocated)