Waiting, Polling and Timeouts

Part II · Module 25 · Chapter 25.6 · Waiting, Polling and Timeouts

1. The Problem

After Chapter 25.5, the runner has a map of job ids and a farm full of jobs. It now needs to know when each job has finished. Nothing will tell it. The scheduler does not call the runner back. The runner has to poll: look, wait a little, look again.

A poll loop has to answer three questions every time round:

1. Which jobs have ended? Those stop being waited for.
2. Has any job run too long? A simulation that waits for a signal that never comes — like stall in this module's bench — will run until someone stops it. That someone must be the runner.
3. Has the whole regression run too long? Even if every job has its own limit, the nightly report must exist by morning.

And it has one rule above the three: whatever happens, the loop ends, and every job leaves it with a recorded reason. A wait loop that can hang is a regression that can hang. A wait loop that drops a job is a report with a missing row.

2. The Loop

Here is one pass of a correct loop. The rest of this chapter justifies each box, mostly by measuring what goes wrong without it:

The examples run on the same mock farm as Chapter 25.5 — no real scheduler exists on the machine these examples were run on — extended with three things a waiting loop needs to be tested against: a limit on how many jobs run at once (so some jobs really wait in PEND), a run limit after which the mock farm kills a job itself, and a mock bkill. They are shown in full in Section 9. The jobs themselves run the real simulator.

3. The Registry Loop, Measured

The registry's example for this chapter is the loop most people write first. It has a limit, which is better than the naive runner in Chapter 25.1. Here it is exactly, against four jobs, one of which is stall. The submission steps from Chapter 25.5 are collected in a small helper file so each example can start from jobs already on the farm:

# farmlib.pl -- Chapter 25.5's submission steps as subroutines, so that this
# chapter's examples can start from jobs already on the (mock) farm.
use strict;
use warnings;
use File::Path qw(make_path remove_tree);
use Time::HiRes qw(time);

sub write_script {
    my ($path, @lines) = @_;
    open my $f, ">", $path or die "$path: $!\n";
    print {$f} map { "$_\n" } @lines;
    close $f or die "$path: $!\n";
    chmod 0755, $path;
}

# submit_plan(REGRESSION, RUN, ...) -- each RUN is { id, args, farm_limit? }.
# Adds dir, job (the job id) and submitted (our clock) to each run.
sub submit_plan {
    my ($regr, @plan) = @_;
    system("bin/build") == 0 or die "build failed\n";
    remove_tree("runs");
    for my $r (@plan) {
        $r->{dir} = "runs/$r->{id}";
        make_path($r->{dir});
        write_script("$r->{dir}/cmd.sh", "#!/bin/sh",
            "cd \"\$(dirname \"\$0\")/../..\" || exit 2",
            "exec bin/simv @{ $r->{args} }");
        write_script("$r->{dir}/job.sh", "#!/bin/sh",
            "cd \"\$(dirname \"\$0\")\" || exit 2",
            "./cmd.sh > sim.log 2>&1",
            "echo \"exit=\$?\" > status",
            ": > done");
        my @w   = $r->{farm_limit} ? ("-W", $r->{farm_limit}) : ();
        my $out = `farm/bsub @w -J $regr.$r->{id} -o $r->{dir}/farm.out $r->{dir}/job.sh`;
        ($r->{job}) = $out =~ /^Job <(\d+)> is submitted to queue <\S+>\.$/m
            or die "$r->{id}: not submitted\n";
        $r->{submitted} = time;
    }
    return @plan;
}

# farm_state(JOB_ID, ...) -- { job id => STAT }, columns found by name.
sub farm_state {
    my @rows = `farm/bjobs @_ 2>/dev/null`;
    my @col  = split ' ', (shift(@rows) // "");
    my %at   = map { $col[$_] => $_ } 0 .. $#col;
    return map { my @f = split ' '; ($f[ $at{JOBID} ] => $f[ $at{STAT} ]) } @rows;
}

1;

#!/usr/bin/perl
# die_loop.pl -- the registry's wait loop, as written, with one job that hangs.
use strict;
use warnings;
require "./farmlib.pl";

my @runs = submit_plan("r1",
    { id => "smoke_s1",  args => ["+test=smoke",  "+seed=1"] },
    { id => "corner_s1", args => ["+test=corner", "+seed=1"] },
    { id => "rand_s2",   args => ["+test=rand",   "+seed=2"] },
    { id => "stall_s1",  args => ["+test=stall",  "+seed=1"] });
my %job     = map { $_->{job} => $_->{dir} } @runs;
my %pending = map { $_ => 1 } keys %job;
my ($start, $MAX, $POLL) = (time, 3, 1);

eval {                                       # (only so we can look afterwards)
    while (keys %pending) {
        die "regression timeout\n" if time - $start > $MAX;
        sleep $POLL;
        delete $pending{$_} for grep { -e "$job{$_}/done" } keys %pending;
    }
};
print "the loop ended with: $@";
my @finished = grep { -e "$_->{dir}/done" } @runs;
print "runs that had finished: ", scalar @finished, " of ", scalar @runs,
      "; runs reported: 0 (the runner died before its report)\n";
my %st = farm_state(map { $_->{job} } @runs);
print "still on the farm: ", join(", ", map { "$_->{id} ($st{$_->{job}})" }
                                       grep { $st{$_->{job}} =~ /RUN|PEND/ } @runs), "\n";
system("farm/bkill $_->{job} > /dev/null") for grep { $st{$_->{job}} =~ /RUN|PEND/ } @runs;

the loop ended with: regression timeout
runs that had finished: 3 of 4; runs reported: 0 (the runner died before its report)
still on the farm: stall_s1 (RUN)

The limit worked: the loop stopped after about three seconds. But look at what stopping meant:

• Three of the four runs had finished, and none of them were reported. die ends the runner. The report — the only thing anyone wanted from the regression — was never written. One hung test cost the results of every test.
• The hung job was still running on the farm. Nothing killed it. The runner is gone, so nothing ever will, until it reaches whatever limit the farm imposes, holding a slot (and on a real farm, a licence) the whole time. Chapter 25.1 measured the same thing locally: stopping the runner does not stop what it started.

A limit must end the waiting, not the runner. When time runs out, the loop should kill whatever is still running, record a reason for each of those jobs, and fall through to the report like a normal exit. The timed-out jobs then appear as rows saying TIMEOUT — which is exactly the information the morning reader needs.

4. The Whole-Second Clock

The registry loop also uses time, and that has a subtler problem. Perl's built-in time returns whole seconds. A difference of two whole-second readings is not a duration. Here is a 2-second limit timed with time, started at three different moments within a second, compared with Time::HiRes::time, which returns fractions:

#!/usr/bin/perl
# int_clock.pl -- a 2-second limit timed with whole-second time(), started at
# three different points within a second, against a fractional clock.
use strict;
use warnings;
use Time::HiRes ();

my $LIMIT = 2;
sub wait_until_fraction {                   # start at N.frac seconds
    my ($frac) = @_;
    Time::HiRes::sleep(0.001) until abs((Time::HiRes::time() - int Time::HiRes::time()) - $frac) < 0.005;
}
for my $frac (0.2, 0.5, 0.8) {
    wait_until_fraction($frac);
    my $t0    = Time::HiRes::time();
    my $start = time;                       # CORE time: whole seconds
    Time::HiRes::sleep(0.01) until time - $start >= $LIMIT;
    my $real  = Time::HiRes::time() - $t0;
    printf "started %.1f s into a second: time() said %d s had passed after %.1f real seconds\n",
           $frac, $LIMIT, int($real * 10) / 10;
}
my $t0 = Time::HiRes::time();
Time::HiRes::sleep(0.01) until Time::HiRes::time() - $t0 >= $LIMIT;
printf "with Time::HiRes::time(): the limit fired after %.1f real seconds\n",
       int((Time::HiRes::time() - $t0) * 10) / 10;

started 0.2 s into a second: time() said 2 s had passed after 1.8 real seconds
started 0.5 s into a second: time() said 2 s had passed after 1.5 real seconds
started 0.8 s into a second: time() said 2 s had passed after 1.2 real seconds
with Time::HiRes::time(): the limit fired after 2.0 real seconds

The same 2-second limit fired after 1.8, 1.5 and 1.2 real seconds, depending only on where in the second the clock was started. The reason is in the arithmetic: if the loop starts at 10.8 seconds, time says 10. At 12.0 seconds time says 12, the difference is 2, and the limit fires — after 1.2 real seconds. With > instead of >=, the error goes the other way: the limit fires up to a second late. Either way the limit is wrong by up to one whole second, plus the poll interval.

For a 10-hour nightly limit, a second does not matter. For per-job limits on short tests, it does, and the error is invisible: the limit says 2, the code says 2, and some runs are killed early. This is not hypothetical. The first version of Chapter 25.1's mini_run.pl had exactly this bug: its "2 s" timeout fired, and its whole run of seven simulations took 1.85 seconds. It was found only because the total was measured. The fix is one line:

use Time::HiRes qw(time sleep);   # time() now returns fractions; sleep() takes them

That import replaces the built-in time and sleep in that file. Do it in every script that measures a duration.

5. Is It Still Running?

A runner that launches local jobs (as in Chapter 25.1, without a farm) needs to know whether each child is still running. The obvious test is kill 0, $pid, which sends no signal but reports whether the process exists. It gives the wrong answer for a child that has finished:

#!/usr/bin/perl
# zombie.pl -- is a finished child still "alive"? Two ways of asking.
use strict;
use warnings;
use POSIX qw(WNOHANG);

system("bin/build") == 0 or die "build failed\n";

my $pid = fork // die "fork: $!\n";
if ($pid == 0) {                             # a run that finishes at once
    open STDOUT, ">", "/dev/null";
    exec "bin/simv", "+test=smoke";
    exit 127;
}
sleep 1;                                     # it has certainly finished by now
print "kill 0 => ", (kill(0, $pid) ? "alive" : "gone"), "   (child exited a second ago)\n";
my $r = waitpid($pid, WNOHANG);
print "waitpid(WNOHANG) => ", ($r == $pid ? "it had finished; status reaped" : "still running"), "\n";
print "kill 0 => ", (kill(0, $pid) ? "alive" : "gone"), "   (after waitpid)\n";

kill 0 => alive   (child exited a second ago)
waitpid(WNOHANG) => it had finished; status reaped
kill 0 => gone   (after waitpid)

The child finished almost immediately, but a second later kill 0 still said alive. A process that has exited remains in the process table — as a "zombie" — until its parent collects its exit status with wait or waitpid. Until then it exists, so kill 0 succeeds. A loop that tests liveness with kill 0 and never reaps would see every finished child as running until its deadline, and then "time out" jobs that ended long ago.

The right question for your own children is waitpid($pid, WNOHANG). It returns at once: the child's pid if it has ended (and $? now holds its status — copy it), or 0 if it is still running. It answers "has it ended?" and collects the status in the same call, which is what the loop needs. (kill 0 is still useful for processes that are not your children, where you cannot waitpid — but then you also cannot get their status, which is why farm jobs report through files.)

6. Start Each Job's Clock When It Starts

A per-job limit says "a single simulation of this test should never take longer than N". The question is: N from when?

From submission is the easy answer — the runner already knows that time — and on a busy farm it is wrong. A job can sit in PEND for an hour because the farm is full. If its clock started at submission, a healthy 2-minute test that waited an hour would be killed as a "timeout" the moment it began. Worse, the report would say TIMEOUT for a test that has nothing wrong with it, and someone would go and debug it.

The waiter in Section 9 starts each job's clock the first time the farm reports it is no longer pending, measured with the runner's own clock. Section 9's output shows the difference on the mock farm with one slot: smoke_s2 ran for a fraction of a second, but it ended more than 2 seconds after it was submitted, because it waited behind stall. A limit counted from submission would have killed it.

Two details:

• Use your own clock for durations. The farm machine's clock and the runner machine's clock are different clocks. A file timestamp written on the execution host and compared with time on the runner's host mixes the two. The waiter records when it first saw the job running, and measures from there with Time::HiRes::time. The error is at most one poll interval, and it is in the safe direction — the job gets slightly more time, never less.
• The regression limit still counts from the start of the regression. That limit exists for the morning report, and the morning does not care why jobs waited.

7. Ask the Farm Too

The registry loop waits for each job's done file and nothing else. The done file is the right signal for "this job reached the end of its script". But some jobs never reach the end of their script:

• the farm kills the job for exceeding its own run limit or memory limit;
• the execution machine crashes;
• someone runs bkill by hand.

None of those jobs will ever write done. A loop that waits only for done keeps waiting for them until the job limit or the regression limit — hours, possibly — and then reports them as timeouts, which is not what happened.

So the waiter also asks the farm, once per poll, for the state of every pending job, in one query (the waiter passes all pending job ids to one bjobs call; a loop that runs one query per job sends a thousand queries per poll to the scheduler). If the farm says a job has ended (DONE or EXIT) but there is no done file, the waiter records "ended without done file" and stops waiting for it. Chapter 25.7 then decides what that means for the verdict.

The waiter waits one extra poll before recording that. On a single machine the done file is visible the instant it is written. On farms, the run directory usually lives on a network file system, and a file written on one machine can take a moment to become visible on another. One poll of grace avoids misreporting a job that finished normally a fraction of a second before the check.

8. Kill It, and Keep Your Own Record

When a job is over its limit, the waiter must end it, and it must do two things in the right order: kill it, and record that it was killed by the waiter. The order of the evidence matters, because the job's own evidence may not say so:

#!/usr/bin/perl
# farm_says.pl -- kill a hung simulation through the farm and ask the farm
# what happened to it.
use strict;
use warnings;
require "./farmlib.pl";

system("bin/build") == 0 or die "build failed\n";
my $out = `farm/bsub -J r1.stall_direct -o /dev/null bin/simv +test=stall`;
my ($jid) = $out =~ /^Job <(\d+)>/m or die;
sleep 1;
my %st = farm_state($jid);
print "before: job $jid is $st{$jid}\n";
system("farm/bkill $jid > /dev/null");
%st = farm_state($jid);
print "after bkill: the farm records job $jid as $st{$jid}\n";

before: job 4101 is RUN
after bkill: the farm records job 4101 as DONE

The farm recorded the killed job as DONE. The mock bkill sends TERM first, and Icarus vvp catches TERM and exits with status 0 — Chapter 26.7 measured that on the real simulator. A process that exits 0 is a successful job, as far as any scheduler can tell. (In this chapter's waiter the jobs run through job.sh, whose shell does die from TERM, so the farm records EXIT instead. The point stands: whether the farm's record says "killed" depends on details of the job script that the runner should not rely on.)

So the waiter writes the reason itself, at the moment it decides to kill: TIMEOUT: ran over 2s. That record is authoritative because the waiter is the one that did it. This is the same rule as in Chapter 25.1, where the local runner kept a timed_out flag because the simulator's exit status would never say "timeout" — and the same rule as Chapter 21.8, which puts TIMEOUT first in the verdict order for exactly this reason.

Killing must also be complete. On the mock farm, bkill signals the job's whole process group, and then sends KILL to anything that ignored TERM. Locally, the same idea applies: start each run in its own process group (setpgrp in the child) and signal the group, kill "TERM", -$pgid, so that a wrapper script's children do not survive their parent — Chapter 25.1 measured the shell and vvp surviving when only the runner was killed.

9. The Waiter

Here are the mock farm pieces used in this chapter, followed by the waiter. The mock bsub is Chapter 25.5's with three additions, each marked in its header: a slot limit, a run limit, and a process group per job.

#!/usr/bin/perl
# farm/bsub -- a MOCK of LSF's bsub, for this module's examples only.
# Chapter 25.5's mock plus three additions: MOCK_SLOTS limits how many jobs
# run at once (the rest wait in PEND, as on a busy farm); -W SECONDS is a run
# limit after which the mock farm kills the job itself; and each job runs in
# its own process group, saved so that the mock bkill can stop it.
# It prints the documented line  Job <ID> is submitted to queue <QUEUE>.
# It is NOT LSF.
use strict;
use warnings;
use FindBin qw($Bin);
use POSIX qw(setsid WNOHANG);
use Fcntl qw(:flock);
use Time::HiRes qw(time);

my %QUEUES = map { $_ => 1 } qw(normal long);
my ($queue, $name, $out, $limit) = ("normal", "", "/dev/null", 0);
while (@ARGV && $ARGV[0] =~ /^-/) {
    my $o = shift;
    if    ($o eq "-q") { $queue = shift }
    elsif ($o eq "-J") { $name  = shift }
    elsif ($o eq "-o") { $out   = shift }
    elsif ($o eq "-W") { $limit = shift }
    else  { print STDERR "mock bsub: unknown option $o\n"; exit 255 }
}
@ARGV or do { print STDERR "mock bsub: no command given\n"; exit 255 };
$QUEUES{$queue} or do {
    print STDERR "mock bsub: queue '$queue' does not exist; job not submitted\n";
    exit 255;
};

my $state = "$Bin/state";
mkdir $state;
open my $lk, "+>>", "$state/next_id" or die "mock bsub: $!\n";
flock $lk, LOCK_EX; seek $lk, 0, 0;
my $id = <$lk> // 4100; chomp $id; $id++;
truncate $lk, 0; print {$lk} "$id\n"; close $lk;

my $cmd = join " ", @ARGV;
write_state($id, "PEND");
open my $meta, ">", "$state/$id.job" or die;
print {$meta} "name=$name\nqueue=$queue\ncmd=$cmd\n";
close $meta;

my $pid = fork // die "mock bsub: fork: $!\n";
if ($pid == 0) {                               # the "execution host"
    setsid();
    open STDIN, "<", "/dev/null";
    open STDOUT, ">", $out or exit 1;
    open STDERR, ">&", \*STDOUT;
    open my $wf, ">", "$state/$id.wpid" or exit 1; print {$wf} "$$\n"; close $wf;
    my $slots = $ENV{MOCK_SLOTS} || 1000;
    while (1) {                                # wait for a free slot
        open my $g, ">>", "$state/slots.lock" or exit 1;
        flock $g, LOCK_EX;
        my ($running, $ahead) = (0, 0);        # first come, first served
        for my $f (glob "$state/*.stat") {
            my ($j) = $f =~ m{/(\d+)\.stat$} or next;
            open my $s, "<", $f or next;
            my $st = <$s> // "";
            $running++ if $st =~ /^RUN/;
            $ahead++   if $st =~ /^PEND/ && $j < $id;
        }
        if ($running < $slots && !$ahead) { write_state($id, "RUN"); close $g; last }
        close $g;
        select(undef, undef, undef, 0.1);
    }
    my $job = fork // exit 1;
    if ($job == 0) {
        setpgrp(0, 0);                         # the job's own process group
        exec "/bin/sh", "-c", $cmd;            # through a shell, as a job script would
        exit 127;
    }
    open my $pf, ">", "$state/$id.pgid" or exit 1; print {$pf} "$job\n"; close $pf;
    my ($t0, $over) = (time, 0);
    while (waitpid($job, WNOHANG) == 0) {
        if ($limit && !$over && time - $t0 > $limit) { $over = 1; kill "KILL", -$job }
        select(undef, undef, undef, 0.05);
    }
    write_state($id, ($? == 0 && !$over) ? "DONE" : "EXIT", $over ? "runlimit" : $? >> 8);
    exit 0;
}
print "Job <$id> is submitted to queue <$queue>.\n";
exit 0;

sub write_state {
    my ($j, $s, $code) = @_;
    open my $f, ">", "$state/$j.stat.tmp" or die;
    print {$f} defined $code ? "$s $code\n" : "$s\n";
    close $f;
    rename "$state/$j.stat.tmp", "$state/$j.stat";
}

#!/usr/bin/perl
# farm/bjobs -- a MOCK of LSF's bjobs: one row per job id, or every job whose
# name matches -J NAME ('*' matches anything). Prints JOBID, STAT and JOB_NAME only (real bjobs
# prints more columns). It is NOT LSF.
use strict;
use warnings;
use FindBin qw($Bin);

my $state = "$Bin/state";
my $want_name;
if (@ARGV >= 2 && $ARGV[0] eq "-J") { shift; $want_name = shift }
my @ids = @ARGV;
if (defined $want_name) {
    @ids = ();
    for my $f (sort glob "$state/*.job") {
        my ($id) = $f =~ m{/(\d+)\.job$};
        my %m = map { /^(\w+)=(.*)$/ } do { open my $h, "<", $f or die; <$h> };
        my $re = join ".*", map { quotemeta } split /\*/, $want_name, -1;
        push @ids, $id if $m{name} =~ /^$re$/;
    }
    @ids or do { print STDERR "mock bjobs: no job matches $want_name\n"; exit 255 };
}
print "JOBID   STAT  JOB_NAME\n";
for my $id (@ids) {
    open my $s, "<", "$state/$id.stat" or do { print STDERR "mock bjobs: no job $id\n"; next };
    my ($stat) = split ' ', scalar <$s>;
    my %m = map { /^(\w+)=(.*)$/ } do { open my $h, "<", "$state/$id.job" or die; <$h> };
    printf "%-7s %-5s %s\n", $id, $stat, $m{name};
}

#!/usr/bin/perl
# farm/bkill -- a MOCK of LSF's bkill. A running job: TERM to its process
# group, then KILL after a grace period. A pending job: removed from the
# queue. Either way the job ends in state EXIT. It is NOT LSF.
use strict;
use warnings;
use FindBin qw($Bin);

my $state = "$Bin/state";
for my $id (@ARGV) {
    if (open my $p, "<", "$state/$id.pgid") {           # running: stop the job
        chomp(my $pg = <$p>);
        kill "TERM", -$pg;
        select(undef, undef, undef, 0.5);
        kill "KILL", -$pg;                               # whatever ignored TERM
    } elsif (open my $w, "<", "$state/$id.wpid") {      # pending: dequeue it
        chomp(my $wp = <$w>);
        kill "KILL", $wp;
        open my $f, ">", "$state/$id.stat" or die;
        print {$f} "EXIT dequeued\n";
        close $f;
    } else {
        print STDERR "mock bkill: no job $id\n";
        next;
    }
    for (1 .. 40) {                                      # until the farm records it
        open my $s, "<", "$state/$id.stat" or last;
        last if <$s> !~ /^(?:RUN|PEND)/;
        select(undef, undef, undef, 0.05);
    }
    print "Job <$id> is being terminated\n";
}

#!/usr/bin/perl
# farm_wait.pl -- wait for submitted jobs with a bounded poll loop: a per-job
# limit counted from when each job STARTED, a limit for the whole regression,
# and a recorded reason for every job that stopped being waited for.
# Usage: perl farm_wait.pl JOB_LIMIT REGRESSION_LIMIT     (seconds)
use strict;
use warnings;
use Time::HiRes qw(time sleep);
require "./farmlib.pl";

my ($JOB_LIMIT, $REGR_LIMIT) = @ARGV == 2 ? @ARGV : (2, 20);
my $POLL = 0.2;
$ENV{MOCK_SLOTS} = 1;                      # a busy farm: one job runs at a time

my @runs = submit_plan("r1",
    { id => "smoke_s1", args => ["+test=smoke", "+seed=1"] },
    { id => "rand_big", args => ["+test=rand", "+seed=5", "+n=100000"], farm_limit => 0.5 },
    { id => "stall_s1", args => ["+test=stall", "+seed=1"] },
    { id => "smoke_s2", args => ["+test=smoke", "+seed=2"] });

my $start   = time;
my %pending = map { $_->{job} => $_ } @runs;

sub stop_waiting {                         # record why, and stop polling this job
    my ($r, $why) = @_;
    $r->{why}   = $why;
    $r->{ended} = time;
    delete $pending{ $r->{job} };
}
sub kill_job {                             # we end it, so WE record it
    my ($r, $why) = @_;
    system("farm/bkill $r->{job} > /dev/null");
    stop_waiting($r, $why);
}

while (%pending) {
    my $now  = time;
    my %stat = farm_state(keys %pending);  # ONE query for every pending job
    for my $jid (sort { $a <=> $b } keys %pending) {
        my $r  = $pending{$jid};
        my $st = $stat{$jid} // "UNKNOWN";
        $r->{started} //= $now if $st ne "PEND";              # our clock, not theirs
        if (-e "$r->{dir}/done") { stop_waiting($r, "finished (done file)"); next }
        if ($st eq "DONE" || $st eq "EXIT") {                 # the farm says it ended
            stop_waiting($r, "ended without done file") if $r->{seen_ended}++;
            next;                                             # (one poll's grace first)
        }
        if (defined $r->{started} && $now - $r->{started} >= $JOB_LIMIT) {
            kill_job($r, "TIMEOUT: ran over ${JOB_LIMIT}s");
        }
    }
    if (%pending && time - $start >= $REGR_LIMIT) {           # stop the whole regression
        for my $r (sort { $a->{job} <=> $b->{job} } values %pending) {
            kill_job($r, defined $r->{started} ? "REGRESSION DEADLINE: was running"
                                               : "REGRESSION DEADLINE: never started");
        }
    }
    sleep $POLL if %pending;
}

printf "job limit %ss, regression limit %ss\n", $JOB_LIMIT, $REGR_LIMIT;
printf "%-9s %-5s %-36s %s\n", "RUN", "JOB", "WAITING ENDED BECAUSE", "SUBMIT-TIME LIMIT WOULD HAVE KILLED IT?";
for my $r (@runs) {
    my $healthy = $r->{why} =~ /^finished/;
    my $unfair  = $healthy && $r->{ended} - $r->{submitted} >= $JOB_LIMIT;
    printf "%-9s %-5s %-36s %s\n", $r->{id}, $r->{job}, $r->{why},
           !$healthy ? "-" : $unfair ? "YES, a healthy run" : "no";
}

The plan has four jobs, chosen so that each way a wait can end happens once: smoke_s1 finishes quickly; rand_big is given a farm run limit of half a second (the mock's -W, in seconds) and is long enough to exceed it, so the farm kills it; stall_s1 hangs; and smoke_s2 is healthy but queued behind the others, because the mock farm runs one job at a time. The demonstration runs the waiter twice, with two sets of limits:

#!/usr/bin/perl
# wait_demo.pl -- the same four jobs waited for twice: first with a per-job
# limit, then with a regression limit shorter than the work.
use strict;
use warnings;

$| = 1;
system($^X, "farm_wait.pl", 2, 20);
print "\n";
system($^X, "farm_wait.pl", 10, 2.5);

job limit 2s, regression limit 20s
RUN       JOB   WAITING ENDED BECAUSE                SUBMIT-TIME LIMIT WOULD HAVE KILLED IT?
smoke_s1  4101  finished (done file)                 no
rand_big  4102  ended without done file              -
stall_s1  4103  TIMEOUT: ran over 2s                 -
smoke_s2  4104  finished (done file)                 YES, a healthy run

job limit 10s, regression limit 2.5s
RUN       JOB   WAITING ENDED BECAUSE                SUBMIT-TIME LIMIT WOULD HAVE KILLED IT?
smoke_s1  4105  finished (done file)                 no
rand_big  4106  ended without done file              -
stall_s1  4107  REGRESSION DEADLINE: was running     -
smoke_s2  4108  REGRESSION DEADLINE: never started   -

First run (job limit 2 s, regression limit 20 s). Every job left the loop for a different, recorded reason:

• smoke_s1 — its done file appeared.
• rand_big — the farm ended it (its run limit) and no done file ever appeared. The waiter noticed on the second look and stopped waiting immediately, instead of holding it until a limit.
• stall_s1 — ran for 2 seconds after it started, so the waiter killed it and recorded TIMEOUT.
• smoke_s2 — finished normally. The last column is the counterfactual from Section 6: it ended more than 2 seconds after submission, because it waited behind stall_s1. A limit counted from submission would have killed a healthy run. Counted from its start, it was never close.

Second run (job limit 10 s, regression limit 2.5 s). Now the regression limit is the one that fires. The waiter killed both remaining jobs and recorded why each one was still there: stall_s1 was running, and smoke_s2 had never started. Those are different facts for the morning reader — one is a test that may be hanging, the other is a test that was never tried — and the report should not merge them into one word.

Both runs ended the loop normally and printed a row for every job. The runner never died, and nothing was left on the farm.

Walk through the loop once more with the code in front of you:

• farm_state(keys %pending) is the single query per poll.
• $r->{started} //= $now if $st ne "PEND" sets the start time once, the first time the job is seen out of PEND. //= assigns only if the value is still undefined.
• The checks are in a deliberate order: done first (the job's own evidence wins if it exists), then the farm's state with one poll of grace, then the job's limit. A job whose done appeared in the same poll in which it crossed its limit is reported as finished, not killed.
• stop_waiting is the only way out of %pending, and it always records a reason and the time. kill_job kills and then calls stop_waiting. There is no other way for a job to leave the loop, so there is no way for a job to leave it silently.
• The regression limit kills and records; it does not die. After the loop, the report runs for every job, whatever happened.

10. Choosing the Numbers

The code is the easy part. The limits need judgement.

Per-job limit. Base it on measured run times, not on hope. A common rule is a small multiple — say two to three times — of the longest normal run time of that test, recorded from previous regressions. Store it per test in the test list (Chapter 25.2's timeout= option exists for this), because a 30-second smoke test and a 6-hour full-chip test cannot share one number. A limit that is too tight produces false timeouts, which teach people to ignore TIMEOUT rows. A limit that is too loose lets one hung test hold a slot for most of the night.

Regression limit. Work backwards from when the report is needed, leaving time for collection and reporting after the limit fires. The regression limit is a backstop, and if it fires often, the per-job limits or the size of the regression are wrong.

Poll interval. The examples here poll every 0.2 seconds because the jobs take a second. On a real farm, each poll is a query to a shared scheduler that serves many users, and jobs take minutes or hours; poll far less often, query all jobs at once, and ask your farm's administrators what load is acceptable. The poll interval is also the resolution of every limit: a job is killed up to one poll interval after its limit.

11. Exercises

1. Make the registry loop safe. Change die_loop.pl so that when $MAX is reached it kills the remaining jobs, records a reason for each, and continues to a report that lists all four runs. Keep the loop's structure; change as few lines as you can.

2. A local waiter. Write the same waiter for local jobs started with fork: each child in its own process group, waitpid($pid, WNOHANG) to detect the end, and kill "TERM", -$pgid then kill "KILL", -$pgid for a timeout. Prove that no simulator process is left running after a timeout (Chapter 25.1's hang_demo.pl shows how to look).

3. The done file and the farm disagree. Change job.sh so that it writes done and then sleeps for 3 seconds before exiting. Run the waiter. Which signal does it act on, and is the result right? Now reverse it: the farm says DONE but the done file is never written. Which reason does the waiter record?

4. Time spent waiting. Extend the report with two columns: how long each job waited in the queue, and how long it ran, both measured with the runner's clock. Print them bucketed ("under 1 s", "1 to 10 s", …) rather than to the millisecond, so the report does not change on every run. Which of the four jobs spent the most time queued?

5. Retry a timeout? Some teams rerun a timed-out job once with double the limit before reporting it. Write down the arguments for and against. When does a retry hide a real bug? (Hint: think about the stall test, and about a design that is only slow for some seeds.)

12. What To Remember

• Poll, and make sure the loop always ends with a recorded reason for every job.
• A limit must end the waiting, not the runner. Measured: die on timeout reported none of the three finished runs and left the hung job running on the farm.
• Use Time::HiRes. Measured: whole-second time fired a 2-second limit after 1.8, 1.5 and 1.2 real seconds.
• For your own children, ask waitpid($pid, WNOHANG), not kill 0. Measured: a child that ended a second earlier was "alive" until it was reaped.
• Count a job's limit from when it started, with your own clock. Measured: a healthy job queued behind a hung one would have been killed by a limit counted from submission.
• Ask the farm as well as the done file, in one query per poll, with one poll of grace before recording "ended without done file".
• Kill completely, and record it yourself. Measured: the farm recorded a killed simulation as DONE, because vvp exits 0 on TERM.
• A regression limit records was running and never started separately.
• Choose limits from measured run times, per test.

Chapter 25.7 takes what the waiter recorded — finished, ended without a done file, timed out, never started — and turns every launched run into a verdict, including the runs that left no log at all.