For diagnostic purposes, it can often be useful to know when specific build tasks started and how long they took to execute. This information can help you spot anomalies and resolve odd issues.

For example, I worked on one project many years ago where our integration tests were frustratingly unreliable; while they always worked perfectly when being observed, they’d occasionally fail when they ran in the middle of the night. After many weeks of investigation and roughly a thousand different theories, we discovered the database server was becoming unresponsive while doing a backup at 2am every morning. Since the timing of our overnight tests wasn’t important, I changed the timing so the tests wouldn’t be running at the same time as the backup. Problem solved.

Our build scripts - which ran the integration tests - included time-stamps in their output. This was pivotal in spotting this anomaly.

Since that experience, I’ve also found it useful to have the duration of each task showing. In another situation, spotting that out unit test duration had increased from around 2 minutes to just over 6 minutes allowed me to spot and remedy an issue before it started causing real difficulties.

To add these details into our existing script, we’ll start by the modifying the function we supply for formatTaskName to include the timestamp at the end of each banner we display.

formatTaskName {
    param($taskName)

    $width = 70
    $divider = "-" * $width

We’re defining our banner width as 70 so that we can easily change things in the future if we choose; this is more robust than doing all the calculations manually and then having to do them over if we change.

    $now = get-date
    $nowString = $now.ToString("HH:mm:ss").PadLeft($width - $taskName.Length - 5)

We pad $nowString on the left in order to align the time stamp near to the right-hand margin of our banner.

    $script:lastTaskStart = $now
    return "$divider`r`n  $taskName $nowString`r`n$divider`r`n"
} 

The last thing we do before returning the banner string is to store the timestamp in the $script:lastTaskStart variable to preserve the value until the next time we generate a banner.

The banner generated by this function looks pretty good:

-------------------------------------------------------------------------------
  Compile.Assembly                                                   11:21:33
-------------------------------------------------------------------------------

Stashing away the timestamp each time we generate a task header allows us to check on it when we generate the next task header - this is where we get our duration.

Keeping in mind that there’s no prior value when we create our very first task header, we can work out a duration to include as the first line of the banner:

if ($lastTaskStart -ne $null) {
    $duration = Format-Duration($now - $lastTaskStart)
    $duration = $duration.PadLeft($width - 2)
}

The Format-Duration function is a little helper function that formats the TimeSpan in a human readable form:

function Format-Duration($duration) {
    if ($duration.TotalMinutes -ge 60) {
        return "{0}h {1}m" -f $duration.Hours, $duration.Minutes
    }

    if ($duration.TotalSeconds -ge 60) {
        return "{0}m {1}s" -f $duration.Minutes, $duration.Seconds
    }

    return "{0:N3}s" -f $duration.TotalSeconds
}

The formatted durations show an appropriate amount of detail- if something took over an hour to run, we don’t need to report on how many fractions of a second were involved.

The return statement is modified to include the duration as the first line:

return "$duration`r`n$divider`r`n  $taskName $nowString`r`n$divider`r`n"

Lastly, as a bonus, let us make the banner width adapt to the width of the console window. Immediately after the existing initialization of $width, add this:

$hostWidth = (get-host).UI.RawUI.WindowSize.Width
if ($hostWidth -ne $null) {
    $width = $hostWidth - 2
}

When not running inside a console window, say if being run by PowerShell, $hostWidth will end up as $null and we’ll fall back to the standard width of 70.

Our final banner looks like this:

                                                                       4.105s
-------------------------------------------------------------------------------
  Requires.dotNet                                                    11:21:37
-------------------------------------------------------------------------------

Note that it’s the previous task that took just over 4s to execute - you might want to add some labels into the banner to make this more explicit:

                                                              Elapsed: 4.105s
-------------------------------------------------------------------------------
  Requires.dotNet                                           Started: 11:21:37
-------------------------------------------------------------------------------
Prior post in this series:
The day my build broke
Next post in this series:
Test Coverage History

Comments

blog comments powered by Disqus