Watching a Run's Resource Use

Part II · Module 30 · Chapter 30.3 · Watching a Run's Resource Use

Chapter 30.2 has four jobs running. The question that arrives next, usually about twenty minutes in, is whether any of them is actually doing anything — and the obvious way to answer it does not work.

1. The Log Is Not a Progress Signal

A simulation that touches 32 MB of memory in eight blocks, printing one line per block, with its output redirected to a file. Sampled every 0.9 seconds:

$ vvp logs/grow.vvp > logs/buf.log 2>&1 & p=$!
$ for i in 1 2 3 4 5 6 7 8 9 10; do
>   sleep 0.9
>   kill -0 $p 2>/dev/null || { printf '  %-6s %-12s %s   (exited)\n' "${i}s" "$(wc -c < logs/buf.log)" "$(grep -c . logs/buf.log)"; break; }
>   printf '  %-6s %-12s %s\n' "${i}s" "$(wc -c < logs/buf.log)" "$(grep -c . logs/buf.log)"
> done
  t      log bytes    lines
  1s            0     0
  2s            0     0
  3s            0     0
  4s            0     0
  5s            0     0
  6s            0     0
  7s            0     0
  8s          270     11
  9s          270     11   (exited)

Seven seconds of continuous work, and the log was empty. Then all 270 bytes appeared at once, when the process exited and its standard output was flushed.

It is not the redirection to a file that matters, either. Reading the output through a pipe, line by line, gives the same answer:

$ ( vvp logs/grow.vvp 2>&1 | while IFS= read -r l; do printf '%s\n' "$l" >> logs/pipe.log; done ) &
$ for i in 1 2 3; do sleep 1.2; printf '  %-6s pipe log: %s lines\n' "${i}s" "$(grep -c . logs/pipe.log 2>/dev/null)"; done
  1s     pipe log:  lines
  2s     pipe log:  lines
  3s     pipe log:  lines
$ wait; printf '  final: %s lines\n' "$(grep -c . logs/pipe.log)"
  final: 11 lines

The reader was ready the whole time. Nothing was written to read.

2. The Signals That Do Answer the Question

$ ps -o pid,etime,rss,pcpu -p "$pid"
  PID ELAPSED    RSS  %CPU
96394   00:00   2496   0.0

Four fields, and each answers something different.

etime — wall-clock age. Compared against a passing run's known duration, this alone separates "slower than usual" from "stuck".

rss — resident set size in kilobytes: how much physical memory the process currently holds. The growth pattern matters more than the number, and §3 is about why.

pcpu — the fraction of a CPU it is using. This is the single most useful field, and the interpretation is not the obvious one:

pid — included because without it a multi-process output is ambiguous, and because it is what you pass to Chapter 30.4's signals.

Note what ps does not give you: %CPU on most systems is an average since the process started, not an instantaneous rate. A job that spent an hour computing and is now blocked still shows a high %CPU. Two samples a few seconds apart, differenced, are what give you the current rate — which is the same lesson as §1 in a different field.

3. RSS Is Not Monotonic, So One Sample Says Nothing

Sampling the memory-hungry simulation nine times over eight seconds:

  SAMPLE  ELAPSED   RSS (KB)    %CPU
  1       00:01     6608        46.4
  2       00:02     9008        65.7
  3       00:03     9760        73.5
  4       00:04     10000       75.3
  5       00:05     9632        69.4
  6       00:06     10576       69.1
  7       00:07     8704        71.1
  8       00:07     7488        54.7
  9       00:08     10144       72.2

The trend is upward — 6,608 KB to 10,144 KB, about 1.5× — and it goes down four times on the way, once by 16%. Samples 6 to 8 read 10,576 → 8,704 → 7,488, which in isolation is a process releasing memory.

Resident set size is physical memory currently mapped in, and the kernel is free to reclaim pages it judges cold. So a falling RSS can mean the process freed memory, or that the system took it back under pressure, and the two are indistinguishable from ps.

Three consequences for anything that watches memory:

One sample is a number, not a signal. A threshold alarm on a single rss reading will fire on sample 6 and not on sample 8 for the same healthy run.

A pair can mislead. Samples 6 and 8 would report a 29% decrease; samples 1 and 9 report a 54% increase. Both pairs are from the same run.

Watch the maximum, and watch the trend over many samples. A leak looks like a maximum that never comes down across minutes, not like two consecutive rising samples.

4. A Watcher

#!/bin/bash
# watchrun PID [INTERVAL] [COUNT] — sample a running job and report the trend.
set -u
pid=${1:?usage: watchrun PID [INTERVAL] [COUNT]}
iv=${2:-5}
n=${3:-12}

kill -0 "$pid" 2>/dev/null || { echo "watchrun: no such process: $pid" >&2; exit 2; }

printf '%-7s %-10s %-10s %-8s %s\n' SAMPLE ELAPSED 'RSS (KB)' '%CPU' NOTE
max=0; min=0; first=0; last=0; i=0
while [ "$i" -lt "$n" ]; do
  kill -0 "$pid" 2>/dev/null || { printf '(the process exited after %d samples)\n' "$i"; break; }
  set -- $(ps -o etime=,rss=,pcpu= -p "$pid" 2>/dev/null | tr -s ' ' | sed 's/^ //')
  [ $# -lt 3 ] && { printf '(ps returned nothing -- the process exited)\n'; break; }
  i=$((i + 1))
  et=$1; rss=$2; cpu=$3
  [ "$i" = 1 ] && { first=$rss; min=$rss; }
  last=$rss
  [ "$rss" -gt "$max" ] && max=$rss
  [ "$rss" -lt "$min" ] && min=$rss
  note=""
  # a single sample cannot distinguish these; the NOTE is a hint, not a verdict
  case "${cpu%%.*}" in
    (0) note="not on CPU -- blocked on I/O, a licence, or a lock" ;;
    (*) [ "${cpu%%.*}" -ge 80 ] && note="computing" ;;
  esac
  printf '%-7s %-10s %-10s %-8s %s\n' "$i" "$et" "$rss" "$cpu" "$note"
  sleep "$iv"
done

[ "$i" -eq 0 ] && exit 1
printf '\nRSS over %d samples: first %s, min %s, max %s, last %s KB\n' "$i" "$first" "$min" "$max" "$last"
printf 'peak-to-trough spread: %s KB (%s%% of the peak)\n' \
       "$((max - min))" "$(( (max - min) * 100 / (max > 0 ? max : 1) ))"
printf 'NOTE a falling RSS may be the process freeing memory or the kernel reclaiming it;\n'
printf '     ps cannot tell those apart. Judge a leak by a maximum that never comes down.\n'

$ vvp logs/grow.vvp > logs/w.log 2>&1 & watchrun $! 1 9
SAMPLE  ELAPSED    RSS (KB)   %CPU     NOTE
1       00:01      29904      78.9
2       00:02      72384      97.4     computing
3       00:03      111648     100.0    computing
(the process exited after 3 samples)

RSS over 3 samples: first 29904, min 29904, max 111648, last 111648 KB
peak-to-trough spread: 81744 KB (73% of the peak)
NOTE a falling RSS may be the process freeing memory or the kernel reclaiming it;
     ps cannot tell those apart. Judge a leak by a maximum that never comes down.
$ echo $?
0

And the two degenerate cases:

$ ( sleep 2 ) & watchrun $! 1 8 | tail -3
peak-to-trough spread: 0 KB (0% of the peak)
NOTE a falling RSS may be the process freeing memory or the kernel reclaiming it;
     ps cannot tell those apart. Judge a leak by a maximum that never comes down.
$ watchrun 999999; echo "exit=$?"
watchrun: no such process: 999999
exit=2

Five decisions.

Five decisions.

It reports min, max, first and last rather than a single figure, because §3 measured a 37% peak-to-trough spread inside one healthy run.

The NOTE column is a hint and says so. %CPU near zero is consistent with several causes and distinguishes none of them; the note names the candidates rather than picking one.

It checks kill -0 before each sample and handles ps returning nothing. A watcher is by definition racing the thing it watches, and the process can exit between the check and the ps.

The caveat is printed, not left in the documentation. The person reading the output at 2am is not reading the chapter.

It exits 1 if it got no samples at all, so it is usable in a condition.

5. Slow, Stuck, or Swapping

The three cases the registry asks about, and what separates them:

Slow. %CPU high, etime growing, rss stable. The job is computing. Compare etime against a known-good run of the same test — which requires having recorded one, and is why Chapter 27.9's record includes start and finish times.

Stuck. %CPU near zero and rss stable. Something outside the simulation is not answering. In an EDA flow the candidates are a licence server (Chapter 25.4), a filesystem that has stopped responding, or a full disk (Chapter 28.3). The distinguishing move is to look at what the process has open:

# what is this process waiting on?
lsof -p "$pid" 2>/dev/null | tail -20

Swapping. rss large and the system short of memory, with %CPU moderate and wall-clock time far exceeding CPU time. This is the one case where a per-process view is insufficient: the process looks unremarkable and the machine is thrashing. It needs the system-wide figures from §3's callout, and on a shared machine it needs them before you conclude the problem is yours — a colleague's job can make your run slow without your process looking different in any way.

That last point is the shared-machine theme of this module: a per-process measurement cannot tell you that the machine is the problem. Chapter 22.5 has the etiquette; the technical content here is that your own ps output is the same whether the contention is yours or somebody else's.

Practice

1. Run a low-output simulation with output to a file and sample the log size every second. Record when the first byte appears.
2. Do the same through a pipe read line by line, and confirm the answer does not change.
3. Sample a high-output run and find the step size its log grows in.
4. Express the corrected rule about log growth, with its precondition.
5. Explain which direction the error goes if you treat growth as proof of health.
6. Run ps -o pid,etime,rss,pcpu on a live job and interpret each field.
7. Find two samples in your own run that would suggest the memory is falling.
8. Compute the peak-to-trough spread across ten samples of a healthy run.
9. Check your page size and find one script of yours that assumes 4096.
10. Check whether free exists on your machine and on your compute server.
11. Write watchrun and confirm it reports min, max and the spread.
12. Let the process exit mid-sample and confirm the watcher handles it.
13. Find a blocked process and run lsof -p on it to see what it is waiting for.
14. Run the same watcher twice — once on a quiet machine and once while something else is busy — and compare the RSS traces.
15. Work out how you would tell your own job is slow because of somebody else's.

Check Your Understanding

1. How long was the simulation working with its log at zero bytes?
2. Did reading through a pipe change that, and what does that prove?
3. What was the step size of the high-output run's log growth, and why that number?
4. State the corrected rule from 29.5 with its precondition.
5. Which direction does the error go if growth is treated as proof of health?
6. Which ps field is most useful, and what does a value near zero mean?
7. Why is %CPU from a single ps call not a current rate?
8. By how much did RSS fall inside a healthy run, and why can that happen?
9. Why is a threshold alarm on a single rss reading unreliable?
10. How should a leak be judged instead?
11. What is the page size here, and what breaks because of it?
12. What does free do on this platform?
13. Give the signature of each of slow, stuck and swapping.
14. The same binary on the same input gave two unrecognisably different RSS traces. Why, and what does that mean for thresholds?
15. Why can a per-process measurement not tell you the machine is the problem?

6. Remember

• A simulation worked for seven seconds with its log at exactly 0 bytes. Output to a file is block-buffered, and a pipe does not change it.
• This corrects Chapter 29.5: log growth is a progress signal only for a job that produces enough output to keep flushing. The high-output run grew in exact 8,192-byte steps.
• The error goes into silence if growth is read as proof of health.
• ps -o pid,etime,rss,pcpu is the measurement. %CPU near zero with stable rss means blocked, not slow.
• %CPU is an average since start, so differencing two samples is what gives a current rate.
• RSS is non-monotonic — it fell 29% inside a healthy run — so one sample is a number and a pair can mislead. Report min, max and the spread.
• Judge a leak by a maximum that never comes down.
• The same binary on the same input gave 6.6→10.1 MB with four reversals on a busy machine and 29.9→111.6 MB with none on a quiet one. A memory profile belongs to the run and the machine — which is why "it only leaks on the build server" is usually not a leak.
• The page size here is 16,384 bytes, so page-count arithmetic using 4096 is wrong by 4×. And free does not exist.
• Print the caveats in the output, not just in the documentation.
• Slow, stuck and swapping have distinct signatures — and a per-process view cannot tell you the machine itself is the problem.

7. What Is Next

The job is being watched and its state is known. Chapter 30.4 stops it — and measures what each signal costs in evidence, including the kill that destroyed 88 lines of log while leaving a 50 MB waveform intact.