Ceph

We see the same thing in our production cluster, running the same ceph version and configuration with KV on EC OSDs:

11> 2015-07-14 17:05:24.299882 7f0824479700  1 - 10.141.16.11:0/17839 <== osd.233 10.141.16.23:6827/27123 323 ==== osd_ping(you_died e21218 stamp 2015-07-14 17:05:24.289598) v2 ==== 47+0+0 (862640411 0 0) 0
x6b61a00 con 0x9313180
   10> 2015-07-14 17:05:24.299888 7f0824479700  1 - 10.141.16.11:0/17839 <== osd.173 10.141.16.20:6829/53390 323 ==== osd_ping(you_died e21218 stamp 2015-07-14 17:05:24.289598) v2 ==== 47+0+0 (862640411 0 0) 0
x13dcb600 con 0x4572dee0
    9> 2015-07-14 17:05:24.299894 7f0824479700  1 - 10.141.16.11:0/17839 <== osd.87 10.143.16.15:6823/25376 325 ==== osd_ping(you_died e21218 stamp 2015-07-14 17:05:24.289598) v2 ==== 47+0+0 (862640411 0 0) 0x
1e7dda00 con 0x5f626880
    8> 2015-07-14 17:05:28.136387 7f08317a9700  1 heartbeat_map is_healthy 'OSD::osd_tp thread 0x7f081e46d700' had timed out after 15
    -7> 2015-07-14 17:05:28.139616 7f08317a9700  1 heartbeat_map is_healthy 'OSD::osd_tp thread 0x7f081e46d700' had suicide timed out after 150
    -6> 2015-07-14 17:05:28.344302 7f081f46f700 10 monclient: tick
    -5> 2015-07-14 17:05:28.368416 7f081f46f700 10 monclient: _check_auth_rotating have uptodate secrets (they expire after 2015-07-14 17:04:58.367510)
    -4> 2015-07-14 17:05:28.372101 7f081f46f700 10 monclient: renew subs? (now: 2015-07-14 17:05:28.372100; renew after: 2015-07-14 17:04:33.075361) - yes
    3> 2015-07-14 17:05:28.372753 7f081f46f700 10 monclient: renew_subs
    -2> 2015-07-14 17:05:28.375533 7f081f46f700 10 monclient: _send_mon_message to mon.mds03 at 10.141.16.3:6789/0
    -1> 2015-07-14 17:05:28.375569 7f081f46f700  1 - 10.141.16.11:6810/17839 --> 10.141.16.3:6789/0 -- mon_subscribe({monmap=2+,osd_pg_creates=0,osdmap=21128}) v2 -- ?+0 0x16d24600 con 0x8e95120
     0> 2015-07-14 17:05:28.413966 7f08317a9700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f08317a9700 time 2015-07-14 17:05:
28.140873
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

ceph version 0.94.1 (e4bfad3a3c51054df7e537a724c8d0bf9be972ff)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x85) [0xbc51f5]
 2: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2d9) [0xafaff9]
 3: (ceph::HeartbeatMap::is_healthy()+0xde) [0xafb8ee]
 4: (ceph::HeartbeatMap::check_touch_file()+0x2c) [0xafc00c]
 5: (CephContextServiceThread::entry()+0x15b) [0xbd542b]
 6: (()+0x7df5) [0x7f083457ddf5]
 7: (clone()+0x6d) [0x7f08330601ad]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

From my intuition, it should be blocking on submit transaction to backend. It's possible that leveldb may stuck into compaction and make client io blocking.

Do you use leveldb ?

Yes, our OSDs are using leveldb

I think what we can do is boost the keyvaluestore thread timeout value, and tune leveldb config or use rocksdb as backend.

I guess I then should add `keyvaluestore_backend = rocksdb` to the config ?
Can this be done for existing OSDS?
Can they be mixed in the same pool ? (Then I could recreate/change OSDs gradually)

Thank you !!
Kenneth

This time, we have the same error, but with a filestore OSD! :

  
 -11> 2015-07-17 12:20:53.171071 7f72bc889700  1 -- 10.143.8.180:0/21943 <== osd.5 10.141.8.180:6813/2025958 2490 ==== osd_ping(ping_reply e973 stam
p 2015-07-17 12:20:53.036238) v2 ==== 47+0+0 (2350916550 0 0) 0x65a9c00 con 0xc7c1e40
   -10> 2015-07-17 12:20:53.173162 7f72bc889700  1 -- 10.143.8.180:0/21943 <== osd.2 10.141.8.180:6805/23455 2490 ==== osd_ping(ping_reply e973 stamp 
2015-07-17 12:20:53.036238) v2 ==== 47+0+0 (2350916550 0 0) 0xb46a800 con 0xc7c7bc0
    -9> 2015-07-17 12:20:53.175126 7f72bc889700  1 -- 10.143.8.180:0/21943 <== osd.2 10.143.8.180:6805/23455 2490 ==== osd_ping(ping_reply e973 stamp 
2015-07-17 12:20:53.036238) v2 ==== 47+0+0 (2350916550 0 0) 0x7e85e00 con 0xc7c48e0
    -8> 2015-07-17 12:20:53.175224 7f72bc889700  1 -- 10.143.8.180:0/21943 <== osd.5 10.143.8.180:6835/2025958 2490 ==== osd_ping(ping_reply e973 stam
p 2015-07-17 12:20:53.036238) v2 ==== 47+0+0 (2350916550 0 0) 0x1acd4a00 con 0xc7c14a0
    -7> 2015-07-17 12:20:53.189213 7f72bc889700  1 -- 10.143.8.180:0/21943 <== osd.4 10.143.8.180:6809/25053 185101 ==== osd_ping(ping_reply e973 stam
p 2015-07-17 12:20:53.036238) v2 ==== 47+0+0 (2350916550 0 0) 0x787a800 con 0x67cb2e0
    -6> 2015-07-17 12:20:53.719974 7f72ba084700  1 -- 10.143.8.180:6801/21943 <== osd.1 10.143.8.180:0/19736 2511 ==== osd_ping(ping e973 stamp 2015-0
7-17 12:20:53.719120) v2 ==== 47+0+0 (3630202744 0 0) 0x293ec800 con 0x5d056a0
    -5> 2015-07-17 12:20:53.720115 7f72ba084700  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7f72b4078700' had timed out after 15
    -4> 2015-07-17 12:20:53.720123 7f72ba084700  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7f72b4078700' had suicide timed out after 150
    -3> 2015-07-17 12:20:53.868534 7f72ccc07700  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7f72b4078700' had timed out after 15
    -2> 2015-07-17 12:20:53.868573 7f72ccc07700  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7f72b4078700' had suicide timed out after 150
    -1> 2015-07-17 12:20:53.927786 7f72bb887700  1 -- 10.141.8.180:6801/21943 <== osd.34 10.141.8.182:0/22430 185102 ==== osd_ping(ping e973 stamp 201
5-07-17 12:20:53.926670) v2 ==== 47+0+0 (4208267044 0 0) 0x7e87400 con 0x60a3180
     0> 2015-07-17 12:20:53.928257 7f72ccc07700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, con
st char*, time_t)' thread 7f72ccc07700 time 2015-07-17 12:20:53.868594
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.94.1 (e4bfad3a3c51054df7e537a724c8d0bf9be972ff)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x85) [0xbc51f5]
 2: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2d9) [0xafaff9]
 3: (ceph::HeartbeatMap::is_healthy()+0xde) [0xafb8ee]
 4: (ceph::HeartbeatMap::check_touch_file()+0x2c) [0xafc00c]
 5: (CephContextServiceThread::entry()+0x15b) [0xbd542b]
 6: (()+0x7df5) [0x7f72cfa0fdf5]
 7: (clone()+0x6d) [0x7f72ce4d61ad]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- begin dump of recent events ---
     0> 2015-07-17 12:20:53.928268 7f72ba084700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbea
t_handle_d*, const char*, time_t)' thread 7f72ba084700 time 2015-07-17 12:20:53.722164
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.94.1 (e4bfad3a3c51054df7e537a724c8d0bf9be972ff)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x85) [0xbc51f5]
 2: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2d9) [0xafaff9]
 3: (ceph::HeartbeatMap::is_healthy()+0xde) [0xafb8ee]
 4: (OSD::handle_osd_ping(MOSDPing*)+0x733) [0x695f13]
 5: (OSD::heartbeat_dispatch(Message*)+0x2fb) [0x69718b]
 6: (DispatchQueue::entry()+0x62a) [0xc7cc4a]
 7: (DispatchQueue::DispatchThread::entry()+0xd) [0xba403d]
 8: (()+0x7df5) [0x7f72cfa0fdf5]
 9: (clone()+0x6d) [0x7f72ce4d61ad]

2015-07-17 13:57:53.425744 7f55ae088880  0 ceph version 0.94.1 (e4bfad3a3c51054df7e537a724c8d0bf9be972ff), process ceph-osd, pid 55201
2015-07-17 13:57:53.457758 7f55ae088880 -1 WARNING: the following dangerous and experimental features are enabled: keyvaluestore
2015-07-17 13:57:53.501718 7f55ae088880  0 filestore(/var/lib/ceph/osd/ceph-0) backend xfs (magic 0x58465342)
2015-07-17 13:57:53.510131 7f55ae088880  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-0) detect_features: FIEMAP ioctl is supporte
d and appears to work
2015-07-17 13:57:53.510141 7f55ae088880  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-0) detect_features: FIEMAP ioctl is disabled
 via 'filestore fiemap' config option
2015-07-17 13:57:53.510662 7f55ae088880  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-0) detect_features: syncfs(2) syscall fully 
supported (by glibc and kernel)
2015-07-17 13:57:53.510742 7f55ae088880  0 xfsfilestorebackend(/var/lib/ceph/osd/ceph-0) detect_feature: extsize is supported and kern
el 3.10.0-229.4.2.el7.centos.ug.x86_64 >= 3.5
2015-07-17 13:57:53.633826 7f55ae088880  0 filestore(/var/lib/ceph/osd/ceph-0) mount: enabling WRITEAHEAD journal mode: checkpoint is 
not enabled

So it is not limited to KV stores..

hi, Kenneth
We also encounter this suicide error very often when we test the 4K random writes.

the osd_op_tp threads maintain the op_wq workqueue, for write, it will clear the timeout when delivery the write op the filejournal's workqueue.

if the pressure is from submit transactions to backend, it should be filestore's op_tp timeout, but not osd_op_tp timeout.

i's using lockdep and lttng to trace this problem, but with no lucky.

huang jun wrote:

hi, Kenneth
We also encounter this suicide error very often when we test the 4K random writes.

the osd_op_tp threads maintain the op_wq workqueue, for write, it will clear the timeout when delivery the write op to the filejournal's workqueue.

if the pressure is from submit transactions to backend, it should be filestore's op_tp timeout, but not osd_op_tp timeout.

i's using lockdep and lttng to trace this problem, but with no lucky.

Did you guys find a fix for this?

We upgraded from firefly to hammer 0.94.5 two days ago and since then we've had three OSD heartbeat suicides. The most recent one was a hanging 4k object create:

An example slow request:

2015-11-19 16:31:23.001378 osd.655 128.142.23.84:6942/3240023 539 : cluster [WRN] slow request 240.720215 seconds old, received
at 2015-11-19 16:27:22.281109: osd_op(client.53707886.0:7400356601 rbd_data.33a409b2d523beb.0000000000007923 [write 2154496~40
96] 4.29b54dc1 ack+ondisk+write e295797) currently waiting for subops from 541,767

and osd.767 had one osd thread timing out until it committed suicide:

2015-11-19 16:33:34.936161 7f2dd9a0e700  1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7f2db1c26700' had suicide timed out after 150

Here’s the last op from that thread:

2015-11-19 16:31:01.222687 7f2db1c26700  7 osd.767 pg_epoch: 295797 pg[64.31e( v 295797'301109 (292493'298050,295797'301109] lo
cal-les=294244 n=6 ec=105353 les/c 294244/294244 294243/294243/294243) [767,18,655] r=0 lpr=294243 crt=295794'301107 lcod 29579
7'301108 mlcod 295797'301108 active+clean] issue_repop rep_tid 593075 o a2b44b1e/benchmark_data_p01001532021656.cern.ch_1533185
_object76/head//64

(the op comes from one of our monitoring probes — which is a very light load of 4k writes every 5 minutes).

I posted that OSD's log:
ceph-post-file: da8fd559-8417-4718-8979-362c864ba38c

This is unlikely to be the same issue you're hitting, Dan, unless you're also using KV-backed OSDs.

Probably you're just hitting slowness that you weren't noticing before (I think some of the timeouts got turned down) and will need to adjust, but that's for a separate thread/ticket.