On an HDD-based Quincy 17.2.5 cluster (with DB/WAL on datacenter-class NVMe with enhanced power loss protection), I sometimes (once or twice per week) see log entries similar to what I reproduced below (a bit trimmed): Wed 2023-09-06 22:41:54 UTC ceph-osd09 ceph-osd@39.service[5574]: 2023-09-06T22:41:54.429+0000 7f83d813d700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7f83b9ec1700' had timed out after 15.000000954s Wed 2023-09-06 22:41:54 UTC ceph-osd09 ceph-osd@39.service[5574]: 2023-09-06T22:41:54.429+0000 7f83d793c700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7f83b9ec1700' had timed out after 15.000000954s Wed 2023-09-06 22:41:54 UTC ceph-osd09 ceph-osd@39.service[5574]: 2023-09-06T22:41:54.469+0000 7f83d713b700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7f83b9ec1700' had timed out after 15.000000954s <many more repeats> Wed 2023-09-06 22:42:04 UTC mds02 ceph-mgr@mds02.service[4954]: 2023-09-06T22:42:04.735+0000 7ffab1a20700 0 log_channel(cluster) log [DBG] : pgmap v227303: 5449 pgs: 1 active+clean+laggy, 7 active+clean+snaptrim, 34 active+remapped+backfilling, 13 active+clean+scrubbing, 4738 active+clean, 19 active+clean+scrubbing+deep, 637 active+remapped+backfill_wait; 2.0 PiB data, 2.9 PiB used, 2.2 PiB / 5.2 PiB avail; 103 MiB/s rd, 25 MiB/s wr, 2.76k op/s; 923967567/22817724437 objects misplaced (4.049%); 128 MiB/s, 142 objects/s recovering <some more osd_op_tp threads timed out> Wed 2023-09-06 22:42:06 UTC mds02 ceph-mgr@mds02.service[4954]: 2023-09-06T22:42:06.767+0000 7ffab1a20700 0 log_channel(cluster) log [DBG] : pgmap v227304: 5449 pgs: 2 active+clean+laggy, 7 active+clean+snaptrim, 34 active+remapped+backfilling, 13 active+clean+scrubbing, 4737 active+clean, 19 active+clean+scrubbing+deep, 637 active+remapped+backfill_wait; 2.0 PiB data, 2.9 PiB used, 2.2 PiB / 5.2 PiB avail; 88 MiB/s rd, 23 MiB/s wr, 3.85k op/s; 923967437/22817727283 objects misplaced (4.049%); 115 MiB/s, 126 objects/s recovering <some more osd_op_tp threads timed out> Wed 2023-09-06 22:42:15 UTC mds02 ceph-mgr@mds02.service[4954]: 2023-09-06T22:42:15.311+0000 7ffab1a20700 0 log_channel(cluster) log [DBG] : pgmap v227308: 5449 pgs: 1 active+remapped+backfill_wait+laggy, 3 active+clean+laggy, 7 active+clean+snaptrim, 34 active+remapped+backfilling, 13 active+clean+scrubbing, 4736 active+clean, 19 active+clean+scrubbing+deep, 636 active+remapped+backfill_wait; 2.0 PiB data, 2.9 PiB used, 2.2 PiB / 5.2 PiB avail; 67 MiB/s rd, 13 MiB/s wr, 3.21k op/s; 923966538/22817734196 objects misplaced (4.049%); 134 MiB/s, 137 objects/s recovering <some more osd_op_tp threads timed out> Wed 2023-09-06 22:42:22 UTC ceph-osd09 ceph-osd@39.service[5574]: 2023-09-06T22:42:22.708+0000 7f83b9ec1700 1 heartbeat_map reset_timeout 'OSD::osd_op_tp thread 0x7f83b9ec1700' had timed out after 15.000000954s <no more osd_op_tp threads time out> Wed 2023-09-06 22:42:24 UTC ceph-osd06 ceph-osd@12.service[5527]: 2023-09-06T22:42:24.637+0000 7f4fbfcc3700 -1 osd.12 1031871 heartbeat_check: no reply from 10.3.0.9:6864 osd.39 since back 2023-09-06T22:41:54.079627+0000 front 2023-09-06T22:41:54.079742+0000 (oldest deadline 2023-09-06T22:42:24.579224+0000) Wed 2023-09-06 22:42:24 UTC ceph-osd08 ceph-osd@126.service[5505]: 2023-09-06T22:42:24.671+0000 7feb033d8700 -1 osd.126 1031871 heartbeat_check: no reply from 10.3.0.9:6864 osd.39 since back 2023-09-06T22:41:53.996908+0000 front 2023-09-06T22:41:53.997184+0000 (oldest deadline 2023-09-06T22:42:24.496552+0000) Wed 2023-09-06 22:42:24 UTC ceph-osd06 ceph-osd@75.service[5532]: 2023-09-06T22:42:24.797+0000 7fe15bc77700 -1 osd.75 1031871 heartbeat_check: no reply from 10.3.0.9:6864 osd.39 since back 2023-09-06T22:41:49.384037+0000 front 2023-09-06T22:41:49.384031+0000 (oldest deadline 2023-09-06T22:42:24.683399+0000) <some more "no reply" complaints - curiously, most of them come from the old part of the cluster, to which the timed-out OSD also belongs> Wed 2023-09-06 22:42:25 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:25.669+0000 7f8f72216700 1 mon.mds01@0(leader).osd e1031871 prepare_failure osd.39 v1:10.3.0.9:6860/5574 from osd.1 is reporting failure:1 Wed 2023-09-06 22:42:25 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:25.669+0000 7f8f72216700 0 log_channel(cluster) log [DBG] : osd.39 reported failed by osd.1 Wed 2023-09-06 22:42:25 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:25.905+0000 7f8f72216700 1 mon.mds01@0(leader).osd e1031871 prepare_failure osd.39 v1:10.3.0.9:6860/5574 from osd.408 is reporting failure:1 Wed 2023-09-06 22:42:25 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:25.905+0000 7f8f72216700 0 log_channel(cluster) log [DBG] : osd.39 reported failed by osd.408 Wed 2023-09-06 22:42:25 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:25.905+0000 7f8f72216700 1 mon.mds01@0(leader).osd e1031871 we have enough reporters to mark osd.39 down Wed 2023-09-06 22:42:25 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:25.905+0000 7f8f72216700 0 log_channel(cluster) log [INF] : osd.39 failed (root=default,host=ceph-osd09) (2 reporters from different host after 32.232905 >= grace 30.000000) Wed 2023-09-06 22:42:26 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:26.445+0000 7f8f74a1b700 0 log_channel(cluster) log [WRN] : Health check failed: 1 osds down (OSD_DOWN) Wed 2023-09-06 22:42:26 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:26.453+0000 7f8f70212700 1 mon.mds01@0(leader).osd e1031872 e1031872: 459 total, 437 up, 438 in Wed 2023-09-06 22:42:26 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:26.453+0000 7f8f70212700 0 log_channel(cluster) log [DBG] : osdmap e1031872: 459 total, 437 up, 438 in <other MONs report the same> Wed 2023-09-06 22:42:26 UTC ceph-osd09 ceph-osd@39.service[5574]: 2023-09-06T22:42:26.532+0000 7f83d813d700 0 --1- v1:10.3.0.9:6862/5574 >> v1:10.3.0.7:6857/5579 conn(0x55cd63342000 0x55cd63344000 :-1 s=OPENED pgs=12691 cs=1079 l=0).fault initiating reconnect Wed 2023-09-06 22:42:26 UTC ceph-osd09 ceph-osd@39.service[5574]: 2023-09-06T22:42:26.532+0000 7f83d813d700 0 --1- v1:10.3.0.9:6862/5574 >> v1:10.3.0.7:6857/5579 conn(0x55cd63342000 0x55cd63344000 :-1 s=CONNECTING_SEND_CONNECT_MSG pgs=12691 cs=1080 l=0).handle_connect_reply_2 connect got RESETSESSION Wed 2023-09-06 22:42:26 UTC ceph-osd07 ceph-osd@91.service[5579]: 2023-09-06T22:42:26.529+0000 7fbf8f3ed700 0 --1- v1:10.3.0.7:6857/5579 >> v1:10.3.0.9:6862/5574 conn(0x5588d67cac00 0x5588f210b000 :6857 s=ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_message_2 accept we reset (peer sent cseq 1080), sending RESETSESSION <some more reconnects and RESETSESSIONs> Wed 2023-09-06 22:42:26 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:26.769+0000 7f8f72216700 0 log_channel(cluster) log [INF] : osd.39 marked itself dead as of e1031872 Wed 2023-09-06 22:42:26 UTC ceph-osd09 ceph-osd@39.service[5574]: 2023-09-06T22:42:26.768+0000 7f83c4ed7700 0 log_channel(cluster) log [WRN] : Monitor daemon marked osd.39 down, but it is still running Wed 2023-09-06 22:42:26 UTC ceph-osd09 ceph-osd@39.service[5574]: 2023-09-06T22:42:26.768+0000 7f83c4ed7700 0 log_channel(cluster) log [DBG] : map e1031872 wrongly marked me down at e1031872 Wed 2023-09-06 22:42:26 UTC ceph-osd09 ceph-osd@39.service[5574]: 2023-09-06T22:42:26.768+0000 7f83c4ed7700 1 osd.39 1031872 start_waiting_for_healthy Wed 2023-09-06 22:42:26 UTC ceph-osd09 ceph-osd@39.service[5574]: 2023-09-06T22:42:26.772+0000 7f83c4ed7700 1 osd.39 1031872 is_healthy false -- only 0/12 up peers (less than 33%) Wed 2023-09-06 22:42:26 UTC ceph-osd09 ceph-osd@39.service[5574]: 2023-09-06T22:42:26.772+0000 7f83c4ed7700 1 osd.39 1031872 not healthy; waiting to boot Wed 2023-09-06 22:42:27 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:27.481+0000 7f8f70212700 1 mon.mds01@0(leader).osd e1031873 e1031873: 459 total, 437 up, 438 in Then osd.39 comes up by itself: Wed 2023-09-06 22:42:28 UTC ceph-osd09 ceph-osd@39.service[5574]: 2023-09-06T22:42:28.516+0000 7f83d20fe700 1 osd.39 1031873 tick checking mon for new map Wed 2023-09-06 22:42:28 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:28.541+0000 7f8f70212700 0 log_channel(cluster) log [INF] : osd.39 v1:10.3.0.9:6860/5574 boot Wed 2023-09-06 22:42:28 UTC mds01 ceph-mon@mds01.service[3258]: 2023-09-06T22:42:28.541+0000 7f8f70212700 0 log_channel(cluster) log [DBG] : osdmap e1031874: 459 total, 438 up, 438 in 1) Is this the same? 2) It's strange that the majority (but not all) of OSDs saying "no reply" come from the old part of the cluster. Is there any debug option that would allow us to discriminate between the automatic compaction and network issues? At which debug level are automatic compactions announced? I am asking the question (2) because, prior to the first osd_op_tp timeout, there is nothing that announces a compaction. On Thu, Sep 7, 2023 at 5:08 PM J-P Methot <jp.methot@planethoster.info> wrote:
We're talking about automatic online compaction here, not running the command.
On 9/7/23 04:04, Konstantin Shalygin wrote:
Hi,
On 7 Sep 2023, at 10:05, J-P Methot <jp.methot@planethoster.info> wrote:
We're running latest Pacific on our production cluster and we've been seeing the dreaded 'OSD::osd_op_tp thread 0x7f346aa64700' had timed out after 15.000000954s' error. We have reasons to believe this happens each time the RocksDB compaction process is launched on an OSD. My question is, does the cluster detecting that an OSD has timed out interrupt the compaction process? This seems to be what's happening, but it's not immediately obvious. We are currently facing an infinite loop of random OSDs timing out and if the compaction process is interrupted without finishing, it may explain that.
You run the online compacting for this OSD's (`ceph osd compact ${osd_id}` command), right?
k
-- Jean-Philippe Méthot Senior Openstack system administrator Administrateur système Openstack sénior PlanetHoster inc. _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
-- Alexander E. Patrakov