Test time is not accurate for first test

[ghostsquad]

The first test always shows up as taking more time because of the overhead involved in loading the test file, running any pre-test code, etc.

Repro

Start-Sleep -Seconds 2

Describe "Pester Test Time" {
    It "Is the First Test" {
        $true | Should be $true
    }

    It "Is the second Test" {
        $true | Should be $true
    }
}

Comparison

Describe "Pester Test Time without Sleeping" {
    It "Is the First Test" {
        $true | Should be $true
    }

    It "Is the second Test" {
        $true | Should be $true
    }
}

Results

Describing Pester Test Time
 [+] Is the First Test 2.06s
 [+] Is the second Test 6ms
Describing Pester Test Time without Sleeping
 [+] Is the First Test 63ms
 [+] Is the second Test 5ms

[dlwyatt]

Yep, I know. The old code had more accurate times for each It block, but the total time was way off (because all of that code that runs within Pester, as well as in the Describe / Context blocks of the test script wasn't being tracked.)

At the time, we felt it was better to accurately reflect the total time being spent to run the tests, even though the first It block of each Describe / Context is penalized a bit.

[dlwyatt]

The original issue for this was #47 .

[ghostsquad]

can you keep track of total time, and individual test run times separately?

[dlwyatt]

During execution, easily. Also easy to reflect that in the console output. Would need to see about whether we can put those times into the NUnit XML export in such a way that the total time is still accurate. The output object from -PassThru would also likely need to change, but that's going to happen soon-ish anyway.

[RemcoKapinga]

I noticed this problem as well. The first test within a Context reports very high times, but all the other tests report to high durations as well.

This can be made a whole lot better by adding this line to PesterState.ps1, as the last line in EnterTest:

        $script:MostRecentTimestamp = $script:Stopwatch.Elapsed

This will reset the test time just before executing the test (including setup), but ignores a whole lot of other preparations.

[nohwnd]

This would be nice to solve when we have blocks that encapsulate all user code.

[nohwnd]

This needs a solution proposal that is compatible with NUnit xml format (currently we are on v2.5 of nUnit xml, but I am open to upgrading as long as the resulting xml still works on build servers). Ideally the total run time would be still accurate, most likely we should measure the time spent in Pester code and user code separately, report how long each test took and make the total time the real total time.