Deep investigation: per-OSD latency and logs

Why this matters in production

PG state tells you which OSD is implicated. It never tells you why that OSD is slow. The distinction between a failing disk, a saturated network path, an OSD out of memory, and a RocksDB compaction storm is invisible at the PG layer and obvious one layer down — and they have entirely different fixes.

The cluster-wide latency scan

ceph osd perf

osd  commit_latency(ms)  apply_latency(ms)
 12                 891                 904
 47                  11                  13
 83                   9                  12

commit_latency is the time to make a write durable; apply_latency is the time to make it visible. On BlueStore they move together. What you are looking for is not an absolute value but an outlier — one OSD far from its peers on the same hardware class.

Watching one OSD live

ceph daemonperf osd.12

This streams a live table of the OSD’s counters. The columns that carry the most signal:

An OSD with high latency and near-zero op counts is blocked on something. An OSD with high latency and high op counts is simply saturated.

In-flight operations

The admin socket exposes what the OSD is doing right now:

ceph daemon osd.12 ops
ceph daemon osd.12 dump_historic_ops
ceph daemon osd.12 dump_blocked_ops

ops lists in-flight requests with their age and current stage. A request sitting at waiting for rw locks for seconds is contention; one at waiting for subops from 47,83 is waiting on peers, which redirects the investigation to those OSDs. dump_historic_ops shows the slowest recently-completed operations with per-stage timings — the closest thing Ceph has to a request trace.

On containerised deployments run these through the orchestrator:

cephadm shell -- ceph daemon osd.12 dump_historic_ops

The log

journalctl -u ceph-osd@12 --since '2 hours ago' | grep -Ei 'slow|error|abort|heartbeat'

The events worth grepping for:

• slow request — an operation exceeded osd_op_complaint_time, with the stage it was stuck in
• heartbeat_check: no reply from — the OSD cannot reach a peer, which is a network finding
• _txc_committed delays and RocksDB compaction messages — storage-layer pressure
• osd_map gaps or map e... is newer — the OSD is behind on maps

Turn up verbosity only for a bounded window; debug logging is expensive:

ceph tell osd.12 config set debug_osd 10
# ... reproduce ...
ceph tell osd.12 config set debug_osd 0/5

Quiz

Production discipline

Capture dump_historic_ops and the relevant log window before restarting anything — both are lost on daemon restart, and they are the only artefacts that distinguish the possible causes after the fact. Build the OSD-latency outlier check into your monitoring so an OSD drifting away from its peers is detected before it stalls a scrub or a recovery.

Cross-course references

• Kubernetes: this is the container-runtime layer beneath a failing Pod — one level below where the symptom appears
• Linux: dump_historic_ops stage timings are the same technique as reading blktrace or perf stage breakdowns