diff --git a/.github/workflows/revdep2.yaml b/.github/workflows/revdep2.yaml index e481d686307..870d71fa6fe 100644 --- a/.github/workflows/revdep2.yaml +++ b/.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() diff --git a/.github/workflows/revdep2/README.md b/.github/workflows/revdep2/README.md index 47247bc2195..9e7aeeba6b2 100644 --- a/.github/workflows/revdep2/README.md +++ b/.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 | diff --git a/.github/workflows/revdep2/check-pair.sh b/.github/workflows/revdep2/check-pair.sh index 0d8ad06637f..ceb015c3415 100755 --- a/.github/workflows/revdep2/check-pair.sh +++ b/.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" diff --git a/.github/workflows/revdep2/load-test.sh b/.github/workflows/revdep2/load-test.sh index 87392a5ceb3..0a1b63db68d 100755 --- a/.github/workflows/revdep2/load-test.sh +++ b/.github/workflows/revdep2/load-test.sh @@ -5,11 +5,21 @@ # Usage: # load-test.sh # -# 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 # FAIL # +# 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 diff --git a/.github/workflows/revdep2/preflight.R b/.github/workflows/revdep2/preflight.R index f48b8808a69..7be71c6adf5 100644 --- a/.github/workflows/revdep2/preflight.R +++ b/.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() diff --git a/.github/workflows/revdep2/shard.R b/.github/workflows/revdep2/shard.R index d9ce96e8393..95b9cc3848d 100644 --- a/.github/workflows/revdep2/shard.R +++ b/.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 ", diff --git a/.github/workflows/revdep2/util.R b/.github/workflows/revdep2/util.R index ba7b2665017..26de1f659f9 100644 --- a/.github/workflows/revdep2/util.R +++ b/.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()) diff --git a/.github/workflows/revdep2/watch-resources.sh b/.github/workflows/revdep2/watch-resources.sh index 0bdd9a7550a..eae38b0ade0 100755 --- a/.github/workflows/revdep2/watch-resources.sh +++ b/.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 }