Skip to content

Commit

Permalink
WIP: Fixes #287 test time not accurate (#1185)
Browse files Browse the repository at this point in the history 
Timing at top level reflects total time for all tests including BeforeAll of 2 seconds
Timing at script level test group .\dummytest.ps1 reflects total time for all tests including BeforeAll of 2 seconds
Timing at describe level test group Test reflects total time for all tests including BeforeAll of 2 seconds
Timing at context level test group Sleeping reflects total time for all nested scriptblocks of 1 second
Timing at test "Sleeps for a second reflects total time of the single test of 1 second
  • Loading branch information
@Tiberriver256 @nohwnd
Tiberriver256 authored and nohwnd committed Jan 12, 2019
1 parent 66e8409 commit abf2355
Show file tree
Hide file tree
Showing 4 changed files with 192 additions and 23 deletions.
137 changes: 137 additions & 0 deletions Functions/PesterState.Tests.ps1
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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]
Expand Down
31 changes: 25 additions & 6 deletions Functions/PesterState.ps1
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand All @@ -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)'."
}
Expand Down Expand Up @@ -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) {
Expand All @@ -154,7 +172,6 @@ function New-PesterState {
}

$script:TotalCount++
$script:Time += $Time

switch ($Result) {
Passed {
Expand Down Expand Up @@ -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
}

Expand Down
34 changes: 25 additions & 9 deletions Functions/TestResults.Tests.ps1
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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

Expand All @@ -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" {
Expand All @@ -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))
Expand Down
13 changes: 5 additions & 8 deletions Pester.psm1
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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') {
Expand All @@ -1457,8 +1456,6 @@ function Set-PesterStatistics($Node) {
$Node.InconclusiveCount++; break;
}
}

$Node.Time += $action.Time
}
}
}
Expand Down

0 comments on commit abf2355

Please sign in to comment.