perf(ci): Bigger install chunks, a shard resource sampler, and lower-priority checks

.github/workflows/revdep2.yaml

@@ -326,20 +326,25 @@ jobs:
           TMPDIR: ${{ runner.temp }}/tmp
           TMP: ${{ runner.temp }}/tmp
           TEMP: ${{ runner.temp }}/tmp
+          RESOURCE_PHASE_FILE: ${{ runner.temp }}/preflight/phase
         run: |
           mkdir -p "${RUNNER_TEMP}/preflight" "${RUNNER_TEMP}/tmp"
           watch=./.github/workflows/revdep2/watch-resources.sh
+          # Backgrounded and left running, like the shard's. It used to be
+          # killed when this step ended, which left the two artifact uploads
+          # after it unsampled -- and this job's library artifact is gigabytes
+          # (4.1 GB in run 31951756102), so "the runner stopped answering while
+          # packing" was exactly as unanswerable as it was for shard 16.
+          # `preflight.R` moves the label on through RESOURCE_PHASE_FILE.
           "${watch}" once "before the install"
-          "${watch}" watch 30 "installing" &
-          watcher=$!
-          trap 'kill "${watcher}" 2> /dev/null || true' EXIT
+          "${watch}" watch 30 "preflight" &
+          disown || true
           unbuffered=""
           if command -v stdbuf > /dev/null 2>&1; then
             unbuffered="stdbuf -oL -eL"
           fi
           status=0
           ${unbuffered} Rscript ./.github/workflows/revdep2/preflight.R || status=$?
-          kill "${watcher}" 2> /dev/null || true
           "${watch}" once "after the install"
           exit "${status}"
         shell: bash
@@ -653,6 +658,29 @@ jobs:
       # The phases share the job's environment and the work directory; the
       # install leaves the libraries and a note of what it cost behind, and the
       # check picks both up. Nothing is done twice.
+      # The same sampler the preflight runs, for the same reason, and the shard
+      # needed it more.
+      #
+      # Shard 16 of run 31951756102 died with "The hosted runner lost
+      # communication with the server", whose own advice names starvation of
+      # CPU, memory or network as the causes -- and there was not one number
+      # from that job to say which, because a runner that stops answering takes
+      # its `if: always()` steps with it. Only what was already streamed to the
+      # log survives, so the numbers have to be emitted while the work runs.
+      #
+      # Backgrounded once here rather than per step: a process started in one
+      # step outlives it, and Actions reaps it with the job. `RESOURCE_LOG` also
+      # puts the series in the shard artifact, for the jobs that do reach their
+      # upload.
+      - name: Start the resource sampler
+        run: |
+          watch=./.github/workflows/revdep2/watch-resources.sh
+          "${watch}" once "shard ${SHARD} before the install"
+          RESOURCE_LOG="${RUNNER_TEMP}/results/resources.log" \
+            "${watch}" watch 30 "shard ${SHARD}" &
+          disown || true
+        shell: bash
+
       - name: Install packages
         env:
           PHASE: install
@@ -677,6 +705,18 @@ jobs:
       # Named per attempt: a re-run of one shard must not overwrite the results
       # the other shards uploaded in the first attempt; the collector reads
       # every attempt and lets the later one win per package.
+      # Before the upload, so the last sample and the OOM verdict ride in the
+      # artifact. It cannot run when the *runner* died -- hence the sampler
+      # above -- but it is what answers "was it memory?" in every case where the
+      # job merely failed.
+      - name: Report what the shard consumed
+        if: always()
+        run: |
+          ./.github/workflows/revdep2/watch-resources.sh once "shard ${SHARD} after the checks"
+          ./.github/workflows/revdep2/watch-resources.sh oom
+          df -BG / "${RUNNER_TEMP}" 2>/dev/null || true
+        shell: bash
+
       - name: Upload the shard results
         uses: actions/upload-artifact@v6
         if: always()

.github/workflows/revdep2/README.md

@@ -733,6 +733,7 @@ the report is about *results*, a retry is about *coverage*.
 | A restored package's system library is absent | `sysreqs_check_installed()` names it and `sysreqs_fix_installed()` installs it, in both the preflight and every shard |
 | The preflight job itself dies | the shards run anyway and install their own unions, the collector still reports; only the free rebuild and the early diagnosis are lost |
 | A shard hits its deadline | remaining packages `deferred`; finished old-halves still uploaded and baseline-fed |
+| The runner stops answering the service | "The hosted runner lost communication with the server" names CPU, memory and network starvation as its causes, and a dead runner takes its `if: always()` steps with it — so both the preflight and the shards stream a resource sample every 30 s while they work, and the checks run under `nice -n 10` (and `ionice -c3` where it exists) so the agent is never the process that loses |
 | A shard job dies hard | the collector reconciles against the plan: its packages are reported `missing`, naming the shard, and `retry-run` re-checks exactly them |
 | Every shard dies | the report is still written, with every package `missing`; the artifact download is tolerated, not required |
 | The batch is too big for 250 shards | the plan refuses before anything starts, and names the `part` split that fits |
@@ -790,7 +791,7 @@ and that resolution is the part that stops degrading gracefully:
 the run above spent ten minutes in it
 without a single install starting.
 So both the preflight and the shards install in chunks of
-`REVDEP2_INSTALL_CHUNK` packages (100),
+`REVDEP2_INSTALL_CHUNK` packages (400),
 ordered so that every strong dependency inside the set
 is installed before the package that needs it —
 each chunk then resolves against a library where its dependencies already are.
@@ -1403,7 +1404,7 @@ at the next `if`.
 | Oldest reusable prebuilt library | — | `REVDEP2_PREBUILT_MAX_AGE_DAYS` | 14 days |
 | Runs the history walk looks at | — | `REVDEP2_HISTORY_RUNS` | 40 |
 | Shards a package must be needed by before the preflight installs it | — | `REVDEP2_PREFLIGHT_MIN_SHARDS` | 2 (`1` is the whole universe) |
-| Packages per `pak::pkg_install()` call | — | `REVDEP2_INSTALL_CHUNK` | 100 |
+| Packages per `pak::pkg_install()` call | — | `REVDEP2_INSTALL_CHUNK` | 400 |
 | Time limit on one `pak::pkg_install()` call | — | `REVDEP2_INSTALL_TIMEOUT_MINUTES` | 20 |
 | Wall clock past which no further install is started | — | `REVDEP2_INSTALL_DEADLINE_MINUTES` | 210 |
 | Time limit on one load-test batch | — | `REVDEP2_LOAD_TIMEOUT_MINUTES` | 10 |

.github/workflows/revdep2/check-pair.sh

@@ -24,6 +24,25 @@
 
 set -u
 
+# The checks run at a lower priority than everything else on the runner.
+#
+# Two `R CMD check` processes at once, each with children of its own -- a test
+# suite that opens a PSOCK cluster, a vignette that knits -- can take every core
+# the runner has. The runner agent is a process on that machine too, and it has
+# to reach the service regularly or the job dies with
+#
+#   The hosted runner lost communication with the server.
+#
+# which names starvation as one of its causes. `nice` costs nothing when there
+# is headroom: the scheduler only consults priority when there is more work than
+# cores, which is exactly the case worth protecting. `ionice` does the same for
+# the disk, where a check writing its .Rcheck directory competes with the agent
+# writing logs; it is best-effort, since not every image has it.
+low_priority=(nice -n 10)
+if command -v ionice > /dev/null 2>&1 && ionice -c3 true > /dev/null 2>&1; then
+  low_priority+=(ionice -c3)
+fi
+
 tarball=$1
 work=$2
 lib_old=$3
@@ -57,6 +76,7 @@ check_one() {
   # The status is PIPESTATUS[0] because the stamping is downstream of it.
   R_LIBS="${lib}:${lib_shared}" \
     R_PARALLEL_PORT="${port}" \
+    "${low_priority[@]}" \
     timeout --kill-after=60s "${seconds}s" \
     R CMD check --no-manual --as-cran --output="${out}" "${tarball}" 2>&1 |
     stamp > "${out}/driver.log"

.github/workflows/revdep2/load-test.sh

@@ -5,11 +5,21 @@
 # Usage:
 #   load-test.sh <package-list-file> <library> <seconds> <jobs>
 #
-# Reads one package name per line. Prints one line per package:
+# Reads one package name per line. Prints one line per package on stdout:
 #
 #   OK   <package> <seconds>
 #   FAIL <package> <timeout|error> <seconds>
 #
+# and the same verdict on stderr as it happens, with a running count:
+#
+#   [load  123/1173] OK    red                             19s
+#
+# The two streams are separate on purpose. stdout is the caller's data and is
+# captured; stderr is the live log, so a sweep that takes half an hour says
+# what it is doing while it does it instead of only afterwards. The caller
+# still folds the sorted summary into a collapsed group at the end -- that is
+# the one that answers "what was slow", which the arrival order cannot.
+#
 # Always exits 0: which packages failed is the caller's business, not the
 # shell's.
 #
@@ -40,6 +50,16 @@ lib=$2
 seconds=$3
 jobs=$4
 
+total=$(grep -c . "${list}" || true)
+width=${#total}
+
+# The running count, without a lock. Every finished package appends one byte
+# and reads the size back; single-byte appends to an O_APPEND descriptor do not
+# interleave, so the number is exact rather than approximately right. A stale
+# count would be cosmetic either way -- it is a progress indicator, not data.
+progress=$(mktemp)
+trap 'rm -f "${progress}"' EXIT
+
 # One package, one session, one clock. `--vanilla` so nothing in a profile
 # loads anything this is supposed to be testing.
 load_one() {
@@ -48,18 +68,25 @@ load_one() {
     Rscript --vanilla -e \
     ".libPaths(c('${lib}', .libPaths())); loadNamespace('${pkg}')" \
     > /dev/null 2>&1 || status=$?
-  local took=$((EPOCHSECONDS - start))
+  local took=$((EPOCHSECONDS - start)) verdict
   if [ "${status}" -eq 0 ]; then
+    verdict=OK
     echo "OK ${pkg} ${took}"
   # 124 is coreutils' timeout; anything else is R saying something.
   elif [ "${status}" -eq 124 ] || [ "${status}" -eq 137 ]; then
+    verdict=TIMEOUT
     echo "FAIL ${pkg} timeout ${took}"
   else
+    verdict=ERROR
     echo "FAIL ${pkg} error ${took}"
   fi
+  printf '.' >> "${progress}"
+  printf '[load %*d/%d] %-7s %-32s %ss\n' \
+    "${width}" "$(wc -c < "${progress}")" "${total}" \
+    "${verdict}" "${pkg}" "${took}" >&2
 }
 export -f load_one
-export lib seconds
+export lib seconds progress total width
 
 # GNU parallel where it exists, `xargs -P` where it does not -- the runners
 # have both, but a local invocation may not, and the two are interchangeable

.github/workflows/revdep2/preflight.R

@@ -70,12 +70,12 @@ upgrade <- length(restored) > 0
 # This install is the whole job, and the place it has died: handed the whole
 # universe at once, pak resolves every one of those refs before it installs
 # any of them, and the resolution of a few thousand is where a run that is
-# killed rather than failed gets killed. So it goes in dependency order, a
+# killed rather than failed gets killed. So it goes in dependency order, four
 # hundred at a time (see install_chunks() in util.R), which keeps every
-# resolution small and turns a fatal ten minutes of silence into a chunk
-# counter -- the workflow's resource sampler supplies the other half of that
-# picture, a memory curve on the same clock.
-chunk_size <- env_num("REVDEP2_INSTALL_CHUNK", 100)
+# resolution well clear of the size that killed it and turns a fatal ten
+# minutes of silence into a chunk counter -- the workflow's resource sampler
+# supplies the other half of that picture, a memory curve on the same clock.
+chunk_size <- env_num("REVDEP2_INSTALL_CHUNK", 400)
 # Past this, no further chunk is started. The job's own `timeout-minutes` is
 # 300 and cancels everything; this stops earlier and on purpose, so that the
 # packages that did install are still load-tested, packed and published
@@ -131,6 +131,18 @@ if (identical(metadata, "broken")) {
   )
 }
 
+# What the resource sampler calls the samples it is taking. It runs for the
+# whole job, so a label fixed when it started would say `installing` through the
+# load test and the packing as well -- which is what it used to do.
+phase_file <- env_chr("RESOURCE_PHASE_FILE")
+phase <- function(name) {
+  if (nzchar(phase_file)) {
+    writeLines(name, phase_file)
+  }
+  invisible(name)
+}
+
+phase("installing")
 install_started <- Sys.time()
 installed_ok <- install_in_chunks(
   chunks,
@@ -184,12 +196,14 @@ if (!installed_ok) {
 # absent fails to load for a reason that has nothing to do with the package:
 # without this it would be judged stale and rebuilt from source, and fail
 # again the same way.
+phase("surveying system requirements")
 ensure_sysreqs(lib, "Preflight")
 
 # Load every installed dependency, in chunks small enough to stay clear of the
 # DLL limit; a failing chunk is retried one package at a time so a single bad
 # namespace names itself.
 installed <- intersect(install_union, rownames(utils::installed.packages(lib)))
+phase("load-testing")
 inform("Preflight: loading ", length(installed), " packages")
 
 # Bounded, because `loadNamespace()` is not a thing that necessarily returns:
@@ -290,7 +304,10 @@ if (!out_of_time("the load test") && length(roots) > 0) {
   writeLines(roots, list_file)
   run <- run_with_timeout(
     function(script, args) {
-      system2(script, args, stdout = TRUE, stderr = TRUE)
+      # stdout captured, stderr inherited: the script writes its verdicts to
+      # both, and the stderr copy is what reaches the job log as the sweep
+      # runs rather than half an hour later.
+      system2(script, args, stdout = TRUE, stderr = "")
     },
     list(
       script = file.path(script_dir, "load-test.sh"),
@@ -436,6 +453,7 @@ write_json(failures, file.path(out_dir, "depfail.json"))
 
 # ------------------------------------------------------------------ library --
 
+phase("packing the library")
 lib_out <- env_chr("LIB_OUT")
 index_out <- env_chr("LIB_INDEX_OUT")
 packed <- character()

.github/workflows/revdep2/shard.R

@@ -222,7 +222,7 @@ if (do_install) {
   # does it: one pak call for the whole set is one resolution of the whole set,
   # and that is the part that stops degrading gracefully as the set grows. A
   # shard's union is a fraction of the preflight's, but it is the same call.
-  chunk_size <- env_num("REVDEP2_INSTALL_CHUNK", 100)
+  chunk_size <- env_num("REVDEP2_INSTALL_CHUNK", 400)
   chunks <- install_chunks(install, cran_db(), chunk_size)
   inform(
     "Installing ",

.github/workflows/revdep2/util.R

@@ -940,10 +940,20 @@ install_closure <- function(packages, db) {
 # on disk and is skipped on the next attempt, so a chunk that dies costs a
 # chunk; and the log says which one, which a single opaque call never could.
 #
+# The size is a trade, and 100 was too far towards small. A chunk pays one
+# resolution whether or not it installs anything: run 31930350338's preflight
+# logged `80 pkgs + 214 deps: kept 294 [44s]` for a chunk that built nothing at
+# all. At 100, the 4406-package universe is 45 chunks and something like half
+# an hour of resolution before a single build starts -- on the critical path,
+# since every shard waits for the preflight. At 400 it is 12 chunks. A chunk
+# that dies costs four times as much to redo, which is the price; the counter
+# is that the resolution which killed run 31270092803 was a few thousand refs,
+# and 400 is an order of magnitude below that.
+#
 # Ordering is on strong dependencies only. Suggests are in the set because a
 # revdep's *check* needs them, not its installation, and they are what makes
 # the graph cyclic -- ordering on them would order on nothing.
-install_chunks <- function(pkgs, db, size = 100) {
+install_chunks <- function(pkgs, db, size = 400) {
   pkgs <- unique(pkgs)
   if (length(pkgs) == 0) {
     return(list())

.github/workflows/revdep2/watch-resources.sh

@@ -18,6 +18,12 @@
 #
 # Every sample also goes to $RESOURCE_LOG when that is set, so a job that does
 # reach its upload step carries the series in its artifact too.
+#
+# In `watch` mode the label may move: with $RESOURCE_PHASE_FILE set, each sample
+# reads its first line and uses that instead of the fixed argument. The sampler
+# outlives any one phase of the work -- that is the point of it -- so a label
+# fixed when it starts is wrong for everything after. The preflight labelled
+# half an hour of load-testing `installing` because of exactly this.
 
 set -u
 
@@ -37,6 +43,9 @@ emit() {
 sample() {
   local label="${1:-}"
   local mem disk load top
+  if [ -n "${RESOURCE_PHASE_FILE:-}" ] && [ -r "${RESOURCE_PHASE_FILE}" ]; then
+    label=$(head -n 1 "${RESOURCE_PHASE_FILE}" 2> /dev/null) || label="${1:-}"
+  fi
 
   mem=$(awk '
     /^MemTotal:/     { total = $2 }