diff --git a/Functions/PesterState.Tests.ps1 b/Functions/PesterState.Tests.ps1 index 8e90ee10a..13acac2db 100644 --- a/Functions/PesterState.Tests.ps1 +++ b/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] diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index f2a3dad92..b0076e1c6 100644 --- a/Functions/PesterState.ps1 +++ b/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 } diff --git a/Functions/TestResults.Tests.ps1 b/Functions/TestResults.Tests.ps1 index f5d3c688e..00d91d82e 100644 --- a/Functions/TestResults.Tests.ps1 +++ b/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)) diff --git a/Pester.psm1 b/Pester.psm1 index f4168d469..41e51dfc9 100644 --- a/Pester.psm1 +++ b/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 } } }