From 1fe0018df81a423a3b85faa09b2f8fdabfe143c3 Mon Sep 17 00:00:00 2001
From: Samuel Dionne-Riel <samuel@dionne-riel.com>
Date: Tue, 8 Jan 2019 21:18:27 -0500
Subject: [PATCH 1/2] test-driver: Adds time it took to connect to guest in
 logs

This will make it possible to track whether the time is generous or not
when ran on hydra.
---
 nixos/lib/test-driver/Machine.pm | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/nixos/lib/test-driver/Machine.pm b/nixos/lib/test-driver/Machine.pm
index a00fe25c2b8..8b1f00020cb 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 300;
         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;
 
     });

From 5d93e2c01cc422d386cb00a011e11757edbd1500 Mon Sep 17 00:00:00 2001
From: Samuel Dionne-Riel <samuel@dionne-riel.com>
Date: Tue, 8 Jan 2019 21:27:20 -0500
Subject: [PATCH 2/2] test-driver: Logs time taken for nests

---
 nixos/lib/test-driver/Logger.pm | 3 +++
 1 file changed, 3 insertions(+)

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 $@;
 }