diff --git a/CHANGELOG.md b/CHANGELOG.md index 7c77f4b..c286a1b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Changed +- Traces of the disk sweep, episode lists and DeadAir's work on each file show each step, and the sweep's trace says what it removed (#187). - DeadAir is in the same box as a show's download settings, below them, and stays there when automatic downloads are off (#185). - The container is built on Debian 13 (trixie) instead of 12, so DeadAir uses ffmpeg 7.1 instead of 5.1 (#177). - DeadAir no longer makes a shortened copy of each episode. It plays the original with its long silences left out, ready a few seconds after the download, with no gap where a silence was cut and no extra disk space (#181). diff --git a/src/deadair.rs b/src/deadair.rs index 2322a6e..9b28bd8 100644 --- a/src/deadair.rs +++ b/src/deadair.rs @@ -18,6 +18,10 @@ use std::fmt::Write as _; use std::path::Path; use std::sync::Arc; +use tracing::Instrument; + +use crate::db::step; + use anyhow::{Context, Result, bail}; use serde::{Deserialize, Serialize}; @@ -420,7 +424,10 @@ async fn next(ctx: &Ctx, failed: &mut std::collections::HashSet) -> Result< } let src = crate::download::playable(Path::new(&t.path)); let started = std::time::Instant::now(); - let plans = match analyse(&src).await { + // A trace of its own for each file looked at, not for the passes that find nothing to do, + // which are most of them. + let span = tracing::info_span!("deadair", feed = t.feed_id, enclosure = t.id, cuts = tracing::field::Empty); + let plans = match analyse(&src).instrument(span.clone()).await { Ok(p) => p.unwrap_or_default(), Err(e) => { tracing::warn!(path = %src.display(), error = %format!("{e:#}"), "DeadAir could not read a file"); @@ -428,8 +435,9 @@ async fn next(ctx: &Ctx, failed: &mut std::collections::HashSet) -> Result< return Ok(true); } }; - ctx.db.store_plans(t.id, &serde_json::to_string(&plans)?).await?; + ctx.db.store_plans(t.id, &serde_json::to_string(&plans)?).instrument(span.in_scope(|| step("store_plans"))).await?; let usual = plans.get(&DEFAULT_PAUSE); + span.record("cuts", usual.map_or(0, |p| p.cuts.len())); let saved_ms = usual.map_or(0, Plan::saved_ms); ctx.out.emit(crate::ipc::Event::DeadairDone { feed: t.feed_id.clone(), enclosure: t.id, saved_s: saved_ms / 1000 }); // The event says it too (ev="deadair_done"); this line has how long it took and how many cuts. @@ -450,16 +458,17 @@ async fn next(ctx: &Ctx, failed: &mut std::collections::HashSet) -> Result< /// anything but MP3 or AAC on its own (ADTS; AAC in MP4 has no byte ranges a playlist can /// use), or one with no silence long enough to cut. pub async fn analyse(src: &Path) -> Result>> { - let Some((first, frame)) = probe(src).await? else { return Ok(None) }; + let Some((first, frame)) = probe(src).instrument(step("probe")).await? else { return Ok(None) }; let path = src.display().to_string(); let log = ffmpeg(&[ "-hide_banner", "-nostats", "-i", &path, "-map", "0:a:0", "-af", &format!("silencedetect=n={THRESHOLD}:d={MIN_SILENCE}"), "-f", "null", "-", ]) + .instrument(step("silencedetect")) .await .context("finding the silences")?; let silences = parse_silences(&log); - let frames = frame_bytes(&path).await?; + let frames = frame_bytes(&path).instrument(step("frame_bytes")).await?; let plans: BTreeMap = PAUSES .iter() .map(|&pause| { diff --git a/src/main.rs b/src/main.rs index ff678c3..26c8406 100644 --- a/src/main.rs +++ b/src/main.rs @@ -1137,12 +1137,16 @@ async fn clean_directory(ctx: &Ctx) -> Result<()> { /// `standalone` false means this is the sweep that runs before a scan: it reports what it /// deleted, but must not emit the terminal ReapDone, or a client waiting on its `fetch` /// would stop reading before the scan had even started. -#[tracing::instrument(name = "reap", skip_all, fields(dry_run = dry_run))] +#[tracing::instrument(name = "reap", skip_all, fields(dry_run = dry_run, files = tracing::field::Empty, bytes = tracing::field::Empty, entries = tracing::field::Empty))] async fn reap(ctx: &Ctx, dry_run: bool, standalone: bool) -> Result<()> { let r = retention::run(&ctx.cfg(), &ctx.db, dry_run).await?; + let span = tracing::Span::current(); + span.record("files", r.aged_out.len() + r.over_quota.len()); + span.record("bytes", r.bytes_freed); + span.record("entries", r.entries_pruned); if !dry_run { - clean_directory(ctx).await?; - let gone = art::trim(&art::dir(), ctx.cfg().general.art_cache_mb * 1_048_576); + tracing::Instrument::instrument(clean_directory(ctx), db::step("clean_directory")).await?; + let gone = db::step("trim_artwork").in_scope(|| art::trim(&art::dir(), ctx.cfg().general.art_cache_mb * 1_048_576)); if gone > 0 { tracing::debug!(gone, "trimmed the artwork kept on disk"); } diff --git a/src/retention.rs b/src/retention.rs index fb779ae..6b19a18 100644 --- a/src/retention.rs +++ b/src/retention.rs @@ -1,9 +1,10 @@ //! Disk quota and age sweeps. Replaces iPXQuotaManager.py ("SmartSpace"). use anyhow::Result; +use tracing::Instrument; use crate::config::Config; -use crate::db::{Candidate, Db, now}; +use crate::db::{Candidate, Db, now, step}; /// Headroom kept below the quota, as getToQuota()'s `1048576 * 50` did. pub const PAD_BYTES: u64 = 50 * 1024 * 1024; @@ -49,7 +50,8 @@ pub async fn run(cfg: &Config, db: &Db, dry_run: bool) -> Result { let mut report = Report::default(); // Someone may have deleted a file by hand; the row must stop claiming it exists. - for (id, path) in db.missing_files().await? { + // Each step is a span of the reap's trace, so a slow one says which part was slow. + for (id, path) in db.missing_files().instrument(step("missing_files")).await? { if !dry_run { db.mark_reaped(id).await?; } @@ -57,20 +59,20 @@ pub async fn run(cfg: &Config, db: &Db, dry_run: bool) -> Result { report.reconciled += 1; } - for id in db.prune_abandoned_failures().await? { + for id in db.prune_abandoned_failures().instrument(step("prune_abandoned_failures")).await? { tracing::info!(feed = id, "forgot a failing feed nobody subscribes to"); } - let candidates = db.reap_candidates().await?; + let candidates = db.reap_candidates().instrument(step("reap_candidates")).await?; if cfg.general.max_age_days > 0 { let cutoff = now() - (cfg.general.max_age_days * 86_400) as i64; report.aged_out = aged(&candidates, cutoff); for c in &report.aged_out { - report.bytes_freed += remove(db, c, dry_run).await?; + report.bytes_freed += remove(db, c, dry_run).instrument(step("remove_aged")).await?; } if !dry_run { - report.entries_pruned = db.prune_entries(cutoff).await?; + report.entries_pruned = db.prune_entries(cutoff).instrument(step("prune_entries")).await?; } } @@ -85,7 +87,7 @@ pub async fn run(cfg: &Config, db: &Db, dry_run: bool) -> Result { let total: u64 = remaining.iter().map(|c| c.bytes.max(0) as u64).sum(); report.over_quota = pick(&remaining, total, limit); for c in &report.over_quota { - report.bytes_freed += remove(db, c, dry_run).await?; + report.bytes_freed += remove(db, c, dry_run).instrument(step("remove_over_quota")).await?; } } diff --git a/src/web.rs b/src/web.rs index c109f55..bb4d0c7 100644 --- a/src/web.rs +++ b/src/web.rs @@ -21,6 +21,8 @@ use std::sync::Arc; use tokio::sync::{broadcast, mpsc}; use crate::Ctx; +use crate::db::step; +use tracing::Instrument; use crate::ipc::{Command, Event}; const COOKIE: &str = "ipx_token"; @@ -833,8 +835,6 @@ async fn feeds( /// The feed list as this person sees it, or with `only` the one row for that feed: what a live /// update sends after the feed changes, so the page redraws a row instead of reloading the list. async fn feed_rows(state: &WebState, user: &crate::db::User, only: Option<&str>) -> anyhow::Result> { - use crate::db::step; - use tracing::Instrument; let cfg = state.ctx.cfg(); // Config entries plus the feeds derived from OPML subscriptions -- the catalogue. // What comes back is only the part of it this person subscribes to. @@ -1468,16 +1468,20 @@ async fn entry_page( let search = page.q.as_deref().map(str::trim).filter(|q| !q.is_empty()); let db = &state.ctx.db; let order = crate::db::order_sql(page.sort.as_deref().unwrap_or("published"), page.dir.as_deref().unwrap_or("desc")); - let mut rows = - db.entries_in(user_id, feed, filter, search, page.offset, page.limit.clamp(1, 200), &order).await?; - let mut sanitizer = feed_sanitizer(); - for row in &mut rows { - if let Some(d) = &row.description { - row.description = Some(clean_description(&mut sanitizer, d, row.link.as_deref())); + let mut rows = db + .entries_in(user_id, feed, filter, search, page.offset, page.limit.clamp(1, 200), &order) + .instrument(step("entries_in")) + .await?; + step("sanitize").in_scope(|| { + let mut sanitizer = feed_sanitizer(); + for row in &mut rows { + if let Some(d) = &row.description { + row.description = Some(clean_description(&mut sanitizer, d, row.link.as_deref())); + } } - } - crate::deadair::for_reader(&state.ctx, user_id, &mut rows).await?; - let total = db.count_in(user_id, feed, filter, search).await?; + }); + crate::deadair::for_reader(&state.ctx, user_id, &mut rows).instrument(step("deadair")).await?; + let total = db.count_in(user_id, feed, filter, search).instrument(step("count_in")).await?; Ok(Json(EntryPage { total, entries: rows })) } @@ -1960,7 +1964,7 @@ async fn media_deadair(State(state): State, Path(id): Path, user: if let Err(e) = subscribed(&state, &user, &enc.feed_id).await { return e.into_response(); } - let plan = match crate::deadair::plan_for(&state.ctx, user.id, &enc.feed_id, id).await { + let plan = match crate::deadair::plan_for(&state.ctx, user.id, &enc.feed_id, id).instrument(step("plan")).await { Ok(Some(p)) => p, Ok(None) => return (StatusCode::NOT_FOUND, "DeadAir has nothing to cut in this file for you").into_response(), Err(e) => return (StatusCode::INTERNAL_SERVER_ERROR, format!("{e:#}")).into_response(), @@ -1988,7 +1992,7 @@ async fn media_save(State(state): State, Path(id): Path, user: cr let Some(path) = enc.path else { return (StatusCode::NOT_FOUND, "not downloaded").into_response(); }; - let plan = match crate::deadair::plan_for(&state.ctx, user.id, &enc.feed_id, id).await { + let plan = match crate::deadair::plan_for(&state.ctx, user.id, &enc.feed_id, id).instrument(step("plan")).await { Ok(Some(p)) => p, Ok(None) => return (StatusCode::NOT_FOUND, "DeadAir has nothing to cut in this file for you").into_response(), Err(e) => return (StatusCode::INTERNAL_SERVER_ERROR, format!("{e:#}")).into_response(),