WIP: Fixes #287 test time not accurate

Functions/PesterState.Tests.ps1

@@ -72,6 +72,143 @@ InModuleScope Pester {
         context "adding test result" {
             $p.EnterTestGroup('Describe', 'Describe')
 
+            #region TIMING TESTS ###########
+            #
+            # Timing is collected and reported in Pester at the following levels:
+            #   1. Test - Time between the start and finish of a test
+            #   2. TestGroup - Time between the start and finish of a test group (i.e. Describe block or Script block)
+            #   3. TestSuite - Time between the start and finish of all test groups
+            #
+            #################################
+            it "times test accurately within 10 milliseconds" {
+
+                # Simulating the start of a test
+                $p.EnterTest()
+
+                # Simulating a test action
+                $Time = Measure-Command -Expression {
+                    Start-Sleep -Milliseconds 100
+                }
+
+                # Simulating leaving a test
+                $p.LeaveTest()
+
+                <#
+                     Invoking the add test result with the typical value of $null for ticks which should mean that
+                        the time of the test is automatically recorded as the time between the start of the test
+                        and the finish of the test which should also match the time we recorded using the
+                        Measure-Command
+                #>
+                $p.AddTestResult("result", "Passed", $null)
+
+                # Getting the last test result which was added by the AddTestResult method
+                $result = $p.TestResult[-1]
+
+                # The time recorded as taken during the test should be within + or - 10 milliseconds of the time we
+                #   recorded using Measure-Command
+                $result.time.TotalMilliseconds | Should -BeGreaterOrEqual ($Time.Milliseconds - 10)
+                $result.time.TotalMilliseconds | Should -BeLessOrEqual ($Time.Milliseconds + 10)
+            }
+
+            it "times test groups accurately within 15 milliseconds" {
+
+                # Simulating and collecting the time a single 'Describe' test group and single test
+                $Time = Measure-Command -Expression {
+
+                    # Simulating first Describe group
+                    $p.EnterTestGroup('My Describe 2', 'Describe')
+
+                    # Sleeping to simulate setup time, like a beforeAll block
+                    Start-Sleep -Milliseconds 100
+
+                    # Simulating the start of a test
+                    $p.EnterTest()
+
+                    # Sleeping to simulate test time
+                    Start-Sleep -Milliseconds 100
+
+                    # Simulating the end of a test
+                    $p.LeaveTest()
+
+                    <#
+                     Invoking the add test result with the typical value of $null for ticks which should mean that
+                        the time of the test is automatically recorded as the time between the start of the test
+                        and the finish of the test which should also match the time we recorded using the
+                        Measure-Command
+                    #>
+                    $p.AddTestResult("result", "Passed", $null)
+
+                    # Sleeping to simulate teardown time
+                    Start-Sleep -Milliseconds 100
+
+                    # Simulating the finish of our 'Describe' test group
+                    $p.LeaveTestGroup('My Describe 2', 'Describe')
+                }
+
+                # Getting the last test group result
+                $result = $p.TestGroupStack.peek().Actions.ToArray()[-1]
+
+                # The time recorded as taken during the test should be within + or - 15 milliseconds of the time we
+                #   recorded using Measure-Command
+                $result.time.TotalMilliseconds | Should -BeGreaterOrEqual ($Time.Milliseconds - 15)
+                $result.time.TotalMilliseconds | Should -BeLessOrEqual ($Time.Milliseconds + 15)
+            }
+
+            it "accurately increments total testsuite time within 10 milliseconds" {
+                # Initial time for the current testsuite
+                $TotalTimeStart = $p.time;
+
+                # Simulating entering a new script level test group
+                $p.EnterTestGroup('My Test Group', 'Script')
+
+                # Simulating and collecting the time a single 'Describe' test group and single test
+                $Time = Measure-Command -Expression {
+
+                    # Simulating first Describe group
+                    $p.EnterTestGroup('My Describe 1', 'Describe')
+
+                    # Sleeping to simulate setup time, like a beforeAll block
+                    Start-Sleep -Milliseconds 100
+
+                    # Simulating the start of a test
+                    $p.EnterTest()
+
+                    # Sleeping to simulate test time
+                    Start-Sleep -Milliseconds 100
+
+                    # Simulating the end of a test
+                    $p.LeaveTest()
+
+                    <#
+                     Invoking the add test result with the typical value of $null for ticks which should mean that
+                        the time of the test is automatically recorded as the time between the start of the test
+                        and the finish of the test which should also match the time we recorded using the
+                        Measure-Command
+                    #>
+                    $p.AddTestResult("result", "Passed", $null)
+
+                    # Sleeping to simulate teardown time
+                    Start-Sleep -Milliseconds 100
+
+                    # Simulating the finish of our 'Describe' test group
+                    $p.LeaveTestGroup('My Describe 1', 'Describe')
+                }
+
+                # Simulating the end of a 'Script' test group
+                $p.LeaveTestGroup('My Test Group', 'Script')
+
+                # Getting the total time passed between the start of the testgroup and the finish
+                #   according to our pesterstate
+                $TimeRecorded = $p.time - $TotalTimeStart
+
+                # The time recorded as taken during the test group should be within + or - 10 milliseconds of the time we
+                #   recorded using Measure-Command
+                $TimeRecorded.Milliseconds | Should -BeGreaterOrEqual ($Time.Milliseconds - 10)
+                $TimeRecorded.Milliseconds | Should -BeLessOrEqual ($Time.Milliseconds + 10)
+            }
+
+            #endregion TIMING TESTS
+
             it "adds passed test" {
                 $p.AddTestResult("result", "Passed", 100)
                 $result = $p.TestResult[-1]

Functions/PesterState.ps1

@@ -45,7 +45,8 @@ function New-PesterState {
 
         $script:SessionState = $_sessionState
         $script:Stopwatch = [System.Diagnostics.Stopwatch]::StartNew()
-        $script:MostRecentTimestamp = 0
+        $script:TestStartTime = $null
+        $script:TestStopTime = $null
         $script:CommandCoverage = @()
         $script:Strict = $Strict
         $script:Show = $Show
@@ -83,6 +84,7 @@ function New-PesterState {
                 BeforeAll         = & $SafeCommands['New-Object'] System.Collections.Generic.List[scriptblock]
                 AfterAll          = & $SafeCommands['New-Object'] System.Collections.Generic.List[scriptblock]
                 TotalCount        = 0
+                StartTime         = $Null
                 Time              = [timespan]0
                 PassedCount       = 0
                 FailedCount       = 0
@@ -98,13 +100,25 @@ function New-PesterState {
 
         function EnterTestGroup([string] $Name, [string] $Hint) {
             $newGroup = New-TestGroup @PSBoundParameters
+            $newGroup.StartTime = $script:Stopwatch.Elapsed
             $null = $script:TestGroupStack.Peek().Actions.Add($newGroup)
+
             $script:TestGroupStack.Push($newGroup)
         }
 
         function LeaveTestGroup([string] $Name, [string] $Hint) {
+            $StopTime = $script:Stopwatch.Elapsed
             $currentGroup = $script:TestGroupStack.Pop()
 
+            if ( $Hint -eq 'Script' ) {
+                $script:Time += $StopTime - $currentGroup.StartTime
+            }
+
+            $currentGroup.Time = $StopTime - $currentGroup.StartTime
+
+            # Removing start time property from output to prevent clutter
+            $currentGroup.PSObject.properties.remove('StartTime')
+
             if ($currentGroup.Name -ne $Name -or $currentGroup.Hint -ne $Hint) {
                 throw "TestGroups stack corrupted:  Expected name/hint of '$Name','$Hint'.  Found '$($currentGroup.Name)', '$($currentGroup.Hint)'."
             }
@@ -133,11 +147,15 @@ function New-PesterState {
                 return $errorRecord
             }
 
-            $previousTime = $script:MostRecentTimestamp
-            $script:MostRecentTimestamp = $script:Stopwatch.Elapsed
-
             if ($null -eq $Time) {
-                $Time = $script:MostRecentTimestamp - $previousTime
+                if ( $script:TestStartTime -and $script:TestStopTime ) {
+                    $Time = $script:TestStopTime - $script:TestStartTime
+                    $script:TestStartTime = $null
+                    $script:TestStopTime = [timespan]0
+                }
+                else {
+                    $Time = [timespan]0
+                }
             }
 
             if (-not $script:Strict) {
@@ -154,7 +172,6 @@ function New-PesterState {
             }
 
             $script:TotalCount++
-            $script:Time += $Time
 
             switch ($Result) {
                 Passed {
@@ -298,10 +315,12 @@ function New-PesterState {
                 throw 'You are already in a test case.'
             }
 
+            $script:TestStartTime = $script:Stopwatch.Elapsed
             $script:InTest = $true
         }
 
         function LeaveTest {
+            $script:TestStopTime = $script:Stopwatch.Elapsed
             $script:InTest = $false
         }
 

Functions/TestResults.Tests.ps1

@@ -60,10 +60,18 @@ InModuleScope Pester {
             #create state
             $TestResults = New-PesterState -Path TestDrive:\
             $testResults.EnterTestGroup('Mocked Describe', 'Describe')
-            $TestResults.AddTestResult("Successful testcase", 'Passed', [timespan]10000000) #1.0 seconds
-            $TestResults.AddTestResult("Successful testcase", 'Passed', [timespan]11000000) #1.1 seconds
+            $TestResults.EnterTest()
+            Start-Sleep -Milliseconds 100
+            $TestResults.LeaveTest()
+            $TestResults.AddTestResult("Successful testcase", 'Passed', $null)
+            $TestResults.EnterTest()
+            Start-Sleep -Milliseconds 100
+            $TestResults.LeaveTest()
+            $TestResults.AddTestResult("Successful testcase", 'Passed', $null)
             $testResults.LeaveTestGroup('Mocked Describe', 'Describe')
 
+            $TestGroup = $testResults.TestGroupStack.peek().Actions.ToArray()[-1]
+
             Set-PesterStatistics -Node $TestResults.TestActions
 
             #export and validate the file
@@ -77,18 +85,26 @@ InModuleScope Pester {
             $xmlTestResult.description     | Should -Be "Mocked Describe"
             $xmlTestResult.result          | Should -Be "Success"
             $xmlTestResult.success         | Should -Be "True"
-            $xmlTestResult.time            | Should -Be 2.1
+            $xmlTestResult.time            | Should -Be ([math]::Round($TestGroup.time.TotalSeconds,4))
         }
 
         it "should write two test-suite elements for two describes" {
             #create state
             $TestResults = New-PesterState -Path TestDrive:\
-            $testResults.EnterTestGroup('Describe #1', 'Describe')
-            $TestResults.AddTestResult("Successful testcase", 'Passed', (New-TimeSpan -Seconds 1))
+            $TestResults.EnterTestGroup('Describe #1', 'Describe')
+            $TestResults.EnterTest()
+            Start-Sleep -Milliseconds 200
+            $TestResults.LeaveTest()
+            $TestResults.AddTestResult("Successful testcase", 'Passed', $null)
             $TestResults.LeaveTestGroup('Describe #1', 'Describe')
+            $Describe1 = $testResults.TestGroupStack.peek().Actions.ToArray()[-1]
             $testResults.EnterTestGroup('Describe #2', 'Describe')
-            $TestResults.AddTestResult("Failed testcase", 'Failed', (New-TimeSpan -Seconds 2))
+            $TestResults.EnterTest()
+            Start-Sleep -Milliseconds 200
+            $TestResults.LeaveTest()
+            $TestResults.AddTestResult("Failed testcase", 'Failed', $null)
             $TestResults.LeaveTestGroup('Describe #2', 'Describe')
+            $Describe2 = $testResults.TestGroupStack.peek().Actions.ToArray()[-1]
 
             Set-PesterStatistics -Node $TestResults.TestActions
 
@@ -102,14 +118,14 @@ InModuleScope Pester {
             $xmlTestSuite1.description | Should -Be "Describe #1"
             $xmlTestSuite1.result      | Should -Be "Success"
             $xmlTestSuite1.success     | Should -Be "True"
-            $xmlTestSuite1.time        | Should -Be 1.0
+            $xmlTestSuite1.time        | Should -Be ([math]::Round($Describe1.time.TotalSeconds,4))
 
             $xmlTestSuite2 = $xmlResult.'test-results'.'test-suite'.results.'test-suite'[1]
             $xmlTestSuite2.name        | Should -Be "Describe #2"
             $xmlTestSuite2.description | Should -Be "Describe #2"
             $xmlTestSuite2.result      | Should -Be "Failure"
             $xmlTestSuite2.success     | Should -Be "False"
-            $xmlTestSuite2.time        | Should -Be 2.0
+            $xmlTestSuite2.time        | Should -Be ([math]::Round($Describe2.time.TotalSeconds,4))
         }
 
         it "should write the environment information" {
@@ -132,7 +148,7 @@ InModuleScope Pester {
             #create state
             $TestResults = New-PesterState -Path TestDrive:\
             $testResults.EnterTestGroup('Describe #1', 'Describe')
-            $TestResults.AddTestResult("Successful testcase", 'Passed', (New-TimeSpan -Seconds 1))
+            $TestResults.AddTestResult("Successful testcase", 'Passed', (New-TimeSpan -mi 1))
             $testResults.LeaveTestGroup('Describe #1', 'Describe')
             $testResults.EnterTestGroup('Describe #2', 'Describe')
             $TestResults.AddTestResult("Failed testcase", 'Failed', (New-TimeSpan -Seconds 2))

Pester.psm1

@@ -1429,12 +1429,11 @@ function Set-PesterStatistics($Node) {
         if ($action.Type -eq 'TestGroup') {
             Set-PesterStatistics -Node $action
 
-            $Node.TotalCount += $action.TotalCount
-            $Node.Time += $action.Time
-            $Node.PassedCount += $action.PassedCount
-            $Node.FailedCount += $action.FailedCount
-            $Node.SkippedCount += $action.SkippedCount
-            $Node.PendingCount += $action.PendingCount
+            $Node.TotalCount        += $action.TotalCount
+            $Node.PassedCount       += $action.PassedCount
+            $Node.FailedCount       += $action.FailedCount
+            $Node.SkippedCount      += $action.SkippedCount
+            $Node.PendingCount      += $action.PendingCount
             $Node.InconclusiveCount += $action.InconclusiveCount
         }
         elseif ($action.Type -eq 'TestCase') {
@@ -1457,8 +1456,6 @@ function Set-PesterStatistics($Node) {
                     $Node.InconclusiveCount++; break;
                 }
             }
-
-            $Node.Time += $action.Time
         }
     }
 }