From e1341559a9fe2cd3065338566b0d03296302b6f2 Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Wed, 26 Dec 2018 23:00:08 -0500 Subject: [PATCH 01/18] Added new tests for timing at group level and individual test level --- Functions/PesterState.Tests.ps1 | 30 ++++++++++++++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/Functions/PesterState.Tests.ps1 b/Functions/PesterState.Tests.ps1 index 35ce98410..8c2fd7e4e 100644 --- a/Functions/PesterState.Tests.ps1 +++ b/Functions/PesterState.Tests.ps1 @@ -72,6 +72,36 @@ InModuleScope Pester { context "adding test result" { $p.EnterTestGroup('Describe', 'Describe') + it "times test accurately within 10 milliseconds" { + $p.EnterTest() + $Time = Measure-Command -Expression { + Start-Sleep -Milliseconds 100 + } + $p.LeaveTest() + $p.AddTestResult("result","Passed",$null) + $result = $p.TestResult[-1] + [int]($result.time.TotalMilliseconds) | Should -BeGreaterOrEqual ($Time.Milliseconds-10) + [int]($result.time.TotalMilliseconds) | Should -BeLessOrEqual ($Time.Milliseconds+10) + } + + it "times test group accurately within 150 milliseconds" { + $p.EnterTestGroup() + $Time = Measure-Command -Expression { + # Sleeping to simulate setup time + Start-Sleep -Milliseconds 100 + $p.EnterTest() + # Sleeping to simulate test time + Start-Sleep -Milliseconds 100 + $p.LeaveTest() + $p.AddTestResult("result","Passed",$null) + # Sleeping to simulate teardown time + Start-Sleep -Milliseconds 100 + } + $p.LeaveTestGroup() + [int]($p.time.TotalMilliseconds) | Should -BeGreaterOrEqual ($Time.Milliseconds-150) + [int]($p.time.TotalMilliseconds) | Should -BeLessOrEqual ($Time.Milliseconds+150) + } + it "adds passed test" { $p.AddTestResult("result","Passed", 100) $result = $p.TestResult[-1] From 32a8bdf8ec512f9060900431f4993dc5427f3dfd Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Wed, 26 Dec 2018 23:17:17 -0500 Subject: [PATCH 02/18] Adjusted where timestamps are gathered for differing timings --- Functions/PesterState.ps1 | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index cb8f84b60..f0998d679 100644 --- a/Functions/PesterState.ps1 +++ b/Functions/PesterState.ps1 @@ -50,7 +50,8 @@ function New-PesterState $script:SessionState = $_sessionState $script:Stopwatch = [System.Diagnostics.Stopwatch]::StartNew() - $script:MostRecentTimestamp = 0 + $script:TestGroupStartTime = 0 + $script:TestStartTime = 0 $script:CommandCoverage = @() $script:Strict = $Strict $script:Show = $Show @@ -109,12 +110,18 @@ function New-PesterState { $newGroup = New-TestGroup @PSBoundParameters $null = $script:TestGroupStack.Peek().Actions.Add($newGroup) + $script:TestGroupStartTime = $script:Stopwatch.Elapsed $script:TestGroupStack.Push($newGroup) } function LeaveTestGroup([string] $Name, [string] $Hint) { $currentGroup = $script:TestGroupStack.Pop() + $script:TestGroupStopTime = $script:Stopwatch.Elapsed + if ( $script:TestGroupStartTime ) { + $script:Time += $script:TestGroupStopTime - $script:TestGroupStartTime + $script:TestGroupStartTime = $null + } if ($currentGroup.Name -ne $Name -or $currentGroup.Hint -ne $Hint) { @@ -146,12 +153,9 @@ function New-PesterState return $errorRecord } - $previousTime = $script:MostRecentTimestamp - $script:MostRecentTimestamp = $script:Stopwatch.Elapsed - if ($null -eq $Time) { - $Time = $script:MostRecentTimestamp - $previousTime + $Time = $script:TestFinishTime - $script:TestStartTime } if (-not $script:Strict) @@ -171,7 +175,6 @@ function New-PesterState } $script:TotalCount++ - $script:Time += $Time switch ($Result) { @@ -324,11 +327,13 @@ function New-PesterState throw 'You are already in a test case.' } + $script:TestStartTime = $script:Stopwatch.Elapsed $script:InTest = $true } function LeaveTest { + $script:TestFinishTime = $script:Stopwatch.Elapsed $script:InTest = $false } From b31b58ba961c4661761dcc7102cfdcad28444c63 Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Wed, 26 Dec 2018 23:37:50 -0500 Subject: [PATCH 03/18] Adding logic for skipped and pending tests --- Functions/PesterState.ps1 | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index f0998d679..ae318241c 100644 --- a/Functions/PesterState.ps1 +++ b/Functions/PesterState.ps1 @@ -155,7 +155,12 @@ function New-PesterState if ($null -eq $Time) { - $Time = $script:TestFinishTime - $script:TestStartTime + if( "Skipped","Pending" -contains $Result ){ + $Time = $script:TestFinishTime - $script:TestStartTime + } else { + # EnterTest or LeaveTest were not called. Typically a skipped or pending test. + $Time = 0 + } } if (-not $script:Strict) From 435fec34bbdcc0b7bbaeccdaeb42d665f8a47e70 Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Wed, 26 Dec 2018 23:42:30 -0500 Subject: [PATCH 04/18] Getting tired... --- Functions/PesterState.ps1 | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index ae318241c..dbaa880f0 100644 --- a/Functions/PesterState.ps1 +++ b/Functions/PesterState.ps1 @@ -155,11 +155,11 @@ function New-PesterState if ($null -eq $Time) { - if( "Skipped","Pending" -contains $Result ){ - $Time = $script:TestFinishTime - $script:TestStartTime - } else { + if( $null -eq $script:TestFinishTime -or $null -eq $script:TestStartTime ){ # EnterTest or LeaveTest were not called. Typically a skipped or pending test. $Time = 0 + } else { + $Time = $script:TestFinishTime - $script:TestStartTime } } From 85b7d82cf5fbc975697b1a438dac84ae428b2e7c Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Wed, 26 Dec 2018 23:48:04 -0500 Subject: [PATCH 05/18] PowerShell 2.0 doesn't deal well with non initialized variables --- Functions/PesterState.ps1 | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index dbaa880f0..b5d3915a7 100644 --- a/Functions/PesterState.ps1 +++ b/Functions/PesterState.ps1 @@ -51,7 +51,9 @@ function New-PesterState $script:SessionState = $_sessionState $script:Stopwatch = [System.Diagnostics.Stopwatch]::StartNew() $script:TestGroupStartTime = 0 + $script:TestGroupStopTime = 0 $script:TestStartTime = 0 + $script:TestStopTime = 0 $script:CommandCoverage = @() $script:Strict = $Strict $script:Show = $Show @@ -155,11 +157,11 @@ function New-PesterState if ($null -eq $Time) { - if( $null -eq $script:TestFinishTime -or $null -eq $script:TestStartTime ){ + if( $null -eq $script:TestStopTime -or $null -eq $script:TestStartTime ){ # EnterTest or LeaveTest were not called. Typically a skipped or pending test. $Time = 0 } else { - $Time = $script:TestFinishTime - $script:TestStartTime + $Time = $script:TestStopTime - $script:TestStartTime } } @@ -338,7 +340,7 @@ function New-PesterState function LeaveTest { - $script:TestFinishTime = $script:Stopwatch.Elapsed + $script:TestStopTime = $script:Stopwatch.Elapsed $script:InTest = $false } From a17914c42539b78b19a957bbadae9e405c7a3d25 Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Wed, 26 Dec 2018 23:58:38 -0500 Subject: [PATCH 06/18] Another attempt at PowerShell 2.0 --- Functions/PesterState.ps1 | 18 ++++++++++-------- 1 file changed, 10 insertions(+), 8 deletions(-) diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index b5d3915a7..3d0f0651b 100644 --- a/Functions/PesterState.ps1 +++ b/Functions/PesterState.ps1 @@ -50,10 +50,10 @@ function New-PesterState $script:SessionState = $_sessionState $script:Stopwatch = [System.Diagnostics.Stopwatch]::StartNew() - $script:TestGroupStartTime = 0 - $script:TestGroupStopTime = 0 - $script:TestStartTime = 0 - $script:TestStopTime = 0 + $script:TestGroupStartTime = $null + $script:TestGroupStopTime = [timespan]0 + $script:TestStartTime = $null + $script:TestStopTime = [timespan]0 $script:CommandCoverage = @() $script:Strict = $Strict $script:Show = $Show @@ -123,6 +123,7 @@ function New-PesterState if ( $script:TestGroupStartTime ) { $script:Time += $script:TestGroupStopTime - $script:TestGroupStartTime $script:TestGroupStartTime = $null + $script:TestGroupStopTime = [timespan]0 } if ($currentGroup.Name -ne $Name -or $currentGroup.Hint -ne $Hint) @@ -157,11 +158,12 @@ function New-PesterState if ($null -eq $Time) { - if( $null -eq $script:TestStopTime -or $null -eq $script:TestStartTime ){ - # EnterTest or LeaveTest were not called. Typically a skipped or pending test. - $Time = 0 - } else { + if ( $script:TestStartTime ) { $Time = $script:TestStopTime - $script:TestStartTime + $script:TestStartTime = $null + $script:TestStopTime = [timespan]0 + } else { + $Time = [timespan]0 } } From a94ab5b22d5be1088b2c46bc010604e76534971f Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Thu, 27 Dec 2018 00:07:38 -0500 Subject: [PATCH 07/18] Adjusting the acceptable timing on test groups to 200 milliseconds --- Functions/PesterState.Tests.ps1 | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/Functions/PesterState.Tests.ps1 b/Functions/PesterState.Tests.ps1 index 8c2fd7e4e..f1af8d526 100644 --- a/Functions/PesterState.Tests.ps1 +++ b/Functions/PesterState.Tests.ps1 @@ -84,7 +84,7 @@ InModuleScope Pester { [int]($result.time.TotalMilliseconds) | Should -BeLessOrEqual ($Time.Milliseconds+10) } - it "times test group accurately within 150 milliseconds" { + it "times test group accurately within 200 milliseconds" { $p.EnterTestGroup() $Time = Measure-Command -Expression { # Sleeping to simulate setup time @@ -98,8 +98,8 @@ InModuleScope Pester { Start-Sleep -Milliseconds 100 } $p.LeaveTestGroup() - [int]($p.time.TotalMilliseconds) | Should -BeGreaterOrEqual ($Time.Milliseconds-150) - [int]($p.time.TotalMilliseconds) | Should -BeLessOrEqual ($Time.Milliseconds+150) + [int]($p.time.TotalMilliseconds) | Should -BeGreaterOrEqual ($Time.Milliseconds-200) + [int]($p.time.TotalMilliseconds) | Should -BeLessOrEqual ($Time.Milliseconds+200) } it "adds passed test" { From 3ab52fd9c9eb6815af3136e2b3c68ddfc8894b81 Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Fri, 28 Dec 2018 08:32:49 -0500 Subject: [PATCH 08/18] Removing cast to integer --- Functions/PesterState.Tests.ps1 | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/Functions/PesterState.Tests.ps1 b/Functions/PesterState.Tests.ps1 index f1af8d526..27d2bf373 100644 --- a/Functions/PesterState.Tests.ps1 +++ b/Functions/PesterState.Tests.ps1 @@ -80,8 +80,8 @@ InModuleScope Pester { $p.LeaveTest() $p.AddTestResult("result","Passed",$null) $result = $p.TestResult[-1] - [int]($result.time.TotalMilliseconds) | Should -BeGreaterOrEqual ($Time.Milliseconds-10) - [int]($result.time.TotalMilliseconds) | Should -BeLessOrEqual ($Time.Milliseconds+10) + $result.time.TotalMilliseconds | Should -BeGreaterOrEqual ($Time.Milliseconds-10) + $result.time.TotalMilliseconds | Should -BeLessOrEqual ($Time.Milliseconds+10) } it "times test group accurately within 200 milliseconds" { @@ -98,8 +98,8 @@ InModuleScope Pester { Start-Sleep -Milliseconds 100 } $p.LeaveTestGroup() - [int]($p.time.TotalMilliseconds) | Should -BeGreaterOrEqual ($Time.Milliseconds-200) - [int]($p.time.TotalMilliseconds) | Should -BeLessOrEqual ($Time.Milliseconds+200) + $p.time.TotalMilliseconds | Should -BeGreaterOrEqual ($Time.Milliseconds-200) + $p.time.TotalMilliseconds | Should -BeLessOrEqual ($Time.Milliseconds+200) } it "adds passed test" { From 1a76cef56fe16d753f34ca56d7dfda6da125811c Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Fri, 28 Dec 2018 08:54:20 -0500 Subject: [PATCH 09/18] Figured out why the test group test was so far off (200 ms) and fixed --- Functions/PesterState.Tests.ps1 | 12 +++++++----- Functions/PesterState.ps1 | 19 +++++++++++++------ 2 files changed, 20 insertions(+), 11 deletions(-) diff --git a/Functions/PesterState.Tests.ps1 b/Functions/PesterState.Tests.ps1 index 27d2bf373..78ea6a704 100644 --- a/Functions/PesterState.Tests.ps1 +++ b/Functions/PesterState.Tests.ps1 @@ -84,8 +84,9 @@ InModuleScope Pester { $result.time.TotalMilliseconds | Should -BeLessOrEqual ($Time.Milliseconds+10) } - it "times test group accurately within 200 milliseconds" { - $p.EnterTestGroup() + it "times test group accurately within 10 milliseconds" { + $TotalTimeStart = $p.time; + $p.EnterTestGroup('My Test Group', 'Script') $Time = Measure-Command -Expression { # Sleeping to simulate setup time Start-Sleep -Milliseconds 100 @@ -97,9 +98,10 @@ InModuleScope Pester { # Sleeping to simulate teardown time Start-Sleep -Milliseconds 100 } - $p.LeaveTestGroup() - $p.time.TotalMilliseconds | Should -BeGreaterOrEqual ($Time.Milliseconds-200) - $p.time.TotalMilliseconds | Should -BeLessOrEqual ($Time.Milliseconds+200) + $p.LeaveTestGroup('My Test Group', 'Script') + $TimeRecorded = $p.time - $TotalTimeStart + $TimeRecorded.Milliseconds | Should -BeGreaterOrEqual ($Time.Milliseconds-10) + $TimeRecorded.Milliseconds | Should -BeLessOrEqual ($Time.Milliseconds+10) } it "adds passed test" { diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index 3d0f0651b..dcef58d27 100644 --- a/Functions/PesterState.ps1 +++ b/Functions/PesterState.ps1 @@ -112,18 +112,25 @@ function New-PesterState { $newGroup = New-TestGroup @PSBoundParameters $null = $script:TestGroupStack.Peek().Actions.Add($newGroup) - $script:TestGroupStartTime = $script:Stopwatch.Elapsed + + if( $Hint -eq 'Script' ) { + $script:TestGroupStartTime = $script:Stopwatch.Elapsed + } + $script:TestGroupStack.Push($newGroup) } function LeaveTestGroup([string] $Name, [string] $Hint) { $currentGroup = $script:TestGroupStack.Pop() - $script:TestGroupStopTime = $script:Stopwatch.Elapsed - if ( $script:TestGroupStartTime ) { - $script:Time += $script:TestGroupStopTime - $script:TestGroupStartTime - $script:TestGroupStartTime = $null - $script:TestGroupStopTime = [timespan]0 + + if( $Hint -eq 'Script' ) { + $script:TestGroupStopTime = $script:Stopwatch.Elapsed + if ( $script:TestGroupStartTime ) { + $script:Time += $script:TestGroupStopTime - $script:TestGroupStartTime + $script:TestGroupStartTime = $null + $script:TestGroupStopTime = [timespan]0 + } } if ($currentGroup.Name -ne $Name -or $currentGroup.Hint -ne $Hint) From 1b3dcdf75c7474f884de6222023bbd4921105deb Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Fri, 28 Dec 2018 09:15:19 -0500 Subject: [PATCH 10/18] Added a comments to clarify my thought process for the tests --- Functions/PesterState.Tests.ps1 | 65 ++++++++++++++++++++++++++++++++- 1 file changed, 63 insertions(+), 2 deletions(-) diff --git a/Functions/PesterState.Tests.ps1 b/Functions/PesterState.Tests.ps1 index 78ea6a704..67da0646c 100644 --- a/Functions/PesterState.Tests.ps1 +++ b/Functions/PesterState.Tests.ps1 @@ -72,38 +72,99 @@ 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 group accurately within 10 milliseconds" { + it "times test group time accurately increments 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 { - # Sleeping to simulate setup time + + # 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] From 9d56e3db7e673df7125089b31076fbc45fae6674 Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Thu, 10 Jan 2019 22:58:52 -0500 Subject: [PATCH 11/18] Modifications for group time to include BeforeAll and others --- Functions/PesterState.Tests.ps1 | 46 ++++++++++++++++++++++++++++++++- Functions/PesterState.ps1 | 22 +++++++--------- Pester.psm1 | 3 --- 3 files changed, 54 insertions(+), 17 deletions(-) diff --git a/Functions/PesterState.Tests.ps1 b/Functions/PesterState.Tests.ps1 index 67da0646c..9ffd3c66e 100644 --- a/Functions/PesterState.Tests.ps1 +++ b/Functions/PesterState.Tests.ps1 @@ -110,7 +110,51 @@ InModuleScope Pester { $result.time.TotalMilliseconds | Should -BeLessOrEqual ($Time.Milliseconds+10) } - it "times test group time accurately increments testsuite time within 10 milliseconds" { + it "times test groups accurately within 10 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[-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 "accurately increments total testsuite time within 10 milliseconds" { # Initial time for the current testsuite $TotalTimeStart = $p.time; diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index dcef58d27..979069024 100644 --- a/Functions/PesterState.ps1 +++ b/Functions/PesterState.ps1 @@ -50,10 +50,7 @@ function New-PesterState $script:SessionState = $_sessionState $script:Stopwatch = [System.Diagnostics.Stopwatch]::StartNew() - $script:TestGroupStartTime = $null - $script:TestGroupStopTime = [timespan]0 $script:TestStartTime = $null - $script:TestStopTime = [timespan]0 $script:CommandCoverage = @() $script:Strict = $Strict $script:Show = $Show @@ -95,6 +92,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 @@ -111,28 +109,26 @@ 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) - - if( $Hint -eq 'Script' ) { - $script:TestGroupStartTime = $script:Stopwatch.Elapsed - } $script:TestGroupStack.Push($newGroup) } function LeaveTestGroup([string] $Name, [string] $Hint) { + $StopTime = $script:Stopwatch.Elapsed $currentGroup = $script:TestGroupStack.Pop() if( $Hint -eq 'Script' ) { - $script:TestGroupStopTime = $script:Stopwatch.Elapsed - if ( $script:TestGroupStartTime ) { - $script:Time += $script:TestGroupStopTime - $script:TestGroupStartTime - $script:TestGroupStartTime = $null - $script:TestGroupStopTime = [timespan]0 - } + $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)'." diff --git a/Pester.psm1 b/Pester.psm1 index bd6bc7ceb..35f5e618f 100644 --- a/Pester.psm1 +++ b/Pester.psm1 @@ -1508,7 +1508,6 @@ function Set-PesterStatistics($Node) Set-PesterStatistics -Node $action $Node.TotalCount += $action.TotalCount - $Node.Time += $action.Time $Node.PassedCount += $action.PassedCount $Node.FailedCount += $action.FailedCount $Node.SkippedCount += $action.SkippedCount @@ -1527,8 +1526,6 @@ function Set-PesterStatistics($Node) Pending { $Node.PendingCount++; break; } Inconclusive { $Node.InconclusiveCount++; break; } } - - $Node.Time += $action.Time } } } From 57b2bb05ece30be76a974c125591fc1680a3d9fe Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Thu, 10 Jan 2019 23:42:41 -0500 Subject: [PATCH 12/18] Modified tests to use real time instead of timespans --- Functions/PesterState.Tests.ps1 | 14 +++++++------- Functions/TestResults.Tests.ps1 | 34 ++++++++++++++++++++++++--------- 2 files changed, 32 insertions(+), 16 deletions(-) diff --git a/Functions/PesterState.Tests.ps1 b/Functions/PesterState.Tests.ps1 index f9a0db1b2..b2f8ca0b7 100644 --- a/Functions/PesterState.Tests.ps1 +++ b/Functions/PesterState.Tests.ps1 @@ -96,7 +96,7 @@ InModuleScope Pester { <# 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 + and the finish of the test which should also match the time we recorded using the Measure-Command #> $p.AddTestResult("result","Passed",$null) @@ -110,7 +110,7 @@ InModuleScope Pester { $result.time.TotalMilliseconds | Should -BeLessOrEqual ($Time.Milliseconds+10) } - it "times test groups accurately within 10 milliseconds" { + 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 { @@ -133,7 +133,7 @@ InModuleScope Pester { <# 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 + and the finish of the test which should also match the time we recorded using the Measure-Command #> $p.AddTestResult("result","Passed",$null) @@ -148,10 +148,10 @@ InModuleScope Pester { # Getting the last test group result $result = $p.TestGroupStack.peek().Actions[-1] - # The time recorded as taken during the test should be within + or - 10 milliseconds of the time we + # 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-10) - $result.time.TotalMilliseconds | Should -BeLessOrEqual ($Time.Milliseconds+10) + $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" { @@ -182,7 +182,7 @@ InModuleScope Pester { <# 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 + and the finish of the test which should also match the time we recorded using the Measure-Command #> $p.AddTestResult("result","Passed",$null) diff --git a/Functions/TestResults.Tests.ps1 b/Functions/TestResults.Tests.ps1 index f5d3c688e..d8309c0a9 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[-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[-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[-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)) From b806d1fea1727ea751f583abb8d86011bbabd1b9 Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Fri, 11 Jan 2019 00:14:18 -0500 Subject: [PATCH 13/18] Converting ArrayList to Array for PS v2.0 --- Functions/PesterState.Tests.ps1 | 20 ++++++++++---------- Functions/TestResults.Tests.ps1 | 6 +++--- 2 files changed, 13 insertions(+), 13 deletions(-) diff --git a/Functions/PesterState.Tests.ps1 b/Functions/PesterState.Tests.ps1 index b2f8ca0b7..13acac2db 100644 --- a/Functions/PesterState.Tests.ps1 +++ b/Functions/PesterState.Tests.ps1 @@ -99,15 +99,15 @@ InModuleScope Pester { and the finish of the test which should also match the time we recorded using the Measure-Command #> - $p.AddTestResult("result","Passed",$null) + $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) + $result.time.TotalMilliseconds | Should -BeGreaterOrEqual ($Time.Milliseconds - 10) + $result.time.TotalMilliseconds | Should -BeLessOrEqual ($Time.Milliseconds + 10) } it "times test groups accurately within 15 milliseconds" { @@ -136,7 +136,7 @@ InModuleScope Pester { and the finish of the test which should also match the time we recorded using the Measure-Command #> - $p.AddTestResult("result","Passed",$null) + $p.AddTestResult("result", "Passed", $null) # Sleeping to simulate teardown time Start-Sleep -Milliseconds 100 @@ -146,12 +146,12 @@ InModuleScope Pester { } # Getting the last test group result - $result = $p.TestGroupStack.peek().Actions[-1] + $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) + $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" { @@ -185,7 +185,7 @@ InModuleScope Pester { and the finish of the test which should also match the time we recorded using the Measure-Command #> - $p.AddTestResult("result","Passed",$null) + $p.AddTestResult("result", "Passed", $null) # Sleeping to simulate teardown time Start-Sleep -Milliseconds 100 @@ -203,8 +203,8 @@ InModuleScope Pester { # 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) + $TimeRecorded.Milliseconds | Should -BeGreaterOrEqual ($Time.Milliseconds - 10) + $TimeRecorded.Milliseconds | Should -BeLessOrEqual ($Time.Milliseconds + 10) } #endregion TIMING TESTS diff --git a/Functions/TestResults.Tests.ps1 b/Functions/TestResults.Tests.ps1 index d8309c0a9..00d91d82e 100644 --- a/Functions/TestResults.Tests.ps1 +++ b/Functions/TestResults.Tests.ps1 @@ -70,7 +70,7 @@ InModuleScope Pester { $TestResults.AddTestResult("Successful testcase", 'Passed', $null) $testResults.LeaveTestGroup('Mocked Describe', 'Describe') - $TestGroup = $testResults.TestGroupStack.peek().Actions[-1] + $TestGroup = $testResults.TestGroupStack.peek().Actions.ToArray()[-1] Set-PesterStatistics -Node $TestResults.TestActions @@ -97,14 +97,14 @@ InModuleScope Pester { $TestResults.LeaveTest() $TestResults.AddTestResult("Successful testcase", 'Passed', $null) $TestResults.LeaveTestGroup('Describe #1', 'Describe') - $Describe1 = $testResults.TestGroupStack.peek().Actions[-1] + $Describe1 = $testResults.TestGroupStack.peek().Actions.ToArray()[-1] $testResults.EnterTestGroup('Describe #2', 'Describe') $TestResults.EnterTest() Start-Sleep -Milliseconds 200 $TestResults.LeaveTest() $TestResults.AddTestResult("Failed testcase", 'Failed', $null) $TestResults.LeaveTestGroup('Describe #2', 'Describe') - $Describe2 = $testResults.TestGroupStack.peek().Actions[-1] + $Describe2 = $testResults.TestGroupStack.peek().Actions.ToArray()[-1] Set-PesterStatistics -Node $TestResults.TestActions From 7f6fe3a3ffcc7657f2816b6a26e02c5a67a6cea3 Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Fri, 11 Jan 2019 00:31:13 -0500 Subject: [PATCH 14/18] More goodness for PowerShell 2.0 --- Functions/PesterState.ps1 | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index 1b3c77487..783eb36e8 100644 --- a/Functions/PesterState.ps1 +++ b/Functions/PesterState.ps1 @@ -147,7 +147,7 @@ function New-PesterState { } if ($null -eq $Time) { - if ( $script:TestStartTime ) { + if ( $null -ne $script:TestStartTime -and $null -ne $script:TestStopTime ) { $Time = $script:TestStopTime - $script:TestStartTime $script:TestStartTime = $null $script:TestStopTime = [timespan]0 From 539f1811cec51eb5079cc06b32afac18c77e7a83 Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Fri, 11 Jan 2019 00:31:13 -0500 Subject: [PATCH 15/18] More goodness for PowerShell 2.0 --- Functions/PesterState.ps1 | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index 1b3c77487..ea2025307 100644 --- a/Functions/PesterState.ps1 +++ b/Functions/PesterState.ps1 @@ -147,7 +147,7 @@ function New-PesterState { } if ($null -eq $Time) { - if ( $script:TestStartTime ) { + if ( $script:TestStartTime -and $script:TestStopTime ) { $Time = $script:TestStopTime - $script:TestStartTime $script:TestStartTime = $null $script:TestStopTime = [timespan]0 From 5bedcb41408fe5759b58796e670cfd8df769e696 Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Fri, 11 Jan 2019 00:40:44 -0500 Subject: [PATCH 16/18] PowerShell 2.0 --- Functions/PesterState.ps1 | 4 ---- 1 file changed, 4 deletions(-) diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index b42f8d174..ea2025307 100644 --- a/Functions/PesterState.ps1 +++ b/Functions/PesterState.ps1 @@ -147,11 +147,7 @@ function New-PesterState { } if ($null -eq $Time) { -<<<<<<< HEAD if ( $script:TestStartTime -and $script:TestStopTime ) { -======= - if ( $null -ne $script:TestStartTime -and $null -ne $script:TestStopTime ) { ->>>>>>> 7f6fe3a3ffcc7657f2816b6a26e02c5a67a6cea3 $Time = $script:TestStopTime - $script:TestStartTime $script:TestStartTime = $null $script:TestStopTime = [timespan]0 From 72192c88fcd6ffb7316a7f881706d5a752717852 Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Fri, 11 Jan 2019 00:48:34 -0500 Subject: [PATCH 17/18] Fix for v2.0 sctrict mode support --- Functions/PesterState.ps1 | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index ea2025307..94db4cbc8 100644 --- a/Functions/PesterState.ps1 +++ b/Functions/PesterState.ps1 @@ -147,7 +147,7 @@ function New-PesterState { } if ($null -eq $Time) { - if ( $script:TestStartTime -and $script:TestStopTime ) { + if ( (test-path variable:Script:testStartTime) -and (test-path variable:Script:testStopTime) ) { $Time = $script:TestStopTime - $script:TestStartTime $script:TestStartTime = $null $script:TestStopTime = [timespan]0 From b14f200f0d7033f301163470c15c21a92dd4d729 Mon Sep 17 00:00:00 2001 From: Micah Rairdon Date: Fri, 11 Jan 2019 01:08:52 -0500 Subject: [PATCH 18/18] Declared variable as null instead of testing for it --- Functions/PesterState.ps1 | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/Functions/PesterState.ps1 b/Functions/PesterState.ps1 index 94db4cbc8..b0076e1c6 100644 --- a/Functions/PesterState.ps1 +++ b/Functions/PesterState.ps1 @@ -46,6 +46,7 @@ function New-PesterState { $script:SessionState = $_sessionState $script:Stopwatch = [System.Diagnostics.Stopwatch]::StartNew() $script:TestStartTime = $null + $script:TestStopTime = $null $script:CommandCoverage = @() $script:Strict = $Strict $script:Show = $Show @@ -147,7 +148,7 @@ function New-PesterState { } if ($null -eq $Time) { - if ( (test-path variable:Script:testStartTime) -and (test-path variable:Script:testStopTime) ) { + if ( $script:TestStartTime -and $script:TestStopTime ) { $Time = $script:TestStopTime - $script:TestStartTime $script:TestStartTime = $null $script:TestStopTime = [timespan]0