pq/libfreemkv
1
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

v0.13.13 — telemetry: tracing instrumentation in SgIoTransport + Disc::copy

Browse Source 
v0.13.12 shipped the async fd_recovery design but a live test on Dune 2
showed Pass 1 sat for 14 minutes with bytes_good=0 — the inner loop iterates
(throttled on_progress log fires every 78s) but each iteration evidently
takes ~60s instead of the microseconds the design promises on fast-fail.
Without trace-level telemetry at the SCSI + Disc::copy boundaries we
can't tell where the time goes.

This release is instrumentation only — no behavior change.

- New dep: tracing 0.1. Per CLAUDE.md, debug/trace logging is allowed in
  libfreemkv (the no-English rule applies to errors). Consumers wire a
  tracing subscriber.
- SgIoTransport::execute (Linux): trace at every state transition (entry,
  recovery_swap_ok, recovery_pending, write_ok / write_err, poll_done,
  timeout_spawn_recovery, scsi_err, read_err, ok). Each event includes
  opcode + elapsed timing. The bg recovery thread also traces close_ms +
  open_ms so we can see if the kernel really takes 60s to close+open on a
  wedged Initio bridge.
- Disc::copy: trace at copy_start, outer_loop, region_enter, every 100
  inner-loop iterations (iter_progress with pos/region_end/skip_size/
  bytes_good/read_ok_count/read_err_count/last_read_ms/copy_elapsed_ms),
  copy_done.
- All trace events use targets `freemkv::scsi` and `freemkv::disc` so
  consumers can filter by subsystem (e.g. autorip /api/debug?q=freemkv::scsi).

Next: run the live test on Dune 2 again, read the autorip JSONL log,
diagnose why each iter is slow, fix the actual bug.
This commit is contained in:
matthew
2026-04-25 18:32:05 -07:00
parent 4fd60389fa
commit ae18dc35b7
4 changed files with 215 additions and 6 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/disc/mod.rs
+66
View File
@@ -1286,6 +1286,20 @@ impl Disc {
let mut buf = vec![0u8; batch as usize * 2048];
let mut bytes_done = 0u64;
let mut halt_requested = false;
let copy_t0 = std::time::Instant::now();
let mut iter_count: u64 = 0;
let mut read_ok_count: u64 = 0;
let mut read_err_count: u64 = 0;
let mut last_log_iter: u64 = 0;
tracing::trace!(
target: "freemkv::disc",
phase = "copy_start",
total_bytes,
batch,
skip_init,
skip_max,
"Disc::copy entered"
);
// Iterate over not-yet-finished regions from the mapfile. We re-read the
// mapfile after each block because record() mutates the region list.
@@ -1295,6 +1309,12 @@ impl Disc {
mapfile::SectorStatus::NonTrimmed,
mapfile::SectorStatus::NonScraped,
]);
tracing::trace!(
target: "freemkv::disc",
phase = "outer_loop",
regions_remaining = regions_to_do.len(),
"Disc::copy outer iter"
);
if regions_to_do.is_empty() {
break;
}
@@ -1307,6 +1327,14 @@ impl Disc {
};
let region_end = region_pos + region_size;
let mut pos = region_pos;
tracing::trace!(
target: "freemkv::disc",
phase = "region_enter",
region_pos,
region_size,
region_end,
"entering NonTried region"
);
while pos < region_end {
if let Some(ref h) = opts.halt {
@@ -1321,11 +1349,15 @@ impl Disc {
let bytes = count as usize * 2048;
let recovery = !opts.skip_on_error; // fast reads when skipping
iter_count += 1;
let read_t0 = std::time::Instant::now();
let read_ok = reader
.read_sectors(lba, count, &mut buf[..bytes], recovery)
.is_ok();
let read_elapsed_ms = read_t0.elapsed().as_millis() as u64;
if read_ok {
read_ok_count += 1;
if opts.decrypt {
crate::decrypt::decrypt_sectors(&mut buf[..bytes], &keys, 0)?;
}
@@ -1339,6 +1371,7 @@ impl Disc {
skip_size = skip_init; // reset after success
pos += block_bytes;
} else if opts.skip_on_error {
read_err_count += 1;
// Zero-fill this block, mark non-trimmed for later patch trim.
buf[..bytes].fill(0);
file.seek(SeekFrom::Start(pos))
@@ -1364,6 +1397,27 @@ impl Disc {
return Err(Error::DiscRead { sector: lba as u64 });
}
// Throttled iter telemetry — every 100 inner iterations.
if iter_count - last_log_iter >= 100 {
last_log_iter = iter_count;
let stats = map.stats();
tracing::trace!(
target: "freemkv::disc",
phase = "iter_progress",
iter_count,
read_ok_count,
read_err_count,
last_read_ms = read_elapsed_ms,
pos,
region_end,
skip_size,
bytes_good = stats.bytes_good,
bytes_pending = stats.bytes_pending,
copy_elapsed_ms = copy_t0.elapsed().as_millis() as u64,
"Disc::copy inner iter"
);
}
if let Some(cb) = opts.on_progress {
let stats = map.stats();
cb(stats.bytes_good, total_bytes);
@@ -1373,6 +1427,18 @@ impl Disc {
file.sync_all().map_err(|e| Error::IoError { source: e })?;
let stats = map.stats();
tracing::trace!(
target: "freemkv::disc",
phase = "copy_done",
iter_count,
read_ok_count,
read_err_count,
bytes_good = stats.bytes_good,
bytes_pending = stats.bytes_pending,
halted = halt_requested,
copy_elapsed_ms = copy_t0.elapsed().as_millis() as u64,
"Disc::copy returning"
);
Ok(CopyResult {
bytes_total: total_bytes,
bytes_good: stats.bytes_good,
src/scsi/linux.rs
+104 -5
View File
@@ -260,6 +260,18 @@ impl ScsiTransport for SgIoTransport {
data: &mut [u8],
timeout_ms: u32,
) -> Result<ScsiResult> {
let exec_t0 = std::time::Instant::now();
let opcode = cdb[0];
tracing::trace!(
target: "freemkv::scsi",
phase = "enter",
opcode = opcode,
timeout_ms,
data_len = data.len(),
fd = self.fd,
"SgIoTransport::execute"
);
// Recover from a prior timeout: if a background reopen produced a
// fresh fd, swap it in. If recovery is still pending (-1), the
// background thread hasn't finished — return DeviceNotFound and let
@@ -269,8 +281,20 @@ impl ScsiTransport for SgIoTransport {
.fd_recovery
.swap(-1, std::sync::atomic::Ordering::Acquire);
if recovered >= 0 {
tracing::trace!(
target: "freemkv::scsi",
phase = "recovery_swap_ok",
new_fd = recovered,
"fd_recovery delivered fresh fd"
);
self.fd = recovered;
} else {
tracing::trace!(
target: "freemkv::scsi",
phase = "recovery_pending",
elapsed_us = exec_t0.elapsed().as_micros() as u64,
"fd_recovery still pending → DeviceNotFound"
);
return Err(Error::DeviceNotFound {
path: self.device_path.display().to_string(),
});
@@ -309,6 +333,7 @@ impl ScsiTransport for SgIoTransport {
// Submit command asynchronously via write()
let hdr_size = std::mem::size_of::<sg_io_hdr>();
let write_t0 = std::time::Instant::now();
let wr = unsafe {
libc::write(
self.fd,
@@ -316,16 +341,32 @@ impl ScsiTransport for SgIoTransport {
hdr_size,
)
};
let write_elapsed_us = write_t0.elapsed().as_micros() as u64;
if wr < 0 {
return Err(Error::IoError {
source: std::io::Error::last_os_error(),
});
let errno = std::io::Error::last_os_error();
tracing::trace!(
target: "freemkv::scsi",
phase = "write_err",
opcode = opcode,
errno = errno.raw_os_error().unwrap_or(0),
write_elapsed_us,
"sg write() returned <0"
);
return Err(Error::IoError { source: errno });
}
tracing::trace!(
target: "freemkv::scsi",
phase = "write_ok",
opcode = opcode,
wr,
write_elapsed_us,
"sg write() submitted"
);
// Wait for completion with enforceable timeout.
// Retry on EINTR (signal interrupted poll) with remaining time.
let deadline =
std::time::Instant::now() + std::time::Duration::from_millis(timeout_ms as u64);
let poll_t0 = std::time::Instant::now();
let deadline = poll_t0 + std::time::Duration::from_millis(timeout_ms as u64);
let pr = loop {
let remaining = deadline
.saturating_duration_since(std::time::Instant::now())
@@ -344,6 +385,16 @@ impl ScsiTransport for SgIoTransport {
break ret;
}
};
let poll_elapsed_ms = poll_t0.elapsed().as_millis() as u64;
tracing::trace!(
target: "freemkv::scsi",
phase = "poll_done",
opcode = opcode,
pr,
poll_elapsed_ms,
timeout_ms,
"poll() returned"
);
if pr <= 0 {
// Timeout (0) or fatal poll error (-1). Command is still pending
@@ -355,17 +406,38 @@ impl ScsiTransport for SgIoTransport {
self.fd = -1;
let c_path = Self::to_c_path(&self.device_path);
let recovery = self.fd_recovery.clone();
tracing::trace!(
target: "freemkv::scsi",
phase = "timeout_spawn_recovery",
opcode = opcode,
old_fd,
exec_elapsed_ms = exec_t0.elapsed().as_millis() as u64,
"poll timeout — spawning bg close+open"
);
std::thread::spawn(move || {
// Close blocks until the kernel finishes/aborts the
// abandoned command. Then we open a fresh fd. Both happen
// off the main thread.
let close_t0 = std::time::Instant::now();
unsafe { libc::close(old_fd) };
let close_ms = close_t0.elapsed().as_millis() as u64;
let open_t0 = std::time::Instant::now();
let new_fd = unsafe {
libc::open(
c_path.as_ptr() as *const libc::c_char,
libc::O_RDWR | libc::O_NONBLOCK | libc::O_CLOEXEC,
)
};
let open_ms = open_t0.elapsed().as_millis() as u64;
tracing::trace!(
target: "freemkv::scsi",
phase = "bg_recovery_done",
old_fd,
new_fd,
close_ms,
open_ms,
"bg recovery thread completed close+open"
);
if new_fd >= 0 {
let prev = recovery.swap(new_fd, std::sync::atomic::Ordering::Release);
if prev >= 0 {
@@ -386,6 +458,7 @@ impl ScsiTransport for SgIoTransport {
}
// Read response — copies data from kernel buffer to caller's buffer
let read_t0 = std::time::Instant::now();
let rd = unsafe {
libc::read(
self.fd,
@@ -393,7 +466,16 @@ impl ScsiTransport for SgIoTransport {
hdr_size,
)
};
let read_elapsed_us = read_t0.elapsed().as_micros() as u64;
if rd < 0 {
tracing::trace!(
target: "freemkv::scsi",
phase = "read_err",
opcode = opcode,
read_elapsed_us,
exec_elapsed_ms = exec_t0.elapsed().as_millis() as u64,
"sg read() returned <0"
);
return Err(Error::IoError {
source: std::io::Error::last_os_error(),
});
@@ -414,6 +496,15 @@ impl ScsiTransport for SgIoTransport {
} else {
0
};
tracing::trace!(
target: "freemkv::scsi",
phase = "scsi_err",
opcode = opcode,
status = hdr.status,
sense_key,
exec_elapsed_ms = exec_t0.elapsed().as_millis() as u64,
"SCSI status non-zero"
);
return Err(Error::ScsiError {
opcode: cdb[0],
status: hdr.status,
@@ -421,6 +512,14 @@ impl ScsiTransport for SgIoTransport {
});
}
tracing::trace!(
target: "freemkv::scsi",
phase = "ok",
opcode = opcode,
bytes_transferred,
exec_elapsed_ms = exec_t0.elapsed().as_millis() as u64,
"execute() success"
);
Ok(ScsiResult {
status: hdr.status,
bytes_transferred,