Troubleshooting Ceph: From HEALTH_WARN to the Peering State Machine

17-1 Before you start#

17-1-1 What questions does this chapter answer?#

Troubleshooting Ceph in the middle of an incident needs method more than memory: where to start, which command shows which layer, and when to hold back. This chapter presents a systematic method and then goes into the code to see exactly where in the PG state machine states such as down, incomplete or peering come from.

• What is the step-by-step troubleshooting method, from ceph -s to the root of the problem?
• How do we separate MON, OSD and network problems?
• What do the PG states mean, and how does the Peering state machine work?
• How do we follow slow ops down to the exact event in the operation's path?
• How does scrub find inconsistencies, and when is repair safe?
• Which commands are dangerous and used only as a last resort?

17-2 The troubleshooting method#

ceph -s                           # overview: health, mon, osd, pgs, io
ceph health detail                # each warning's code with details
ceph health detail --format json-pretty | jq '.checks | keys'
ceph versions                     # version mismatch after an unfinished upgrade
ceph crash ls-new                 # new crashes (RECENT_CRASH)
ceph log last 100                 # the cluster log in the MON

17-2-1 Common warnings#

17-3 MON problems#

• Loss of quorum: no command responds. On each MON host, check with the admin socket: ceph daemon mon.$(hostname -s) mon_status (in cephadm: cephadm shell --name mon.<host> and then the same command). Look at the state, quorum and outside_quorum fields.
• Clock skew: Paxos depends on a time lease; chronyc sources and chronyc tracking on all MONs.
• store.db growth: during long unhealthy periods, the MON does not trim old maps. ceph tell mon.* compact, and fix the cause of the unhealthiness.

17-4 OSD problems#

ceph osd tree down
ceph osd find 12                         # host and path
cephadm logs --name osd.12 -- -n 200     # on the host
ceph crash ls | grep osd.12
ceph daemon osd.12 status                # if it is up
ceph osd dump | grep -E "^osd.12 "

17-5 PG states#

ceph pg stat
ceph pg dump_stuck inactive
ceph pg dump_stuck unclean
ceph pg dump_stuck stale
ceph pg ls down
ceph pg 2.1f query | jq '.state, .recovery_state[0]'

17-6 Inside the code: the Peering state machine#

17-6-1 The hierarchical structure#

src/osd/PeeringState.h defines the PG state machine with boost::statechart. Each state is a struct that names its parent; for example struct GetInfo : boost::statechart::state<GetInfo, Peering>. So the full name of a state is a path: Started/Primary/Peering/GetInfo. Events (such as AdvMap for a new map, MNotifyRec for receiving information from another OSD, GotLog, Activate) move between states.

17-6-2 The prior set and up_thru: why a PG goes "down"#

The central question of peering is: could there be an acknowledged write that we do not know about? Every time the acting set changes, a new interval begins. For each past interval since the last time it became active, the PG checks whether the PG could have become active in that interval and accepted writes. This "could have" is measured with up_thru: before becoming active, the primary must wait until the MON records in the OSDMap that this OSD was alive up to this epoch (the WaitUpThru state). If there is an interval in which up_thru was recorded (so writes may have happened) and none of that interval's OSDs is available now, the PG cannot be sure and goes to Down.

pseudocode: building the prior set (this book's summary of PastIntervals in osd_types)
  for interval in past_intervals since last_epoch_started:
      if not interval.maybe_went_rw: continue        # up_thru not recorded → writes were impossible
      up_now = [osd for osd in interval.acting if osd is up]
      # replicated: if no live OSD remains from that interval → down
      if not recoverable(up_now):             pg_down = true            # EC: fewer than k shards (simplified; the real predicate is IsPGRecoverablePredicate)
      probe += up_now
  return (probe, pg_down, down_osds_we_would_probe)

17-6-3 find_best_info: which log is authoritative?#

In GetLog, the function PeeringState::find_best_info() chooses the best of the received pg_infos. Its logic (this book's rewrite):

pseudocode: find_best_info(infos)
  (max_les, min_lu) = calculate_maxles_and_minlua(infos)   # the maximum last_epoch_started
  if min_lu == max: return none                              # no acceptable candidate
  best = none
  for (shard, info) in infos:
      skip if info.last_update < min_lu
      skip if info.last_epoch_started < max_les
      skip if info.is_incomplete()
      if best is none: best = info; continue
      if pool.require_rollback():          # EC: the smallest last_update is safe (rollback possible)
          prefer smaller last_update
      else:                                # replicated: the largest last_update
          prefer larger last_update
      then prefer smaller log_tail          # a longer log → log-based recovery for more replicas
      then prefer complete (no missing)
      then prefer current primary / up set
  return best

17-7 Three troubleshooting algorithms in numbers#

A good troubleshooter should know exactly which calculation produces outputs such as "PG is down", "slow request 61 seconds old" or "deep scrub is behind". This section follows three calculations with sample data.

17-7-1 Which OSD has the authoritative log?#

pseudocode
max_les = 0
for info: max_les = max(max_les, info.history.les)            # unless osd_find_best_info_ignore_history_les
          if !incomplete: max_les = max(max_les, info.les)
min_lua = min(info.last_update | info.les ≥ max_les)          # if none: the PG has no valid info
best = ∅
for info (only up/acting if restrict):
    skip if lu < min_lua or les < max_les or incomplete
    replicated: larger lu is better ; EC (require_rollback): smaller lu is better
    on a tie: smaller log_tail (longer log) ; then no missing ; then the current primary

Numerical example. A replicated PG receives four infos (eversion in the form epoch'version):

The selection steps:

1. 1. max_les = 40.
2. 2. min_lua among les ≥ 40 is 41'118. eversion comparison looks at the epoch first, so 38'300 is smaller than 41'118 even though its version is larger.
3. 3. osd.7 is dropped because of its les of 38.
4. 4. Of the three remaining candidates, osd.1 and osd.9 have the newest last_update.
5. 5. The smaller tail, that is 40'90 < 41'20, wins, so osd.9 becomes the reference, not the primary.

After this step the primary fetches the authoritative log from osd.9 (GetLog). If all OSDs with les = 40 had failed, min_lua would remain undefined and the PG would get stuck in down/incomplete. This is exactly where ceph pg query shows the down_osds_we_would_probe list in its recovery_state section.

17-7-2 Timing of the slow request warning#

pseudocode
too_old = now − osd_op_complaint_time (30 s)
visit ops by initiated (oldest to newest):
    if op.initiated ≥ too_old: stop                # the rest are younger
    if continuous or multiplier == 0: skip
    slow++                                         # counted in SLOW_OPS and health
    if warned ≥ osd_op_log_threshold (5): continue # count only, no log
    if op.initiated + 30 × multiplier ≥ now: continue
    warned++ ; log "slow request …" ; multiplier ×= 2

Numerical example. An op got stuck at t = 0, and the OSD checks every second.

• t = 31 s: the op is slow and multiplier = 1, so 0 + 30 < 31 and it is logged. multiplier becomes 2.
• The next log is when 0 + 60 < now, that is t = 61. After that t = 121 and t = 241 (multiplier 4 and 8).
• In total, four log lines are written for this op in 400 seconds, but it is counted in SLOW_OPS the whole time.

If 50 ops are slow at once, each check logs at most 5 lines, but "50 slow requests" is reported. So a quiet log does not mean few slow ops. To see all of them, use ceph daemon osd.N dump_ops_in_flight and dump_historic_slow_ops.

17-7-3 When is the next scrub?#

pseudocode
shallow (if not urgent): target = last + min_interval + min_interval × randomize_ratio × U[0,1]
                         not_before = max(last, target)
deep:  sdv = deep_interval × cv
       target = last + clamp(N(deep_interval, sdv), deep_interval − 2·sdv, deep_interval + 2·sdv)
urgent (operator/repair): time = scrub_must_stamp , no randomness
guaranteed_offset: shallow = min × (2 + ratio) , deep = deep + 3·sdv + 10 s

Numerical example (defaults: min 1 day, randomize 0.5, deep 7 days, cv 0.2).

• Shallow scrub: the next one is uniformly distributed between 1 and 1.5 days after the last scrub.
• Deep scrub: sdv = 1.4 days, and the sample is clipped to the range 4.2 to 9.8 days. In a simulation of 100000 samples, about 68% fell between 5.6 and 8.4 days (0.8 to 1.2 times), and about 2.3% landed exactly on the two limits.

The long_desc of the osd_deep_scrub_interval_cv option says 95% are within [0.8, 1.2]. But with cv = 0.2 this range is only one standard deviation. 95% lie within ±2σ, that is [0.6, 1.4]. This inconsistency is in the option's help text, not in the behaviour. For a cluster with 4096 PGs, this spread means about 585 deep scrubs per day on average (4096/7), without all of them starting on the same day.

17-8 Troubleshooting with measured data#

The two figures in this section are built from real data, not guesses. The first shows the timeline of PG states on a real test cluster. The second shows the effect of losing hosts with an exact count over a CRUSH mapping.

17-8-1 Timeline of PG states#

The experiment ran on a three-OSD BlueStore cluster with Ceph 18.2.7 (Debian packages). The pool t17 had 32 PGs and size = 2, and 300 objects of 4 MiB had been written into it. Every second, ceph pg dump pgs_brief -f json was taken and the states counted. Four events were run back to back: ceph osd out 0, then ceph osd in 0, then stopping the osd.1 process, and finally restarting it.

pseudocode
every 1 second:
    pgs = ceph pg dump pgs_brief -f json
    count[state] += 1 for each pg                 # state like "active+recovery_wait+degraded"
    grouping: clean / recovering / recovery_wait / peering / stale / undersized
the next event runs only when all 32 PGs are active+clean again

What was seen.

• Marking osd.0 out: about 16 PGs went to peering. Then, instead of backfill, the PGs were seen in recovery_wait+degraded and recovering. The reason is that in this pool each PG has only about 9 objects, and each PG's log, which keeps at least osd_min_pg_log_entries = 250 entries, covers all the changes. So the new OSD is recovered from the log. In a real cluster with thousands of objects per PG, the same event produces backfill_wait and backfilling.
• Marking it in again: 22 PGs stayed in recovery_wait+degraded for a few seconds and were queued. This is the osd_max_backfills and osd_recovery_max_active cap under mClock.
• Stopping osd.1: stale was seen for a few seconds, because the mgr did not have a fresh report yet. Then peering took about 6 seconds, and at the end exactly 24 PGs, that is all PGs that had osd.1 in their up set, became active+undersized+degraded. I/O continued because min_size = 1. This setting is only for the experiment and is dangerous in a real environment.
• Bringing osd.1 back up: the PGs became clean with log-based recovery within a few seconds. The pause shown is more the delay in statistics reporting than the recovery itself.

17-8-2 Losing one, two or three hosts#

pseudocode
for each combination F of k hosts (all C(10, k) combinations):
    for each PG: n = number of replicas on the hosts in F
        degraded if n ≥ 1 ; inactive if size − n < min_size ; lost if n = size
mean, minimum and maximum over the combinations
P(a client touching N objects gets stuck) = 1 − (1 − p_inactive)^N      # object→PG with a uniform hash

Result (120 OSDs, size = 3, min_size = 2, 8192 PGs).

The means agree with closed-form formulas. For one host it is 3/10. For inactive PGs with two hosts it is C(8,1)/C(10,3) = 8/120. For PGs with no copy with three hosts it is 1/C(10,3) = 1/120.

The practical message is in the inactive column. With two failed hosts only 6.67% of PGs stop I/O. But a one-gigabyte RBD image (256 objects) has at least one object on them with probability $1 - 0.9333^{256} \approx 99.999998\%$. Even a client that touches only 10 objects gets stuck in 50% of cases. So "only 7% of PGs" in practice means almost every virtual machine has stopped.

Until the OSDs are marked out (mon_osd_down_out_interval, chapter 7), CRUSH does not choose new locations and this state continues. If two failure domains are at risk at the same time, the remedy is raising size or choosing a larger failure domain, not lowering min_size.

17-9 slow ops: following an operation#

17-9-1 TrackedOp and events#

Each client request in the OSD is an OpRequest (a subclass of TrackedOp) that records "events" along its path. If an operation takes longer than osd_op_complaint_time (default 30 seconds), it is counted in the SLOW_OPS warning.

ceph health detail | grep -A3 SLOW_OPS
ceph daemon osd.7 dump_ops_in_flight | jq '.ops[] | {age, description, last: .type_data.events[-1].event}'
ceph daemon osd.7 dump_blocked_ops
ceph daemon osd.7 dump_historic_slow_ops | jq '.ops[0].type_data.events'
ceph daemon osd.7 dump_historic_ops_by_duration | jq '.ops[0:3][] | {duration, description}'

17-10 Scrub and inconsistency#

17-10-1 The scrub state machine#

Periodic scrub (default osd_scrub_min_interval=1_day) compares object metadata between copies, and deep scrub (osd_deep_scrub_interval=7_day) also reads the data and verifies checksums. The new scrub code is in src/osd/scrubber/, and its state machine is defined in scrub_machine.h with boost::statechart.

Scrub proceeds by chunk: the primary chooses a range of objects (NewChunk), waits if writes to that range are in flight (RangeBlocked, WaitPushes, WaitLastUpdate), then builds a local map (ScrubMap) and also asks the replicas for maps. scrub_backend compares the maps: size, xattrs, data digest and omap. Inconsistencies are recorded in the ScrubStore (a temporary object) and can be read with rados list-inconsistent-obj.

ceph health detail | grep -E "inconsistent|scrub errors"
rados list-inconsistent-pg rbd
rados list-inconsistent-obj 2.1f --format=json-pretty | jq '.inconsistents[] | {object: .object.name, errors, shards: [.shards[] | {osd, errors}]}'
ceph pg deep-scrub 2.1f          # confirm again before repairing
ceph pg repair 2.1f

17-11 Unfound objects and dangerous tools#

ceph pg 2.5 list_unfound
ceph pg 2.5 query | jq '.recovery_state[] | select(.name|test("Active")) | .might_have_unfound'
# last resort, after making sure the OSD holding a copy will not come back:
ceph pg 2.5 mark_unfound_lost revert     # or delete

17-12 Supplementary and up to date#

• Since Pacific, the scrub code has been rewritten and moved to src/osd/scrubber/ with its own state machine; its scheduling is integrated with mclock.
• Newer warnings such as BLUESTORE_SLOW_OP_ALERT and DB_DEVICE_STALLED_READ_ALERT appear in the Health Checks documentation and reveal storage-layer slowness earlier.
• In the main branch, new states such as MigratingSource, MigratingTarget and WaitLocalPoolMigrationReserved have been added to PeeringState for pool migration; these states do not exist in the v20.2.0 and v21.2.0 tags and belong to future releases.
• ceph crash (an mgr module) has replaced searching for core dumps by hand.

17-13 Hands-on exercise#

1. 1. In a test cluster with size=3, stop two of a PG's three OSDs and follow recovery_state in pg query.
2. 2. With ceph osd set noout, shut down a host for maintenance; record the PG states and compare after it returns.
3. 3. With tc qdisc add dev eth1 root netem delay 200ms on one host, create slow ops and trace them to the guilty OSD.
4. 4. Corrupt an object directly on one OSD (with ceph-objectstore-tool), run a deep scrub and analyse the output of list-inconsistent-obj.
5. 5. Read the state machine in PeeringState.h and write down the path from Reset to Clean for a healthy PG.
6. 6. Export a PG with ceph-objectstore-tool and import it on another OSD.

17-14 Review questions#

1. 1. What are the first two commands in any incident, and why?
2. 2. What is the difference between degraded, undersized and remapped?
3. 3. What problem does the WaitUpThru state solve?
4. 4. Why does a PG go down, and what does the down_osds_we_would_probe field say?
5. 5. How does find_best_info differ between replicated and EC pools, and why?
6. 6. What does a last event of sub_op_sent in a slow op mean?
7. 7. How does scrub coordinate with in-flight writes?
8. 8. What should you check before ceph pg repair?
9. 9. What is the risk of ceph osd lost?
10. 10. Why must nodown and noout be temporary?

Answers to these questions are in Appendix E: Answers to Review Questions. Answers to this chapter's questions →

17-15 Sources for this chapter#

• Health checks
  https://docs.ceph.com/en/latest/rados/operations/health-checks/
• Monitoring OSDs and PGs
  https://docs.ceph.com/en/latest/rados/operations/monitoring-osd-pg/
• Placement group states
  https://docs.ceph.com/en/latest/rados/operations/pg-states/
• Troubleshooting PGs
  https://docs.ceph.com/en/latest/rados/troubleshooting/troubleshooting-pg/
• Troubleshooting OSDs
  https://docs.ceph.com/en/latest/rados/troubleshooting/troubleshooting-osd/
• Troubleshooting monitors
  https://docs.ceph.com/en/latest/rados/troubleshooting/troubleshooting-mon/
• Peering (developer guide
  https://docs.ceph.com/en/latest/dev/peering/
• Source: src/osd/PeeringState.h / .cc
  https://github.com/ceph/ceph/blob/main/src/osd/PeeringState.h
• Source: src/osd/scrubber
  https://github.com/ceph/ceph/tree/main/src/osd/scrubber
• Source: src/osd/OpRequest.h
  https://github.com/ceph/ceph/blob/main/src/osd/OpRequest.h