diff --git a/nixos/lib/test-driver/Logger.pm b/nixos/lib/test-driver/Logger.pm index 3fe5ef67c14..080310ea34e 100644 --- a/nixos/lib/test-driver/Logger.pm +++ b/nixos/lib/test-driver/Logger.pm @@ -4,6 +4,7 @@ use strict; use Thread::Queue; use XML::Writer; use Encode qw(decode encode); +use Time::HiRes qw(clock_gettime CLOCK_MONOTONIC); sub new { my ($class) = @_; @@ -46,10 +47,12 @@ sub nest { print STDERR maybePrefix("$msg\n", $attrs); $self->{log}->startTag("nest"); $self->{log}->dataElement("head", $msg, %{$attrs}); + my $now = clock_gettime(CLOCK_MONOTONIC); $self->drainLogQueue(); eval { &$coderef }; my $res = $@; $self->drainLogQueue(); + $self->log(sprintf("(%.2f seconds)", clock_gettime(CLOCK_MONOTONIC) - $now)); $self->{log}->endTag("nest"); die $@ if $@; } diff --git a/nixos/lib/test-driver/Machine.pm b/nixos/lib/test-driver/Machine.pm index af076cf5ab0..c95bc548e04 100644 --- a/nixos/lib/test-driver/Machine.pm +++ b/nixos/lib/test-driver/Machine.pm @@ -10,6 +10,7 @@ use Cwd; use File::Basename; use File::Path qw(make_path); use File::Slurp; +use Time::HiRes qw(clock_gettime CLOCK_MONOTONIC); my $showGraphics = defined $ENV{'DISPLAY'}; @@ -249,12 +250,15 @@ sub connect { $self->start; + my $now = clock_gettime(CLOCK_MONOTONIC); local $SIG{ALRM} = sub { die "timed out waiting for the VM to connect\n"; }; alarm 600; readline $self->{socket} or die "the VM quit before connecting\n"; alarm 0; $self->log("connected to guest root shell"); + # We're interested in tracking how close we are to `alarm`. + $self->log(sprintf("(connecting took %.2f seconds)", clock_gettime(CLOCK_MONOTONIC) - $now)); $self->{connected} = 1; });