Project

General

Profile

Actions

Bug #18224

closed

Mass OSD failure with Bluestore

Added by Yuri Gorshkov over 7 years ago. Updated over 7 years ago.

Status:
Can't reproduce
Priority:
Normal
Assignee:
-
Category:
OSD
Target version:
-
% Done:

0%

Source:
Tags:
kraken, bluestore, osd, crash
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

Hello,

We've been testing Ceph Kraken + bluestore recently on our 4-node cluster with 96 OSDs. Suddenly we noticed that almost all OSDs went down according to monitors, but their processes stayed up (see attached graph for cluster status).

2016-12-11 02:38:56.734432 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.69 out (down for 601.356632)
2016-12-11 02:52:06.860580 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.51 out (down for 602.185805)
2016-12-11 03:02:31.924243 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.22 out (down for 604.820012)
2016-12-11 03:12:51.964473 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.86 out (down for 600.029707)
2016-12-11 08:06:57.770892 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.51 out (down for 600.095756)
2016-12-11 08:17:17.824783 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.52 out (down for 600.536756)
2016-12-11 08:17:17.824841 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.68 out (down for 600.536756)
2016-12-11 08:20:42.841671 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.17 out (down for 600.894395)
2016-12-11 08:20:47.845449 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.39 out (down for 600.880928)
2016-12-11 08:27:42.877915 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.3 out (down for 604.739737)
2016-12-11 08:27:42.877998 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.33 out (down for 604.739736)
2016-12-11 08:27:42.878041 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.63 out (down for 603.715906)
2016-12-11 08:27:42.878095 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.66 out (down for 601.702021)
2016-12-11 08:27:42.878155 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.70 out (down for 604.739736)
2016-12-11 08:31:02.904964 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.57 out (down for 601.921498)
2016-12-11 08:31:12.912004 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.11 out (down for 603.797970)
2016-12-11 08:31:12.912060 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.79 out (down for 603.797969)
2016-12-11 08:38:02.948024 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.23 out (down for 601.705864)
2016-12-11 08:38:02.948091 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.60 out (down for 601.705864)
2016-12-11 08:38:02.948130 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.89 out (down for 600.054670)
2016-12-11 08:38:07.952074 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.22 out (down for 601.022400)
2016-12-11 08:38:07.952143 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.56 out (down for 604.046908)
2016-12-11 08:38:07.952216 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.72 out (down for 602.032970)
2016-12-11 08:41:22.980888 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.46 out (down for 600.877402)
2016-12-11 08:41:22.980954 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.49 out (down for 600.877402)
2016-12-11 08:41:32.988410 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.6 out (down for 600.847142)
2016-12-11 08:41:32.988467 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.14 out (down for 600.847141)
2016-12-11 08:41:37.992867 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.64 out (down for 604.051581)
2016-12-11 08:48:28.047297 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.0 out (down for 604.939531)
2016-12-11 08:48:28.047360 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.8 out (down for 600.827902)
2016-12-11 08:48:28.047399 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.18 out (down for 601.905401)
2016-12-11 08:48:28.047446 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.27 out (down for 600.827902)
2016-12-11 08:48:28.047480 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.37 out (down for 602.919092)
2016-12-11 08:48:33.056425 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.32 out (down for 602.051636)
2016-12-11 08:48:33.056516 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.87 out (down for 604.075075)
2016-12-11 08:48:33.056565 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.94 out (down for 603.062683)
2016-12-11 08:48:48.064532 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.1 out (down for 602.653615)
2016-12-11 08:48:48.064608 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.74 out (down for 600.632117)
2016-12-11 08:51:43.097541 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.96 out (down for 603.073719)
2016-12-11 08:51:48.107028 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.41 out (down for 603.931911)
2016-12-11 08:51:48.107102 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.48 out (down for 600.795707)
2016-12-11 08:51:58.117308 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.47 out (down for 603.995153)
2016-12-11 08:52:03.126041 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.13 out (down for 600.101105)
2016-12-11 08:52:03.126136 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.55 out (down for 603.816885)
2016-12-11 08:52:08.133279 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.58 out (down for 601.673135)
2016-12-11 08:58:48.218654 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.31 out (down for 600.515754)
2016-12-11 08:58:48.218733 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.35 out (down for 600.515754)
2016-12-11 08:58:48.218783 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.71 out (down for 600.515753)
2016-12-11 08:58:53.230407 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.7 out (down for 603.079602)
2016-12-11 08:58:53.230470 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.15 out (down for 603.079602)
2016-12-11 08:58:53.230512 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.28 out (down for 603.079601)
2016-12-11 08:58:53.230570 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.30 out (down for 603.079600)
2016-12-11 08:58:53.230617 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.40 out (down for 604.127899)
2016-12-11 08:58:53.230719 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.73 out (down for 604.127897)
2016-12-11 08:58:53.230767 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.95 out (down for 603.079598)
2016-12-11 08:58:58.248923 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.26 out (down for 603.764603)
2016-12-11 08:59:13.336434 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.19 out (down for 603.616749)
2016-12-11 08:59:13.336507 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.54 out (down for 600.578905)
2016-12-11 08:59:13.336548 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.59 out (down for 603.616747)
2016-12-11 08:59:18.349427 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.43 out (down for 602.109370)
2016-12-11 09:02:03.375043 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.91 out (down for 601.007010)
2016-12-11 09:02:08.384249 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.67 out (down for 600.224936)
2016-12-11 09:02:13.392412 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.50 out (down for 601.975234)
2016-12-11 09:02:23.401983 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.65 out (down for 600.216345)
2016-12-11 09:02:28.411493 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.61 out (down for 600.735307)
2016-12-11 09:02:28.411554 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.93 out (down for 601.763907)
2016-12-11 09:02:33.424856 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.90 out (down for 602.572448)
2016-12-11 09:02:38.435351 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.86 out (down for 604.405833)
2016-12-11 09:09:13.487424 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.44 out (down for 604.030902)
2016-12-11 09:09:18.504027 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.16 out (down for 603.091040)
2016-12-11 09:09:18.504074 7f729f3a0700  0 log_channel(cluster) log [INF] : osd.80 out (down for 604.120863)

Log for OSD 51:

   -32> 2016-12-11 07:42:25.463805 7fa4d0417700 10 monclient(hunting): picked mon.node03 con 0x7fa520d3a800 addr 192.168.36.7:6789/0
   -31> 2016-12-11 07:42:25.463840 7fa4d0417700 10 monclient(hunting): _send_mon_message to mon.node03 at 192.168.36.7:6789/0
   -30> 2016-12-11 07:42:25.463848 7fa4d0417700  1 -- 192.168.36.7:6829/1947980 --> 192.168.36.7:6789/0 -- auth(proto 0 27 bytes epoch 1) v1 -- 0x7fa517a02640 con 0
   -29> 2016-12-11 07:42:25.463870 7fa4d0417700 10 monclient(hunting): renew_subs
   -28> 2016-12-11 07:42:55.463985 7fa4d0417700 10 monclient(hunting): tick
   -27> 2016-12-11 07:42:55.464015 7fa4d0417700  1 monclient(hunting): continuing hunt
   -26> 2016-12-11 07:42:55.464019 7fa4d0417700 10 monclient(hunting): _reopen_session rank -1 name 
   -25> 2016-12-11 07:42:55.464030 7fa4d0417700  1 -- 192.168.36.7:6829/1947980 >> 192.168.36.7:6789/0 conn(0x7fa520d3a800 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=1).mark_down
   -24> 2016-12-11 07:42:55.464054 7fa4d0417700  2 -- 192.168.36.7:6829/1947980 >> 192.168.36.7:6789/0 conn(0x7fa520d3a800 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=1)._stop
   -23> 2016-12-11 07:42:55.464120 7fa4d0417700 10 monclient(hunting): picked mon.node02 con 0x7fa520d48000 addr 192.168.36.6:6789/0
   -22> 2016-12-11 07:42:55.464137 7fa4d0417700 10 monclient(hunting): _send_mon_message to mon.node02 at 192.168.36.6:6789/0
   -21> 2016-12-11 07:42:55.464143 7fa4d0417700  1 -- 192.168.36.7:6829/1947980 --> 192.168.36.6:6789/0 -- auth(proto 0 27 bytes epoch 1) v1 -- 0x7fa517a02640 con 0
   -20> 2016-12-11 07:42:55.464168 7fa4d0417700 10 monclient(hunting): renew_subs
   -19> 2016-12-11 07:43:25.464258 7fa4d0417700 10 monclient(hunting): tick
   -18> 2016-12-11 07:43:25.464284 7fa4d0417700  1 monclient(hunting): continuing hunt
   -17> 2016-12-11 07:43:25.464288 7fa4d0417700 10 monclient(hunting): _reopen_session rank -1 name 
   -16> 2016-12-11 07:43:25.464314 7fa4d0417700  1 -- 192.168.36.7:6829/1947980 >> 192.168.36.6:6789/0 conn(0x7fa520d48000 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=1).mark_down
   -15> 2016-12-11 07:43:25.464338 7fa4d0417700  2 -- 192.168.36.7:6829/1947980 >> 192.168.36.6:6789/0 conn(0x7fa520d48000 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=1)._stop
   -14> 2016-12-11 07:43:25.464391 7fa4d0417700 10 monclient(hunting): picked mon.node03 con 0x7fa520d49800 addr 192.168.36.7:6789/0
   -13> 2016-12-11 07:43:25.464410 7fa4d0417700 10 monclient(hunting): _send_mon_message to mon.node03 at 192.168.36.7:6789/0
   -12> 2016-12-11 07:43:25.464417 7fa4d0417700  1 -- 192.168.36.7:6829/1947980 --> 192.168.36.7:6789/0 -- auth(proto 0 27 bytes epoch 1) v1 -- 0x7fa517a02640 con 0
   -11> 2016-12-11 07:43:25.464435 7fa4d0417700 10 monclient(hunting): renew_subs
   -10> 2016-12-11 07:43:55.464520 7fa4d0417700 10 monclient(hunting): tick
    -9> 2016-12-11 07:43:55.464542 7fa4d0417700  1 monclient(hunting): continuing hunt
    -8> 2016-12-11 07:43:55.464546 7fa4d0417700 10 monclient(hunting): _reopen_session rank -1 name 
    -7> 2016-12-11 07:43:55.464558 7fa4d0417700  1 -- 192.168.36.7:6829/1947980 >> 192.168.36.7:6789/0 conn(0x7fa520d49800 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=1).mark_down
    -6> 2016-12-11 07:43:55.464579 7fa4d0417700  2 -- 192.168.36.7:6829/1947980 >> 192.168.36.7:6789/0 conn(0x7fa520d49800 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=1)._stop
    -5> 2016-12-11 07:43:55.464638 7fa4d0417700 10 monclient(hunting): picked mon.node02 con 0x7fa520d4b000 addr 192.168.36.6:6789/0
    -4> 2016-12-11 07:43:55.464660 7fa4d0417700 10 monclient(hunting): _send_mon_message to mon.node02 at 192.168.36.6:6789/0
    -3> 2016-12-11 07:43:55.464668 7fa4d0417700  1 -- 192.168.36.7:6829/1947980 --> 192.168.36.6:6789/0 -- auth(proto 0 27 bytes epoch 1) v1 -- 0x7fa517a02640 con 0
    -2> 2016-12-11 07:43:55.464688 7fa4d0417700 10 monclient(hunting): renew_subs
    -1> 2016-12-11 07:44:11.650749 7fa4d241b700 -1 bdev(/var/lib/ceph/osd/ceph-51/block.wal)  aio submit got (22) Invalid argument
     0> 2016-12-11 07:44:11.655085 7fa4d241b700 -1 /mnt/jenkins/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/11.0.2/rpm/el7/BUILD/ceph-11.0.2/src/os/bluestore/KernelDevice.cc: In function 'virtual void KernelDevice::aio_submit(IOContext*)' thread 7fa4d241b700 time 2016-12-11 07:44:11.650793
/mnt/jenkins/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/11.0.2/rpm/el7/BUILD/ceph-11.0.2/src/os/bluestore/KernelDevice.cc: 370: FAILED assert(r == 0)

 ceph version v11.0.2 (697fe64f9f106252c49a2c4fe4d79aea29363be7)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x85) [0x7fa4e90c8b35]
 2: (KernelDevice::aio_submit(IOContext*)+0x799) [0x7fa4e8f18d59]
 3: (BlueFS::_flush_range(BlueFS::FileWriter*, unsigned long, unsigned long)+0xdad) [0x7fa4e8ef547d]
 4: (BlueFS::_flush(BlueFS::FileWriter*, bool)+0x119) [0x7fa4e8ef6529]
 5: (BlueRocksWritableFile::Flush()+0x3a) [0x7fa4e8f0fcca]
 6: (rocksdb::WritableFileWriter::Flush()+0xab) [0x7fa4e901058b]
 7: (rocksdb::log::Writer::EmitPhysicalRecord(rocksdb::log::RecordType, char const*, unsigned long)+0x136) [0x7fa4e8f9bc56]
 8: (rocksdb::log::Writer::AddRecord(rocksdb::Slice const&)+0x110) [0x7fa4e8f9be20]
 9: (rocksdb::DBImpl::WriteImpl(rocksdb::WriteOptions const&, rocksdb::WriteBatch*, rocksdb::WriteCallback*, unsigned long*, unsigned long, bool)+0x1290) [0x7fa4e8f629d0]
 10: (rocksdb::DBImpl::Write(rocksdb::WriteOptions const&, rocksdb::WriteBatch*)+0x27) [0x7fa4e8f63717]
 11: (RocksDBStore::submit_transaction(std::shared_ptr<KeyValueDB::TransactionImpl>)+0xc7) [0x7fa4e8e934b7]
 12: (BlueStore::_kv_sync_thread()+0xbd1) [0x7fa4e8e5dcb1]
 13: (BlueStore::KVSyncThread::entry()+0xd) [0x7fa4e8e6cced]
 14: (()+0x7dc5) [0x7fa4e5344dc5]
 15: (clone()+0x6d) [0x7fa4e422bced]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- logging levels ---
   0/ 5 none
   0/ 1 lockdep
   0/ 1 context
   1/ 1 crush
   1/ 5 mds
   1/ 5 mds_balancer
   1/ 5 mds_locker
   1/ 5 mds_log
   1/ 5 mds_log_expire
   1/ 5 mds_migrator
   0/ 1 buffer
   0/ 1 timer
   0/ 1 filer
   0/ 1 striper
   0/ 1 objecter
   0/ 5 rados
   0/ 5 rbd
   0/ 5 rbd_mirror
   0/ 5 rbd_replay
   0/ 5 journaler
   0/ 5 objectcacher
   0/ 5 client
   0/ 5 osd
   0/ 5 optracker
   0/ 5 objclass
   1/ 3 filestore
   1/ 3 journal
   0/ 5 ms
   1/ 5 mon
   0/10 monc
   1/ 5 paxos
   0/ 5 tp
   1/ 5 auth
   1/ 5 crypto
   1/ 1 finisher
   1/ 5 heartbeatmap
   1/ 5 perfcounter
   1/ 5 rgw
   1/10 civetweb
   1/ 5 javaclient
   1/ 5 asok
   1/ 1 throttle
   0/ 0 refs
   1/ 5 xio
   1/ 5 compressor
   1/ 5 newstore
   1/ 5 bluestore
   1/ 5 bluefs
   1/ 3 bdev
   1/ 5 kstore
   4/ 5 rocksdb
   4/ 5 leveldb
   4/ 5 memdb
   1/ 5 kinetic
   1/ 5 fuse
   1/ 5 mgr
   1/ 5 mgrc
  -2/-2 (syslog threshold)
  -1/-1 (stderr threshold)
  max_recent     10000
  max_new         1000
  log_file /var/log/ceph/ceph-osd.51.log
--- end dump of recent events ---
2016-12-11 07:44:11.700910 7fa4d241b700 -1 *** Caught signal (Aborted) **
 in thread 7fa4d241b700 thread_name:bstore_kv_sync

 ceph version v11.0.2 (697fe64f9f106252c49a2c4fe4d79aea29363be7)
 1: (()+0x89c39a) [0x7fa4e8f3a39a]
 2: (()+0xf100) [0x7fa4e534c100]
 3: (gsignal()+0x37) [0x7fa4e416a5f7]
 4: (abort()+0x148) [0x7fa4e416bce8]
 5: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x267) [0x7fa4e90c8d17]
 6: (KernelDevice::aio_submit(IOContext*)+0x799) [0x7fa4e8f18d59]
 7: (BlueFS::_flush_range(BlueFS::FileWriter*, unsigned long, unsigned long)+0xdad) [0x7fa4e8ef547d]
 8: (BlueFS::_flush(BlueFS::FileWriter*, bool)+0x119) [0x7fa4e8ef6529]
 9: (BlueRocksWritableFile::Flush()+0x3a) [0x7fa4e8f0fcca]
 10: (rocksdb::WritableFileWriter::Flush()+0xab) [0x7fa4e901058b]
 11: (rocksdb::log::Writer::EmitPhysicalRecord(rocksdb::log::RecordType, char const*, unsigned long)+0x136) [0x7fa4e8f9bc56]
 12: (rocksdb::log::Writer::AddRecord(rocksdb::Slice const&)+0x110) [0x7fa4e8f9be20]
 13: (rocksdb::DBImpl::WriteImpl(rocksdb::WriteOptions const&, rocksdb::WriteBatch*, rocksdb::WriteCallback*, unsigned long*, unsigned long, bool)+0x1290) [0x7fa4e8f629d0]
 14: (rocksdb::DBImpl::Write(rocksdb::WriteOptions const&, rocksdb::WriteBatch*)+0x27) [0x7fa4e8f63717]
 15: (RocksDBStore::submit_transaction(std::shared_ptr<KeyValueDB::TransactionImpl>)+0xc7) [0x7fa4e8e934b7]
 16: (BlueStore::_kv_sync_thread()+0xbd1) [0x7fa4e8e5dcb1]
 17: (BlueStore::KVSyncThread::entry()+0xd) [0x7fa4e8e6cced]
 18: (()+0x7dc5) [0x7fa4e5344dc5]
 19: (clone()+0x6d) [0x7fa4e422bced]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- begin dump of recent events ---
     0> 2016-12-11 07:44:11.700910 7fa4d241b700 -1 *** Caught signal (Aborted) **
 in thread 7fa4d241b700 thread_name:bstore_kv_sync

 ceph version v11.0.2 (697fe64f9f106252c49a2c4fe4d79aea29363be7)
 1: (()+0x89c39a) [0x7fa4e8f3a39a]
 2: (()+0xf100) [0x7fa4e534c100]
 3: (gsignal()+0x37) [0x7fa4e416a5f7]
 4: (abort()+0x148) [0x7fa4e416bce8]
 5: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x267) [0x7fa4e90c8d17]
 6: (KernelDevice::aio_submit(IOContext*)+0x799) [0x7fa4e8f18d59]
 7: (BlueFS::_flush_range(BlueFS::FileWriter*, unsigned long, unsigned long)+0xdad) [0x7fa4e8ef547d]
 8: (BlueFS::_flush(BlueFS::FileWriter*, bool)+0x119) [0x7fa4e8ef6529]
 9: (BlueRocksWritableFile::Flush()+0x3a) [0x7fa4e8f0fcca]
 10: (rocksdb::WritableFileWriter::Flush()+0xab) [0x7fa4e901058b]
 11: (rocksdb::log::Writer::EmitPhysicalRecord(rocksdb::log::RecordType, char const*, unsigned long)+0x136) [0x7fa4e8f9bc56]
 12: (rocksdb::log::Writer::AddRecord(rocksdb::Slice const&)+0x110) [0x7fa4e8f9be20]
 13: (rocksdb::DBImpl::WriteImpl(rocksdb::WriteOptions const&, rocksdb::WriteBatch*, rocksdb::WriteCallback*, unsigned long*, unsigned long, bool)+0x1290) [0x7fa4e8f629d0]
 14: (rocksdb::DBImpl::Write(rocksdb::WriteOptions const&, rocksdb::WriteBatch*)+0x27) [0x7fa4e8f63717]
 15: (RocksDBStore::submit_transaction(std::shared_ptr<KeyValueDB::TransactionImpl>)+0xc7) [0x7fa4e8e934b7]
 16: (BlueStore::_kv_sync_thread()+0xbd1) [0x7fa4e8e5dcb1]
 17: (BlueStore::KVSyncThread::entry()+0xd) [0x7fa4e8e6cced]
 18: (()+0x7dc5) [0x7fa4e5344dc5]
 19: (clone()+0x6d) [0x7fa4e422bced]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- logging levels ---
   0/ 5 none
   0/ 1 lockdep
   0/ 1 context
   1/ 1 crush
   1/ 5 mds
   1/ 5 mds_balancer
   1/ 5 mds_locker
   1/ 5 mds_log
   1/ 5 mds_log_expire
   1/ 5 mds_migrator
   0/ 1 buffer
   0/ 1 timer
   0/ 1 filer
   0/ 1 striper
   0/ 1 objecter
   0/ 5 rados
   0/ 5 rbd
   0/ 5 rbd_mirror
   0/ 5 rbd_replay
   0/ 5 journaler
   0/ 5 objectcacher
   0/ 5 client
   0/ 5 osd
   0/ 5 optracker
   0/ 5 objclass
   1/ 3 filestore
   1/ 3 journal
   0/ 5 ms
   1/ 5 mon
   0/10 monc
   1/ 5 paxos
   0/ 5 tp
   1/ 5 auth
   1/ 5 crypto
   1/ 1 finisher
   1/ 5 heartbeatmap
   1/ 5 perfcounter
   1/ 5 rgw
   1/10 civetweb
   1/ 5 javaclient
   1/ 5 asok
   1/ 1 throttle
   0/ 0 refs
   1/ 5 xio
   1/ 5 compressor
   1/ 5 newstore
   1/ 5 bluestore
   1/ 5 bluefs
   1/ 3 bdev
   1/ 5 kstore
   4/ 5 rocksdb
   4/ 5 leveldb
   4/ 5 memdb
   1/ 5 kinetic
   1/ 5 fuse
   1/ 5 mgr
   1/ 5 mgrc
  -2/-2 (syslog threshold)
  -1/-1 (stderr threshold)
  max_recent     10000
  max_new         1000
  log_file /var/log/ceph/ceph-osd.51.log
--- end dump of recent events ---
2016-12-11 07:44:11.985599 7f6d6a4e3800 -1 WARNING: the following dangerous and experimental features are enabled: bluestore,rocksdb
2016-12-11 07:44:11.985605 7f6d6a4e3800  0 set uid:gid to 167:167 (ceph:ceph)
2016-12-11 07:44:11.985622 7f6d6a4e3800  0 ceph version v11.0.2 (697fe64f9f106252c49a2c4fe4d79aea29363be7), process ceph-osd, pid 2001423
2016-12-11 07:44:11.985675 7f6d6a4e3800 -1 WARNING: experimental feature 'bluestore' is enabled
Please be aware that this feature is experimental, untested,
unsupported, and may result in data corruption, data loss,
and/or irreparable damage to your cluster.  Do not use
feature with important data.

2016-12-11 07:44:11.990513 7f6d6a4e3800  0 pidfile_write: ignore empty --pid-file
2016-12-11 07:44:12.010893 7f6d6a4e3800 -1 WARNING: the following dangerous and experimental features are enabled: bluestore,rocksdb
2016-12-11 07:44:12.017812 7f6d6a4e3800  1 bluestore(/var/lib/ceph/osd/ceph-51) mount path /var/lib/ceph/osd/ceph-51
2016-12-11 07:44:12.017848 7f6d6a4e3800  1 bdev create path /var/lib/ceph/osd/ceph-51/block type kernel
2016-12-11 07:44:12.018381 7f6d6a4e3800  1 bdev(/var/lib/ceph/osd/ceph-51/block) open path /var/lib/ceph/osd/ceph-51/block
2016-12-11 07:44:12.018646 7f6d6a4e3800  1 bdev(/var/lib/ceph/osd/ceph-51/block) open size 2000091680768 (0x1d1aec11000, 1862 GB) block_size 4096 (4096 B) non-rotational
2016-12-11 07:44:12.018854 7f6d6a4e3800  1 bdev create path /var/lib/ceph/osd/ceph-51/block.db type kernel
2016-12-11 07:44:12.019359 7f6d6a4e3800  1 bdev(/var/lib/ceph/osd/ceph-51/block.db) open path /var/lib/ceph/osd/ceph-51/block.db
2016-12-11 07:44:12.019552 7f6d6a4e3800  1 bdev(/var/lib/ceph/osd/ceph-51/block.db) open size 67108864 (0x4000000, 65536 kB) block_size 4096 (4096 B) non-rotational
2016-12-11 07:44:12.019558 7f6d6a4e3800  1 bluefs add_block_device bdev 1 path /var/lib/ceph/osd/ceph-51/block.db size 65536 kB
2016-12-11 07:44:12.019700 7f6d6a4e3800  1 bdev create path /var/lib/ceph/osd/ceph-51/block type kernel
2016-12-11 07:44:12.020180 7f6d6a4e3800  1 bdev(/var/lib/ceph/osd/ceph-51/block) open path /var/lib/ceph/osd/ceph-51/block
2016-12-11 07:44:12.020355 7f6d6a4e3800  1 bdev(/var/lib/ceph/osd/ceph-51/block) open size 2000091680768 (0x1d1aec11000, 1862 GB) block_size 4096 (4096 B) non-rotational
2016-12-11 07:44:12.020361 7f6d6a4e3800  1 bluefs add_block_device bdev 2 path /var/lib/ceph/osd/ceph-51/block size 1862 GB
2016-12-11 07:44:12.020372 7f6d6a4e3800  1 bdev create path /var/lib/ceph/osd/ceph-51/block.wal type kernel
2016-12-11 07:44:12.020842 7f6d6a4e3800  1 bdev(/var/lib/ceph/osd/ceph-51/block.wal) open path /var/lib/ceph/osd/ceph-51/block.wal
2016-12-11 07:44:12.021015 7f6d6a4e3800  1 bdev(/var/lib/ceph/osd/ceph-51/block.wal) open size 134217728 (0x8000000, 128 MB) block_size 4096 (4096 B) non-rotational
2016-12-11 07:44:12.021021 7f6d6a4e3800  1 bluefs add_block_device bdev 0 path /var/lib/ceph/osd/ceph-51/block.wal size 128 MB
2016-12-11 07:44:12.021178 7f6d6a4e3800  1 bluefs mount
2016-12-11 07:44:12.392532 7f6d6a4e3800 -1 WARNING: experimental feature 'rocksdb' is enabled
Please be aware that this feature is experimental, untested,
unsupported, and may result in data corruption, data loss,
and/or irreparable damage to your cluster.  Do not use
feature with important data.

2016-12-11 07:44:12.392625 7f6d6a4e3800  0  set rocksdb option compression = kNoCompression
2016-12-11 07:44:12.392633 7f6d6a4e3800  0  set rocksdb option max_write_buffer_number = 16
2016-12-11 07:44:12.392637 7f6d6a4e3800  0  set rocksdb option min_write_buffer_number_to_merge = 3
2016-12-11 07:44:12.392644 7f6d6a4e3800  0  set rocksdb option recycle_log_file_num = 16
2016-12-11 07:44:12.392690 7f6d6a4e3800  0  set rocksdb option compression = kNoCompression
2016-12-11 07:44:12.392696 7f6d6a4e3800  0  set rocksdb option max_write_buffer_number = 16
2016-12-11 07:44:12.392700 7f6d6a4e3800  0  set rocksdb option min_write_buffer_number_to_merge = 3
2016-12-11 07:44:12.392703 7f6d6a4e3800  0  set rocksdb option recycle_log_file_num = 16
2016-12-11 07:44:12.392832 7f6d6a4e3800  4 rocksdb: RocksDB version: 4.12.0

2016-12-11 07:44:12.392841 7f6d6a4e3800  4 rocksdb: Git sha rocksdb_build_git_sha:
2016-12-11 07:44:12.392843 7f6d6a4e3800  4 rocksdb: Compile date Oct 17 2016
2016-12-11 07:44:12.392846 7f6d6a4e3800  4 rocksdb: DB SUMMARY

2016-12-11 07:44:12.392862 7f6d6a4e3800  4 rocksdb: CURRENT file:  CURRENT

2016-12-11 07:44:12.392864 7f6d6a4e3800  4 rocksdb: IDENTITY file:  IDENTITY

2016-12-11 07:44:12.392872 7f6d6a4e3800  4 rocksdb: MANIFEST file:  MANIFEST-000064 size: 1776 Bytes

2016-12-11 07:44:12.392876 7f6d6a4e3800  4 rocksdb: SST files in db dir, Total Num: 2, files: 000062.sst 000063.sst 

2016-12-11 07:44:12.392885 7f6d6a4e3800  4 rocksdb: SST files in db.slow dir, Total Num: 9, files: 000054.sst 000055.sst 000056.sst 000057.sst 000058.sst 000059.sst 000060.sst 000062.sst 000063.sst 

2016-12-11 07:44:12.392893 7f6d6a4e3800  4 rocksdb: Write Ahead Log file in db.wal: 000065.log size: 65495555 ; 000068.log size: 8837163 ; 

2016-12-11 07:44:12.392895 7f6d6a4e3800  4 rocksdb:          Options.error_if_exists: 0
2016-12-11 07:44:12.392897 7f6d6a4e3800  4 rocksdb:        Options.create_if_missing: 0
2016-12-11 07:44:12.392897 7f6d6a4e3800  4 rocksdb:          Options.paranoid_checks: 1
2016-12-11 07:44:12.392899 7f6d6a4e3800  4 rocksdb:                      Options.env: 0x7f6d757a2920
2016-12-11 07:44:12.392900 7f6d6a4e3800  4 rocksdb:                 Options.info_log: 0x7f6d757a2c20
2016-12-11 07:44:12.392901 7f6d6a4e3800  4 rocksdb:           Options.max_open_files: -1
2016-12-11 07:44:12.392902 7f6d6a4e3800  4 rocksdb: Options.max_file_opening_threads: 16
2016-12-11 07:44:12.392903 7f6d6a4e3800  4 rocksdb:       Options.max_total_wal_size: 0
2016-12-11 07:44:12.392904 7f6d6a4e3800  4 rocksdb:        Options.disableDataSync: 0
2016-12-11 07:44:12.392905 7f6d6a4e3800  4 rocksdb:              Options.use_fsync: 0
2016-12-11 07:44:12.392906 7f6d6a4e3800  4 rocksdb:      Options.max_log_file_size: 0
2016-12-11 07:44:12.392907 7f6d6a4e3800  4 rocksdb: Options.max_manifest_file_size: 18446744073709551615
2016-12-11 07:44:12.392908 7f6d6a4e3800  4 rocksdb:      Options.log_file_time_to_roll: 0
2016-12-11 07:44:12.392910 7f6d6a4e3800  4 rocksdb:      Options.keep_log_file_num: 1000
2016-12-11 07:44:12.392910 7f6d6a4e3800  4 rocksdb:   Options.recycle_log_file_num: 16
2016-12-11 07:44:12.392911 7f6d6a4e3800  4 rocksdb:        Options.allow_os_buffer: 1
2016-12-11 07:44:12.392912 7f6d6a4e3800  4 rocksdb:       Options.allow_mmap_reads: 0
2016-12-11 07:44:12.392913 7f6d6a4e3800  4 rocksdb:       Options.allow_fallocate: 1
2016-12-11 07:44:12.392915 7f6d6a4e3800  4 rocksdb:      Options.allow_mmap_writes: 0
2016-12-11 07:44:12.392916 7f6d6a4e3800  4 rocksdb:          Options.create_missing_column_families: 0
2016-12-11 07:44:12.392917 7f6d6a4e3800  4 rocksdb:                              Options.db_log_dir: 
2016-12-11 07:44:12.392918 7f6d6a4e3800  4 rocksdb:                                 Options.wal_dir: db.wal
2016-12-11 07:44:12.392919 7f6d6a4e3800  4 rocksdb:                Options.table_cache_numshardbits: 6
2016-12-11 07:44:12.392920 7f6d6a4e3800  4 rocksdb:     Options.delete_obsolete_files_period_micros: 21600000000
2016-12-11 07:44:12.392920 7f6d6a4e3800  4 rocksdb:              Options.base_background_compactions: 1
2016-12-11 07:44:12.392922 7f6d6a4e3800  4 rocksdb:              Options.max_background_compactions: 1
2016-12-11 07:44:12.392922 7f6d6a4e3800  4 rocksdb:                      Options.max_subcompactions: 1
2016-12-11 07:44:12.392923 7f6d6a4e3800  4 rocksdb:                  Options.max_background_flushes: 1
2016-12-11 07:44:12.392924 7f6d6a4e3800  4 rocksdb:                         Options.WAL_ttl_seconds: 0
2016-12-11 07:44:12.392925 7f6d6a4e3800  4 rocksdb:                       Options.WAL_size_limit_MB: 0
2016-12-11 07:44:12.392925 7f6d6a4e3800  4 rocksdb:             Options.manifest_preallocation_size: 4194304
2016-12-11 07:44:12.392926 7f6d6a4e3800  4 rocksdb:                          Options.allow_os_buffer: 1
2016-12-11 07:44:12.392927 7f6d6a4e3800  4 rocksdb:                         Options.allow_mmap_reads: 0
2016-12-11 07:44:12.392927 7f6d6a4e3800  4 rocksdb:                        Options.allow_mmap_writes: 0
2016-12-11 07:44:12.392928 7f6d6a4e3800  4 rocksdb:                      Options.is_fd_close_on_exec: 1
2016-12-11 07:44:12.392929 7f6d6a4e3800  4 rocksdb:                    Options.stats_dump_period_sec: 600
2016-12-11 07:44:12.392930 7f6d6a4e3800  4 rocksdb:                    Options.advise_random_on_open: 1
2016-12-11 07:44:12.392931 7f6d6a4e3800  4 rocksdb:                     Options.db_write_buffer_size: 0d
2016-12-11 07:44:12.392932 7f6d6a4e3800  4 rocksdb:          Options.access_hint_on_compaction_start: NORMAL
2016-12-11 07:44:12.392932 7f6d6a4e3800  4 rocksdb:   Options.new_table_reader_for_compaction_inputs: 0
2016-12-11 07:44:12.392951 7f6d6a4e3800  4 rocksdb:                Options.compaction_readahead_size: 0d
2016-12-11 07:44:12.392953 7f6d6a4e3800  4 rocksdb:                Options.random_access_max_buffer_size: 1048576d
2016-12-11 07:44:12.392954 7f6d6a4e3800  4 rocksdb:               Options.writable_file_max_buffer_size: 1048576d
2016-12-11 07:44:12.392955 7f6d6a4e3800  4 rocksdb:                       Options.use_adaptive_mutex: 0
2016-12-11 07:44:12.392955 7f6d6a4e3800  4 rocksdb:                             Options.rate_limiter: (nil)
2016-12-11 07:44:12.392957 7f6d6a4e3800  4 rocksdb:      Options.sst_file_manager.rate_bytes_per_sec: 0
2016-12-11 07:44:12.392957 7f6d6a4e3800  4 rocksdb:                           Options.bytes_per_sync: 0
2016-12-11 07:44:12.392958 7f6d6a4e3800  4 rocksdb:                       Options.wal_bytes_per_sync: 0
2016-12-11 07:44:12.392959 7f6d6a4e3800  4 rocksdb:                        Options.wal_recovery_mode: 0
2016-12-11 07:44:12.392959 7f6d6a4e3800  4 rocksdb:                   Options.enable_thread_tracking: 0
2016-12-11 07:44:12.392960 7f6d6a4e3800  4 rocksdb:          Options.allow_concurrent_memtable_write: 0
2016-12-11 07:44:12.392960 7f6d6a4e3800  4 rocksdb:       Options.enable_write_thread_adaptive_yield: 0
2016-12-11 07:44:12.392961 7f6d6a4e3800  4 rocksdb:              Options.write_thread_max_yield_usec: 100
2016-12-11 07:44:12.392962 7f6d6a4e3800  4 rocksdb:             Options.write_thread_slow_yield_usec: 3
2016-12-11 07:44:12.392962 7f6d6a4e3800  4 rocksdb:                                Options.row_cache: None
2016-12-11 07:44:12.392963 7f6d6a4e3800  4 rocksdb:        Options.wal_filter: None
2016-12-11 07:44:12.392964 7f6d6a4e3800  4 rocksdb:                     Options.avoid_flush_during_recovery: 0
2016-12-11 07:44:12.392965 7f6d6a4e3800  4 rocksdb: Compression algorithms supported:
2016-12-11 07:44:12.392966 7f6d6a4e3800  4 rocksdb:     Snappy supported: 1
2016-12-11 07:44:12.392967 7f6d6a4e3800  4 rocksdb:     Zlib supported: 1
2016-12-11 07:44:12.392968 7f6d6a4e3800  4 rocksdb:     Bzip supported: 0
2016-12-11 07:44:12.392968 7f6d6a4e3800  4 rocksdb:     LZ4 supported: 0
2016-12-11 07:44:12.392969 7f6d6a4e3800  4 rocksdb: Fast CRC32 supported: 0
2016-12-11 07:44:12.400573 7f6d6a4e3800  4 rocksdb: Recovering from manifest file: MANIFEST-000064

2016-12-11 07:44:12.400650 7f6d6a4e3800  4 rocksdb: --------------- Options for column family [default]:

2016-12-11 07:44:12.400661 7f6d6a4e3800  4 rocksdb:               Options.comparator: rocksdb.InternalKeyComparator:leveldb.BytewiseComparator
2016-12-11 07:44:12.400687 7f6d6a4e3800  4 rocksdb:           Options.merge_operator: .T:int64_array.b:bitwise_xor
2016-12-11 07:44:12.400692 7f6d6a4e3800  4 rocksdb:        Options.compaction_filter: None
2016-12-11 07:44:12.400693 7f6d6a4e3800  4 rocksdb:        Options.compaction_filter_factory: None
2016-12-11 07:44:12.400693 7f6d6a4e3800  4 rocksdb:         Options.memtable_factory: SkipListFactory
2016-12-11 07:44:12.400694 7f6d6a4e3800  4 rocksdb:            Options.table_factory: BlockBasedTable
2016-12-11 07:44:12.400710 7f6d6a4e3800  4 rocksdb:            table_factory options:   flush_block_policy_factory: FlushBlockBySizePolicyFactory (0x7f6d755a2118)
  cache_index_and_filter_blocks: 0
  pin_l0_filter_and_index_blocks_in_cache: 0
  index_type: 0
  hash_index_allow_collision: 1
  checksum: 1
  no_block_cache: 0
  block_cache: 0x7f6d755dc318
  block_cache_size: 134217728
  block_cache_compressed: (nil)
  block_size: 4096
  block_size_deviation: 10
  block_restart_interval: 16
  index_block_restart_interval: 1
  filter_policy: nullptr
  whole_key_filtering: 1
  skip_table_builder_flush: 0
  format_version: 2

2016-12-11 07:44:12.400714 7f6d6a4e3800  4 rocksdb:        Options.write_buffer_size: 67108864
2016-12-11 07:44:12.400715 7f6d6a4e3800  4 rocksdb:  Options.max_write_buffer_number: 16
2016-12-11 07:44:12.400718 7f6d6a4e3800  4 rocksdb:          Options.compression: NoCompression
2016-12-11 07:44:12.400719 7f6d6a4e3800  4 rocksdb:                  Options.bottommost_compression: Disabled
2016-12-11 07:44:12.400720 7f6d6a4e3800  4 rocksdb:       Options.prefix_extractor: nullptr
2016-12-11 07:44:12.400721 7f6d6a4e3800  4 rocksdb:             Options.num_levels: 7
2016-12-11 07:44:12.400722 7f6d6a4e3800  4 rocksdb:        Options.min_write_buffer_number_to_merge: 3
2016-12-11 07:44:12.400723 7f6d6a4e3800  4 rocksdb:     Options.max_write_buffer_number_to_maintain: 0
2016-12-11 07:44:12.400724 7f6d6a4e3800  4 rocksdb:            Options.compression_opts.window_bits: -14
2016-12-11 07:44:12.400725 7f6d6a4e3800  4 rocksdb:                  Options.compression_opts.level: -1
2016-12-11 07:44:12.400726 7f6d6a4e3800  4 rocksdb:               Options.compression_opts.strategy: 0
2016-12-11 07:44:12.400726 7f6d6a4e3800  4 rocksdb:         Options.compression_opts.max_dict_bytes: 0
2016-12-11 07:44:12.400727 7f6d6a4e3800  4 rocksdb:      Options.level0_file_num_compaction_trigger: 4
2016-12-11 07:44:12.400727 7f6d6a4e3800  4 rocksdb:          Options.level0_slowdown_writes_trigger: 20
2016-12-11 07:44:12.400728 7f6d6a4e3800  4 rocksdb:              Options.level0_stop_writes_trigger: 24
2016-12-11 07:44:12.400729 7f6d6a4e3800  4 rocksdb:                   Options.target_file_size_base: 67108864
2016-12-11 07:44:12.400730 7f6d6a4e3800  4 rocksdb:             Options.target_file_size_multiplier: 1
2016-12-11 07:44:12.400731 7f6d6a4e3800  4 rocksdb:                Options.max_bytes_for_level_base: 268435456
2016-12-11 07:44:12.400731 7f6d6a4e3800  4 rocksdb: Options.level_compaction_dynamic_level_bytes: 0
2016-12-11 07:44:12.400732 7f6d6a4e3800  4 rocksdb:          Options.max_bytes_for_level_multiplier: 10
2016-12-11 07:44:12.400732 7f6d6a4e3800  4 rocksdb: Options.max_bytes_for_level_multiplier_addtl[0]: 1
2016-12-11 07:44:12.400733 7f6d6a4e3800  4 rocksdb: Options.max_bytes_for_level_multiplier_addtl[1]: 1
2016-12-11 07:44:12.400734 7f6d6a4e3800  4 rocksdb: Options.max_bytes_for_level_multiplier_addtl[2]: 1
2016-12-11 07:44:12.400735 7f6d6a4e3800  4 rocksdb: Options.max_bytes_for_level_multiplier_addtl[3]: 1
2016-12-11 07:44:12.400736 7f6d6a4e3800  4 rocksdb: Options.max_bytes_for_level_multiplier_addtl[4]: 1
2016-12-11 07:44:12.400737 7f6d6a4e3800  4 rocksdb: Options.max_bytes_for_level_multiplier_addtl[5]: 1
2016-12-11 07:44:12.400737 7f6d6a4e3800  4 rocksdb: Options.max_bytes_for_level_multiplier_addtl[6]: 1
2016-12-11 07:44:12.400738 7f6d6a4e3800  4 rocksdb:       Options.max_sequential_skip_in_iterations: 8
2016-12-11 07:44:12.400739 7f6d6a4e3800  4 rocksdb:                    Options.max_compaction_bytes: 1677721600
2016-12-11 07:44:12.400739 7f6d6a4e3800  4 rocksdb:                        Options.arena_block_size: 8388608
2016-12-11 07:44:12.400740 7f6d6a4e3800  4 rocksdb:   Options.soft_pending_compaction_bytes_limit: 68719476736
2016-12-11 07:44:12.400741 7f6d6a4e3800  4 rocksdb:   Options.hard_pending_compaction_bytes_limit: 274877906944
2016-12-11 07:44:12.400743 7f6d6a4e3800  4 rocksdb:       Options.rate_limit_delay_max_milliseconds: 1000
2016-12-11 07:44:12.400749 7f6d6a4e3800  4 rocksdb:                Options.disable_auto_compactions: 0
2016-12-11 07:44:12.400750 7f6d6a4e3800  4 rocksdb:           Options.verify_checksums_in_compaction: 1
2016-12-11 07:44:12.400750 7f6d6a4e3800  4 rocksdb:                         Options.compaction_style: 0
2016-12-11 07:44:12.400751 7f6d6a4e3800  4 rocksdb:                           Options.compaction_pri: 0
2016-12-11 07:44:12.400751 7f6d6a4e3800  4 rocksdb:  Options.compaction_options_universal.size_ratio: 1
2016-12-11 07:44:12.400752 7f6d6a4e3800  4 rocksdb: Options.compaction_options_universal.min_merge_width: 2
2016-12-11 07:44:12.400753 7f6d6a4e3800  4 rocksdb: Options.compaction_options_universal.max_merge_width: 4294967295
2016-12-11 07:44:12.400754 7f6d6a4e3800  4 rocksdb: Options.compaction_options_universal.max_size_amplification_percent: 200
2016-12-11 07:44:12.400755 7f6d6a4e3800  4 rocksdb: Options.compaction_options_universal.compression_size_percent: -1
2016-12-11 07:44:12.400755 7f6d6a4e3800  4 rocksdb: Options.compaction_options_fifo.max_table_files_size: 1073741824
2016-12-11 07:44:12.400756 7f6d6a4e3800  4 rocksdb:                   Options.table_properties_collectors: 
2016-12-11 07:44:12.400757 7f6d6a4e3800  4 rocksdb:                   Options.inplace_update_support: 0
2016-12-11 07:44:12.400757 7f6d6a4e3800  4 rocksdb:                 Options.inplace_update_num_locks: 10000
2016-12-11 07:44:12.400758 7f6d6a4e3800  4 rocksdb:               Options.min_partial_merge_operands: 2
2016-12-11 07:44:12.400759 7f6d6a4e3800  4 rocksdb:               Options.memtable_prefix_bloom_size_ratio: 0.000000
2016-12-11 07:44:12.400767 7f6d6a4e3800  4 rocksdb:   Options.memtable_huge_page_size: 0
2016-12-11 07:44:12.400775 7f6d6a4e3800  4 rocksdb:                           Options.bloom_locality: 0
2016-12-11 07:44:12.400777 7f6d6a4e3800  4 rocksdb:                    Options.max_successive_merges: 0
2016-12-11 07:44:12.400777 7f6d6a4e3800  4 rocksdb:                Options.optimize_filters_for_hits: 0
2016-12-11 07:44:12.400778 7f6d6a4e3800  4 rocksdb:                Options.paranoid_file_checks: 0
2016-12-11 07:44:12.400778 7f6d6a4e3800  4 rocksdb:                Options.report_bg_io_stats: 0
2016-12-11 07:44:12.582803 7f6d6a4e3800  4 rocksdb: Recovered from manifest file:db/MANIFEST-000064 succeeded,manifest_file_number is 64, next_file_number is 66, last_sequence is 2601688, log_number is 0,prev_log_number is 0,max_column_family is 0

2016-12-11 07:44:12.582817 7f6d6a4e3800  4 rocksdb: Column family [default] (ID 0), log number is 62

2016-12-11 07:44:12.582900 7f6d6a4e3800  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431452582890, "job": 1, "event": "recovery_started", "log_files": [65, 68]}
2016-12-11 07:44:12.582904 7f6d6a4e3800  4 rocksdb: Recovering log #65 mode 0
2016-12-11 07:44:13.519285 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.534418 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.540922 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.546150 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.553405 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.568758 7f6d6a4e3800  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431453568738, "cf_name": "default", "job": 1, "event": "table_file_creation", "file_number": 66, "file_size": 39871603, "table_properties": {"data_size": 39184879, "index_size": 685813, "filter_size": 0, "raw_key_size": 28505469, "raw_average_key_size": 67, "raw_value_size": 28008401, "raw_average_value_size": 66, "num_data_blocks": 9892, "num_entries": 421391, "filter_policy_name": "", "kDeletedKeys": "320106", "kMergeOperands": "3122"}}
2016-12-11 07:44:13.572518 7f6d6a4e3800  4 rocksdb: Recovering log #68 mode 0
2016-12-11 07:44:13.647788 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.651586 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.655448 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.659634 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.663766 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.676266 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.681993 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.688478 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.696017 7f6d6a4e3800  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431453696000, "cf_name": "default", "job": 1, "event": "table_file_creation", "file_number": 69, "file_size": 7988661, "table_properties": {"data_size": 7844044, "index_size": 143710, "filter_size": 0, "raw_key_size": 1801132, "raw_average_key_size": 68, "raw_value_size": 7108665, "raw_average_value_size": 268, "num_data_blocks": 2032, "num_entries": 26483, "filter_policy_name": "", "kDeletedKeys": "101", "kMergeOperands": "3"}}
2016-12-11 07:44:13.696945 7f6d6a4e3800  4 rocksdb: Creating manifest 70

2016-12-11 07:44:13.697012 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.697285 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.697566 7f6d6a4e3800  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431453697562, "job": 1, "event": "recovery_finished"}
2016-12-11 07:44:13.697622 7f6d6a4e3800  4 rocksdb: Unrecognized log file . 

2016-12-11 07:44:13.697625 7f6d6a4e3800  4 rocksdb: Unrecognized log file .. 

2016-12-11 07:44:13.697939 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.698343 7f6d6a4e3800  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-11 07:44:13.699168 7f6d6a4e3800  4 rocksdb: DB pointer 0x7f6d756dca00
2016-12-11 07:44:13.699204 7f6d6a4e3800  1 bluestore(/var/lib/ceph/osd/ceph-51) _open_db opened rocksdb path db options compression=kNoCompression,max_write_buffer_number=16,min_write_buffer_number_to_merge=3,recycle_log_file_num=16
2016-12-11 07:44:13.699458 7f6d53a7e700  3 rocksdb: ------- DUMPING STATS -------
2016-12-11 07:44:13.699479 7f6d53a7e700  3 rocksdb: 
** Compaction Stats [default] **
Level    Files   Size(MB) Score Read(GB)  Rn(GB) Rnp1(GB) Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) Comp(sec) Comp(cnt) Avg(sec) KeyIn KeyDrop
---------------------------------------------------------------------------------------------------------------------------------------------------------------------
  L0      4/0     142.56   1.0      0.0     0.0      0.0       0.0      0.0       0.0   0.0      0.0     99.7         0         2    0.229       0      0
  L1      4/0     228.97   0.9      0.0     0.0      0.0       0.0      0.0       0.0   0.0      0.0      0.0         0         0    0.000       0      0
  L2      3/0     193.94   0.1      0.0     0.0      0.0       0.0      0.0       0.0   0.0      0.0      0.0         0         0    0.000       0      0
 Sum     11/0     565.46   0.0      0.0     0.0      0.0       0.0      0.0       0.0   1.0      0.0     99.7         0         2    0.229       0      0
 Int      0/0       0.00   0.0      0.0     0.0      0.0       0.0      0.0       0.0   1.0      0.0     99.7         0         2    0.229       0      0
Uptime(secs): 1.3 total, 1.3 interval
AddFile(GB): cumulative 0.000, interval 0.000
Cumulative compaction: 0.04 GB write, 35.14 MB/s write, 0.00 GB read, 0.00 MB/s read, 0.5 seconds
Interval compaction: 0.04 GB write, 35.14 MB/s write, 0.00 GB read, 0.00 MB/s read, 0.5 seconds
Stalls(count): 0 level0_slowdown, 0 level0_slowdown_with_compaction, 0 level0_numfiles, 0 level0_numfiles_with_compaction, 0 stop for pending_compaction_bytes, 0 slowdown for pending_compaction_bytes, 0 memtable_compaction, 0 memtable_slowdown, interval 0 total count

** DB Stats **
Uptime(secs): 1.3 total, 1.3 interval
Cumulative writes: 0 writes, 0 keys, 0 commit groups, 0.0 writes per commit group, ingest: 0.00 GB, 0.00 MB/s
Cumulative WAL: 0 writes, 0 syncs, 0.00 writes per sync, written: 0.00 GB, 0.00 MB/s
Cumulative stall: 00:00:0.000 H:M:S, 0.0 percent
Interval writes: 0 writes, 0 keys, 0 commit groups, 0.0 writes per commit group, ingest: 0.00 MB, 0.00 MB/s
Interval WAL: 0 writes, 0 syncs, 0.00 writes per sync, written: 0.00 MB, 0.00 MB/s
Interval stall: 00:00:0.000 H:M:S, 0.0 percent

2016-12-11 07:44:13.699644 7f6d53a7e700  4 rocksdb: [default] [JOB 3] Compacting 4@0 + 4@1 files to L1, score 1.00
2016-12-11 07:44:13.699665 7f6d53a7e700  4 rocksdb: [default] Compaction start summary: Base version 2 Base level 0, inputs: [69(7801KB) 66(38MB) 63(45MB) 62(51MB)], [54(64MB) 56(64MB) 57(64MB) 58(34MB)]

2016-12-11 07:44:13.699738 7f6d53a7e700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431453699673, "job": 3, "event": "compaction_started", "files_L0": [69, 66, 63, 62], "files_L1": [54, 56, 57, 58], "score": 1, "input_data_size": 389573215}
2016-12-11 07:44:13.761158 7f6d6a4e3800  1 freelist init
2016-12-11 07:44:14.720220 7f6d6a4e3800  0 <cls> /mnt/jenkins/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/11.0.2/rpm/el7/BUILD/ceph-11.0.2/src/cls/hello/cls_hello.cc:305: loading cls_hello
2016-12-11 07:44:14.720343 7f6d6a4e3800  0 <cls> /mnt/jenkins/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/11.0.2/rpm/el7/BUILD/ceph-11.0.2/src/cls/cephfs/cls_cephfs.cc:202: loading cephfs_size_scan
2016-12-11 07:44:14.720780 7f6d6a4e3800  0 _get_class not permitted to load kvs
2016-12-11 07:44:14.720787 7f6d6a4e3800  0 _get_class not permitted to load lua
2016-12-11 07:44:14.742686 7f6d6a4e3800  0 osd.51 524 crush map has features 2200130813952, adjusting msgr requires for clients
2016-12-11 07:44:14.742696 7f6d6a4e3800  0 osd.51 524 crush map has features 2200130813952 was 8705, adjusting msgr requires for mons
2016-12-11 07:44:14.742702 7f6d6a4e3800  0 osd.51 524 crush map has features 2200130813952, adjusting msgr requires for osds
2016-12-11 07:44:20.152148 7f6d6a4e3800  0 osd.51 524 load_pgs
2016-12-11 07:44:21.985634 7f6d53a7e700  4 rocksdb: [default] [JOB 3] Generated table #74: 469289 keys, 68253805 bytes
2016-12-11 07:44:21.985667 7f6d53a7e700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431461985648, "cf_name": "default", "job": 3, "event": "table_file_creation", "file_number": 74, "file_size": 68253805, "table_properties": {"data_size": 67113187, "index_size": 1139707, "filter_size": 0, "raw_key_size": 32865246, "raw_average_key_size": 70, "raw_value_size": 53624938, "raw_average_value_size": 114, "num_data_blocks": 16520, "num_entries": 469289, "filter_policy_name": "", "kDeletedKeys": "320681", "kMergeOperands": "0"}}
2016-12-11 07:44:25.341365 7f6d53a7e700  4 rocksdb: [default] [JOB 3] Generated table #75: 58446 keys, 68143723 bytes
2016-12-11 07:44:25.341398 7f6d53a7e700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431465341382, "cf_name": "default", "job": 3, "event": "table_file_creation", "file_number": 75, "file_size": 68143723, "table_properties": {"data_size": 67111957, "index_size": 1030858, "filter_size": 0, "raw_key_size": 7743349, "raw_average_key_size": 132, "raw_value_size": 62120816, "raw_average_value_size": 1062, "num_data_blocks": 15179, "num_entries": 58446, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2016-12-11 07:44:28.695943 7f6d53a7e700  4 rocksdb: [default] [JOB 3] Generated table #76: 58337 keys, 68140865 bytes
2016-12-11 07:44:28.695976 7f6d53a7e700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431468695960, "cf_name": "default", "job": 3, "event": "table_file_creation", "file_number": 76, "file_size": 68140865, "table_properties": {"data_size": 67113639, "index_size": 1026318, "filter_size": 0, "raw_key_size": 7733501, "raw_average_key_size": 132, "raw_value_size": 62131020, "raw_average_value_size": 1065, "num_data_blocks": 15175, "num_entries": 58337, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2016-12-11 07:44:31.149222 7f6d53a7e700  4 rocksdb: [default] [JOB 3] Generated table #77: 58861 keys, 68145852 bytes
2016-12-11 07:44:31.149271 7f6d53a7e700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431471149241, "cf_name": "default", "job": 3, "event": "table_file_creation", "file_number": 77, "file_size": 68145852, "table_properties": {"data_size": 67113770, "index_size": 1031174, "filter_size": 0, "raw_key_size": 7802753, "raw_average_key_size": 132, "raw_value_size": 62116898, "raw_average_value_size": 1055, "num_data_blocks": 15169, "num_entries": 58861, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2016-12-11 07:44:32.034725 7f6d53a7e700  4 rocksdb: [default] [JOB 3] Generated table #78: 253917 keys, 19631295 bytes
2016-12-11 07:44:32.034756 7f6d53a7e700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431472034741, "cf_name": "default", "job": 3, "event": "table_file_creation", "file_number": 78, "file_size": 19631295, "table_properties": {"data_size": 19395540, "index_size": 234845, "filter_size": 0, "raw_key_size": 5752553, "raw_average_key_size": 22, "raw_value_size": 14896527, "raw_average_value_size": 58, "num_data_blocks": 4531, "num_entries": 253917, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "79826"}}
2016-12-11 07:44:32.034816 7f6d53a7e700  4 rocksdb: [default] [JOB 3] Compacted 4@0 + 4@1 files to L1 => 292315540 bytes
2016-12-11 07:44:32.035486 7f6d53a7e700  4 rocksdb: (Original Log Time 2016/12/11-07:44:32.035367) [default] compacted to: base level 1 max bytes base 268435456 files[0 5 3 0 0 0 0] max score 1.57, MB/sec: 21.2 rd, 15.9 wr, level 1, files in(4, 4) out(5) MB in(142.6, 229.0) out(278.8), read-write-amplify(4.6) write-amplify(2.0) OK, records in: 1221704, records dropped: 322846

2016-12-11 07:44:32.035500 7f6d53a7e700  4 rocksdb: (Original Log Time 2016/12/11-07:44:32.035389) EVENT_LOG_v1 {"time_micros": 1481431472035378, "job": 3, "event": "compaction_finished", "compaction_time_micros": 18335027, "output_level": 1, "num_output_files": 5, "total_output_size": 292315540, "num_input_records": 1221696, "num_output_records": 898850, "num_subcompactions": 1, "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 5, 3, 0, 0, 0, 0]}
2016-12-11 07:44:32.035542 7f6d53a7e700  4 rocksdb: [default] [JOB 4] Compacting 1@1 + 2@2 files to L2, score 1.57
2016-12-11 07:44:32.035549 7f6d53a7e700  4 rocksdb: [default] Compaction start summary: Base version 3 Base level 1, inputs: [74(65MB)], [59(65MB) 60(63MB)]

2016-12-11 07:44:32.035562 7f6d53a7e700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431472035553, "job": 4, "event": "compaction_started", "files_L1": [74], "files_L2": [59, 60], "score": 1.57485, "input_data_size": 203456179}
2016-12-11 07:44:34.167062 7f6d6a4e3800  0 osd.51 524 load_pgs opened 289 pgs
2016-12-11 07:44:34.167540 7f6d6a4e3800  0 osd.51 524 using 1 op queue with priority op cut off at 64.
2016-12-11 07:44:34.168372 7f6d6a4e3800 -1 osd.51 524 log_to_monitors {default=true}
2016-12-11 07:44:34.184162 7f6d6a4e3800  0 osd.51 524 done with init, starting boot process
2016-12-11 07:44:34.470355 7f6d621dc700 -1 osd.51 544 OSD::ms_get_authorizer build_authorizer returned 0x7f6d755d3f40
2016-12-11 07:44:35.150608 7f6d53a7e700  4 rocksdb: [default] [JOB 4] Generated table #79: 270407 keys, 68168318 bytes
2016-12-11 07:44:35.150639 7f6d53a7e700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431475150624, "cf_name": "default", "job": 4, "event": "table_file_creation", "file_number": 79, "file_size": 68168318, "table_properties": {"data_size": 67111259, "index_size": 1056150, "filter_size": 0, "raw_key_size": 13488738, "raw_average_key_size": 49, "raw_value_size": 62617933, "raw_average_value_size": 231, "num_data_blocks": 16870, "num_entries": 270407, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2016-12-11 07:44:35.419877 7f6d621dc700 -1 osd.51 545 OSD::ms_get_authorizer build_authorizer returned 0x7f6d97389ac0
2016-12-11 07:44:35.455153 7f6d621dc700 -1 osd.51 545 OSD::ms_get_authorizer build_authorizer returned 0x7f6d97389b60
2016-12-11 07:44:35.455290 7f6d619db700 -1 osd.51 545 OSD::ms_get_authorizer build_authorizer returned 0x7f6d755d5c00
2016-12-11 07:44:35.455625 7f6d621dc700 -1 osd.51 545 OSD::ms_get_authorizer build_authorizer returned 0x7f6d97389b60
2016-12-11 07:44:35.455790 7f6d619db700 -1 osd.51 545 OSD::ms_get_authorizer build_authorizer returned 0x7f6d755d5c00
2016-12-11 07:44:35.456666 7f6d629dd700  0 -- 192.168.36.7:6859/2001423 >> :/0 conn(0x7f6d96731800 :6859 s=STATE_ACCEPTING_WAIT_BANNER_ADDR pgs=0 cs=0 l=0).fault with nothing to send and in the half  accept state just closed
2016-12-11 07:44:35.460996 7f6d619db700  0 -- 192.168.36.7:6859/2001423 >> :/0 conn(0x7f6d7db40800 :6859 s=STATE_ACCEPTING_WAIT_BANNER_ADDR pgs=0 cs=0 l=0).fault with nothing to send and in the half  accept state just closed
2016-12-11 07:44:35.462096 7f6d629dd700 -1 osd.51 545 OSD::ms_get_authorizer build_authorizer returned 0x7f6d97387a40
2016-12-11 07:44:35.462185 7f6d629dd700  0 -- 192.168.36.7:6859/2001423 >> 192.168.36.7:6881/572077 conn(0x7f6d96733000 :6859 s=STATE_ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_msg accept connect_seq 0 vs existing csq=0 existing_state=STATE_CONNECTING_WAIT_CONNECT_REPLY
2016-12-11 07:44:35.462446 7f6d629dd700  0 -- 192.168.36.7:6859/2001423 >> 192.168.36.7:6881/572077 conn(0x7f6d96733000 :6859 s=STATE_ACCEPTING_WAIT_CONNECT_MSG pgs=0 cs=0 l=0).fault with nothing to send and in the half  accept state just closed
2016-12-11 07:44:35.462509 7f6d629dd700 -1 osd.51 545 OSD::ms_get_authorizer build_authorizer returned 0x7f6d97387a40
2016-12-11 07:44:39.480616 7f6d53a7e700  4 rocksdb: [default] [JOB 4] Generated table #80: 189781 keys, 68240173 bytes
2016-12-11 07:44:39.480650 7f6d53a7e700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431479480635, "cf_name": "default", "job": 4, "event": "table_file_creation", "file_number": 80, "file_size": 68240173, "table_properties": {"data_size": 67111623, "index_size": 1127641, "filter_size": 0, "raw_key_size": 12861998, "raw_average_key_size": 67, "raw_value_size": 61413015, "raw_average_value_size": 323, "num_data_blocks": 16624, "num_entries": 189781, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2016-12-11 07:44:41.289937 7f6d53a7e700  4 rocksdb: [default] [JOB 4] Generated table #81: 50661 keys, 58152239 bytes
2016-12-11 07:44:41.289968 7f6d53a7e700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431481289954, "cf_name": "default", "job": 4, "event": "table_file_creation", "file_number": 81, "file_size": 58152239, "table_properties": {"data_size": 57265197, "index_size": 886134, "filter_size": 0, "raw_key_size": 6715867, "raw_average_key_size": 132, "raw_value_size": 52992189, "raw_average_value_size": 1046, "num_data_blocks": 12950, "num_entries": 50661, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2016-12-11 07:44:41.290126 7f6d53a7e700  4 rocksdb: [default] [JOB 4] Compacted 1@1 + 2@2 files to L2 => 194560730 bytes
2016-12-11 07:44:41.290832 7f6d53a7e700  4 rocksdb: (Original Log Time 2016/12/11-07:44:41.290562) [default] compacted to: base level 1 max bytes base 268435456 files[0 4 4 0 0 0 0] max score 0.83, MB/sec: 22.0 rd, 21.0 wr, level 2, files in(1, 2) out(3) MB in(65.1, 128.9) out(185.5), read-write-amplify(5.8) write-amplify(2.9) OK, records in: 833070, records dropped: 322221

2016-12-11 07:44:41.290843 7f6d53a7e700  4 rocksdb: (Original Log Time 2016/12/11-07:44:41.290585) EVENT_LOG_v1 {"time_micros": 1481431481290576, "job": 4, "event": "compaction_finished", "compaction_time_micros": 9254547, "output_level": 2, "num_output_files": 3, "total_output_size": 194560730, "num_input_records": 833070, "num_output_records": 510849, "num_subcompactions": 1, "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 4, 4, 0, 0, 0, 0]}
2016-12-11 07:44:41.290882 7f6d53a7e700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1481431481290878, "job": 4, "event": "table_file_deletion", "file_number": 74}
2016-12-11 07:51:35.828760 7f6d629dd700 -1 osd.51 549 OSD::ms_get_authorizer build_authorizer returned 0x7f6d9785ad00
2016-12-11 07:56:41.205313 7f6d54a80700  1 bluefs _allocate failed to allocate 0x100000 on bdev 0, free 0xff000; fallback to bdev 1
2016-12-11 07:56:41.205323 7f6d54a80700  1 bluefs _allocate failed to allocate 0x100000 on bdev 1, free 0xfe000; fallback to bdev 2
2016-12-12 00:01:01.399164 7f6d46263700 -1 received  signal: Hangup from  PID: 2173364 task name: killall -q -1 ceph-mon ceph-mds ceph-osd ceph-fuse radosgw  UID: 0
<pre>

I've also attached the log for OSD 52 which failed next.

Files

zabbixOsdFailureGraph.png (31.8 KB) zabbixOsdFailureGraph.png Yuri Gorshkov, 12/12/2016 10:28 AM
osd.52.log.xz (90.8 KB) osd.52.log.xz OSD 52 log Yuri Gorshkov, 12/12/2016 11:32 AM
Actions #1

Updated by Samuel Just over 7 years ago

This is from a few months ago, you'll want to retest with a more recent version.

Actions #2

Updated by Samuel Just over 7 years ago

  • Status changed from New to Can't reproduce
Actions

Also available in: Atom PDF