|
| 1 | +# Progress reporting in `model_analyse` (and the firth/contrast loops) |
| 2 | + |
| 3 | +## TL;DR |
| 4 | + |
| 5 | +A progress bar **already exists** in `model_analyse()` and is correctly ticked |
| 6 | +by every strategy's `model_fun`. The problem is **it is silently suppressed in |
| 7 | +non-interactive / docker runs**, and it writes to `stderr` rather than to the |
| 8 | +`logger` log file that the app and users actually watch. So during a long |
| 9 | +`firth_nested` fit (see WU347684 / WU347680: 5–7 h, 34 cores pegged, log frozen |
| 10 | +at the "model formula" line) there is **zero signal** that anything is |
| 11 | +progressing. The fix is not "add a progress bar" — it is "make the existing one |
| 12 | +visible in batch runs and/or emit coarse progress to the log." |
| 13 | + |
| 14 | +## Evidence / current state |
| 15 | + |
| 16 | +- `R/tidyMS_build_model.R:637` — `model_analyse()` creates |
| 17 | + `pb <- progress::progress_bar$new(total = nrow(nested_proteins))` and passes |
| 18 | + `pb` into `purrr::map(data, model_strategy$model_fun, pb = pb)` (`:639`). |
| 19 | + The map is **sequential** over proteins, so tick-based progress is reliable. |
| 20 | +- Every strategy ticks it: |
| 21 | + - `StrategyLM$model_fun` — `R/tidyMS_R6_Modelling.R:85-86` |
| 22 | + - `StrategyRLM$model_fun` — `R/tidyMS_R6_Modelling.R:189-190` |
| 23 | + - `StrategyLmer$model_fun` — `R/tidyMS_R6_Modelling.R:294-295` |
| 24 | + - `StrategyLogistf$model_fun` — `R/logistf.R:361-362` |
| 25 | +- A second bar exists in the firth contrast step: |
| 26 | + `contrasts_linfct_firth()` — `R/logistf.R:35,48`. |
| 27 | + |
| 28 | +### Why it is invisible in production |
| 29 | +1. `progress::progress_bar$new()` is called **without `force = TRUE`** and with |
| 30 | + the default `stream = stderr()`. The `progress` package only renders when the |
| 31 | + stream is a terminal (`isatty`). In the docker `Rscript --vanilla` run |
| 32 | + (stderr piped to logs, not a tty) the bar is **silently disabled**. |
| 33 | +2. Even if rendered, it goes to `stderr` via carriage-return repaint. The |
| 34 | + `prolfqua_*.log` the user tails is the **`logger`** stream |
| 35 | + (`prolfquapp/R/R6_DEAnalyse.R:240` `logger::log_info("model formula: ...")`). |
| 36 | + prolfqua itself does **not** depend on `logger`, so the bar and the log are |
| 37 | + two disconnected channels. |
| 38 | +3. For `firth_nested`, `build_model_logistf()` calls `model_analyse()` **twice** |
| 39 | + (`R/logistf.R:199` models2 = multi-peptide proteins; `:213` models1 = |
| 40 | + single-peptide), so there are two independent, unlabelled bars plus the |
| 41 | + contrast bar — and the expensive one (models2, formula augmented with the |
| 42 | + peptide key `~ G_ + Subject_ + <peptide_Id>`) gives no hint of its cost. |
| 43 | + |
| 44 | +## Goal |
| 45 | + |
| 46 | +When a fit runs for minutes/hours in a batch/docker context, the log should show |
| 47 | +that it is alive and roughly how far along it is (count, %, ETA) — without |
| 48 | +requiring an interactive terminal, and without prolfqua taking a hard `logger` |
| 49 | +dependency. |
| 50 | + |
| 51 | +## Proposed approach |
| 52 | + |
| 53 | +- **A. Injectable progress callback.** Give `model_analyse(..., progress = NULL)` |
| 54 | + an optional callback invoked every N proteins (or every X seconds). Default |
| 55 | + keeps current bar behaviour; prolfquapp passes a callback that does |
| 56 | + `logger::log_info()`. Keeps prolfqua `logger`-free and makes progress land in |
| 57 | + the real log. |
| 58 | +- **B. Coarse milestone logging at the prolfquapp call site.** In |
| 59 | + `prolfquapp` (`R6_DEAnalyse.R`, around the facade build at `:240`) log |
| 60 | + `start fitting N proteins`, then completion with elapsed time. Guarantees a |
| 61 | + heartbeat in the watched log even if a single model fit takes a long time |
| 62 | + between ticks. Combine with A for intra-fit granularity. |
| 63 | +- **C. Optional forced terminal progress.** For interactive/diagnostic use, |
| 64 | + support `force = TRUE` (and a sane `format`/`show_after`) on the legacy |
| 65 | + `progress::progress_bar` path. This is useful at a terminal, but it is not the |
| 66 | + production fix: carriage-return repaint on `stderr` can be noisy and still does |
| 67 | + not land in the structured `logger` stream users watch. |
| 68 | + |
| 69 | +### Recommendation |
| 70 | +Implement A+B first: a prolfqua callback/reporter API plus prolfquapp |
| 71 | +`logger::log_info()` heartbeat messages. Keep the current terminal progress bar |
| 72 | +as the default path, and add forced terminal progress only as an opt-in |
| 73 | +diagnostic mode. |
| 74 | + |
| 75 | +## Touch points |
| 76 | + |
| 77 | +- `R/tidyMS_build_model.R:637` — `model_analyse()` bar/reporter (label with |
| 78 | + `model_name`, add `progress` callback param; optionally support forced |
| 79 | + terminal progress on the legacy bar path). |
| 80 | +- `R/logistf.R:35` — `contrasts_linfct_firth()` bar. |
| 81 | +- `R/ContrastFirth.R:97,118` — `ContrastsFirth$get_linfct()` has separate |
| 82 | + model1/model2 linfct loops used by the nested Firth facade; instrument these |
| 83 | + too so the post-fit contrast setup is not silent. |
| 84 | +- `R/logistf.R:199,213` — two `model_analyse()` calls; pass distinct labels |
| 85 | + (e.g. "firth multi-peptide" vs "firth single-peptide") so the two bars are |
| 86 | + distinguishable. |
| 87 | +- `prolfquapp/R/R6_DEAnalyse.R:~240` — add start/elapsed `logger::log_info()` |
| 88 | + around the facade build (milestone heartbeat), and/or supply the progress |
| 89 | + callback from option A. |
| 90 | + |
| 91 | +## Acceptance criteria |
| 92 | + |
| 93 | +- A `firth_nested` (or any) run in docker writes periodic progress to the |
| 94 | + watched log (count/%, and ideally ETA), proving liveness. |
| 95 | +- The two firth `model_analyse` passes are individually identifiable in output. |
| 96 | +- No new hard dependency forced on prolfqua (callback/log progress keeps prolfqua |
| 97 | + `logger`-free; the logging happens in prolfquapp). |
| 98 | +- Interactive behaviour unchanged (bar still renders in a terminal). |
| 99 | + |
| 100 | +## Detailed implementation plan — callback/log progress |
| 101 | + |
| 102 | +### Why callback/log progress |
| 103 | +Confirmed from the WU347684 workunit log: prolfqua `message()` output **does** |
| 104 | +reach the captured docker/slurm log (`completing cases`, `starting aggregation`, |
| 105 | +`Joining ...` all appear), but the `progress::progress_bar` does **not** (non-tty |
| 106 | +suppression). So a callback that emits through `message()` / `logger` lands |
| 107 | +exactly in the log the operator is tailing. This keeps prolfqua free of a hard |
| 108 | +`logger` dependency while making progress visible in batch. |
| 109 | + |
| 110 | +### Design: a duck-typed "reporter" with `$tick()` |
| 111 | +The strategies already call `pb$tick()` (`tidyMS_R6_Modelling.R:86,190,295`, |
| 112 | +`logistf.R:362`). Keep that contract; just pass an object that *also* exposes |
| 113 | +`$tick(len = 1, tokens = list())` (same signature as `progress::progress_bar`), |
| 114 | +so call sites can share the same interface. |
| 115 | + |
| 116 | +Important semantic detail: the current strategy methods tick **before** the |
| 117 | +expensive fit starts. For batch logs, progress should represent completion (or |
| 118 | +explicitly say "starting"). Prefer moving ticks to after each successful/failed |
| 119 | +fit attempt, or emit paired `starting protein i` / `finished protein i` events in |
| 120 | +the reporter. Otherwise a run can report 100% and then spend a long time inside |
| 121 | +the final model fit. |
| 122 | + |
| 123 | +Add an internal constructor: |
| 124 | + |
| 125 | +```r |
| 126 | +# default reporter = current progress_bar; override via option or arg |
| 127 | +.make_progress <- function(total, label = NULL, |
| 128 | + reporter = getOption("prolfqua.progress", NULL)) { |
| 129 | + if (is.null(reporter)) { # legacy path, unchanged |
| 130 | + return(progress::progress_bar$new(total = total)) |
| 131 | + } |
| 132 | + if (is.function(reporter)) { # user callback(i, total, label) |
| 133 | + return(.callback_reporter(total, label, reporter)) # throttled by wall time |
| 134 | + } |
| 135 | + if (identical(reporter, "message")) { # simple batch-visible path |
| 136 | + return(.message_reporter(total, label)) # message() every X s / P % |
| 137 | + } |
| 138 | + stop("unknown prolfqua.progress reporter") |
| 139 | +} |
| 140 | +``` |
| 141 | + |
| 142 | +- `.callback_reporter` / `.message_reporter` track an internal counter + start |
| 143 | + time (`Sys.time()`), and only emit when **>= N seconds elapsed since last emit** |
| 144 | + (e.g. 10 s) or **every P%** (e.g. 2%). This avoids 21k chatty lines. |
| 145 | +- Emit content: `"<label>: protein i/total (P%), elapsed Xm, ETA ~Ym"` where |
| 146 | + `ETA = elapsed/i * (total - i)`. |
| 147 | +- `total == 0` → no-op reporter. |
| 148 | + |
| 149 | +### Wiring |
| 150 | +1. `model_analyse(..., progress = getOption("prolfqua.progress", NULL))` |
| 151 | + (`tidyMS_build_model.R:625-639`): build reporter via `.make_progress(total, |
| 152 | + label = model_name, reporter = progress)` and pass into the existing |
| 153 | + `purrr::map(..., pb = pb)`. Keep the NULL/default path behaviour unchanged. |
| 154 | +2. Thread an optional `label` so callers can name the pass. |
| 155 | +3. Ensure ticks are completion-oriented. For `model_fun()` implementations, wrap |
| 156 | + the fit in a local result and call `pb$tick()` after the `tryCatch()` returns, |
| 157 | + or add separate reporter methods for started/finished if start messages are |
| 158 | + wanted. |
| 159 | +4. `build_model_logistf` (`logistf.R:199,213`): pass distinct labels |
| 160 | + `"firth multi-peptide"` / `"firth single-peptide"` so the two `model_analyse` |
| 161 | + passes are distinguishable in the log. |
| 162 | +5. `contrasts_linfct_firth` (`logistf.R:35`): replace its standalone |
| 163 | + `progress_bar$new` with `.make_progress(..., label = "firth contrasts")`. |
| 164 | +6. `ContrastsFirth$get_linfct()` (`ContrastFirth.R:97,118`): replace the model1 |
| 165 | + and model2 standalone bars with labelled reporters, e.g. `"firth linfct |
| 166 | + single-peptide"` and `"firth linfct multi-peptide"`. |
| 167 | + |
| 168 | +### prolfquapp side (keeps prolfqua logger-free) |
| 169 | +- In `prolfquapp` startup / `CMD_DEA_V2.R` (or `R6_DEAnalyse$build_*`), set once: |
| 170 | + ```r |
| 171 | + options(prolfqua.progress = function(i, total, label) { |
| 172 | + label <- if (is.null(label) || identical(label, "")) "fit" else label |
| 173 | + logger::log_info("{label}: {i}/{total} ({round(100*i/total)}%) ...") |
| 174 | + }) |
| 175 | + ``` |
| 176 | + prolfqua only ever calls a user-supplied function — no `logger` import. |
| 177 | +- Add a start/elapsed heartbeat around the facade build in |
| 178 | + `R6_DEAnalyse.R:~240` (already logs the model formula there) so even a |
| 179 | + zero-tick stall is bracketed by `start fitting N proteins` / `done in Xs`. |
| 180 | + |
| 181 | +### Tests (prolfqua `tests/testthat/`) |
| 182 | +- Callback reporter: collect `(i,total)` into an env; assert ticks are monotonic |
| 183 | + and final `i == total` after a small `build_contrast_analysis(..., "firth")`. |
| 184 | +- `"message"` reporter emits in a non-interactive session: capture via |
| 185 | + `capture.output(type = "message", ...)` / `withCallingHandlers`. |
| 186 | +- Default (`NULL`) path: assert results identical to pre-change (regression). |
| 187 | + |
| 188 | +### Risk / scope |
| 189 | +- `model_analyse` is core to **all** Wald facades — keep the `NULL` default path |
| 190 | + untouched and gate every new behaviour behind a non-NULL reporter/option. |
| 191 | +- Reporter must be concurrency-safe **if** the protein loop is ever parallelised |
| 192 | + (it is currently a sequential `purrr::map`, so fine today — note it). |
| 193 | +- Reporter `$tick()` must accept `len`/`tokens` args for drop-in compatibility |
| 194 | + with `progress_bar`. |
| 195 | + |
| 196 | +### Phasing |
| 197 | +1. `.make_progress` + reporters + unit tests (no call-site change). |
| 198 | +2. Wire into `model_analyse` (default unchanged). |
| 199 | +3. Apply to the firth loops + labels. |
| 200 | +4. prolfquapp option + heartbeat. |
| 201 | +5. Docs: document `prolfqua.progress` option and the `callback(i, total, label)` |
| 202 | + contract. |
| 203 | + |
| 204 | +## Notes / related |
| 205 | + |
| 206 | +- The 34-core / 129-thread usage comes from multithreaded BLAS inside each fit, |
| 207 | + **not** from parallelising the protein loop — the loop is a sequential |
| 208 | + `purrr::map`, which is exactly why per-protein ticks are trustworthy. |
| 209 | +- Related diagnosis: `prolfquapp/TODO` discussion of `firth_nested` being |
| 210 | + pathologically slow on large peptide-level DIA-NN input with a paired design. |
| 211 | + Progress reporting does not fix the cost, but it turns a "frozen, is it |
| 212 | + hung?" experience into an informed "it's protein 4,000/21,000, ETA Xh" |
| 213 | + decision. |
0 commit comments