WIP: Fixes #287 test time not accurate

[Tiberriver256]

1. General summary of the pull request

Fixes #287 - Test time is not accurate on the first run

I kept the concept of a single timer but split the timestamps into two places so that we get an accurate total test time as well as an accurate Test time.

Test time is evaluated based on timestamps in the EnterTest and LeaveTest functions.

Total test time is evaluated based on timestamps in the EnterTestGroup and LeaveTestGroup functions.

I also created two new tests for each case. Hopefully I got them in a section of the test that makes sense. Please let me know if there is anything I need to adjust.

[Tiberriver256]

Actually.... One more thing I just noticed on the timings from an nunit xml. The the TestGroup level timings are the sum of the tests within that TestGroup. Is that the way it should be? or should the TestGroup time include the time taken for BeforeAll / BeforeEach blocks?

I'll give a couple of examples down below. Just let me know if it should look like example 1 or example 2 and I'll drop in a quick fix or leave it as is.

Test

Describe "Test" {
        BeforeAll { Start-Sleep -Seconds 1  } 
        
        Context "Sleeping" {
           It "Sleeps for a second" { Start-Sleep -Seconds 1 }
        }        
}

Example 1

• 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

. . .
  <test-suite type="TestFixture" name="Pester" executed="True" result="Success" success="True" time="2" asserts="0" description="Pester">
    <results>
      <test-suite type="TestFixture" name=".\dummytest.ps1" executed="True" result="Success" success="True" time="2" asserts="0" description=".\dummytest.ps1">
        <results>
          <test-suite type="TestFixture" name="Test" executed="True" result="Success" success="True" time="2" asserts="0" description="Test">
            <results>
              <test-suite type="TestFixture" name="Sleeping" executed="True" result="Success" success="True" time="1" asserts="0" description="Sleeping">
                <results>
                  <test-case description="Sleeps for a second" name="Test.Sleeping.Sleeps for a second" time="1" asserts="0" success="True" result="Success" executed="True" />
                </results>
              </test-suite>
            </results>
          </test-suite>
        </results>
      </test-suite>
    </results>
  </test-suite>
. . .

Example 2

• 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 of 1 second
• Timing at describe level test group Test reflectstotal time for all tests of 1 second
• Timing at context level test group Sleeping reflects total time for all nested tests of 1 second
• Timing at test "Sleeps for a second reflects total time of the single test of 1 second

. . .
  <test-suite type="TestFixture" name="Pester" executed="True" result="Success" success="True" time="2" asserts="0" description="Pester">
    <results>
      <test-suite type="TestFixture" name=".\dummytest.ps1" executed="True" result="Success" success="True" time="1" asserts="0" description=".\dummytest.ps1">
        <results>
          <test-suite type="TestFixture" name="Test" executed="True" result="Success" success="True" time="1" asserts="0" description="Test">
            <results>
              <test-suite type="TestFixture" name="Sleeping" executed="True" result="Success" success="True" time="1" asserts="0" description="Sleeping">
                <results>
                  <test-case description="Sleeps for a second" name="Test.Sleeping.Sleeps for a second" time="1" asserts="0" success="True" result="Success" executed="True" />
                </results>
              </test-suite>
            </results>
          </test-suite>
        </results>
      </test-suite>
    </results>
  </test-suite>
. . .

I'm pretty sure example 1 is what we're going for here but wanted to double check.

[nohwnd]

For me the time should be all the time spent in user code, because the whole test does take that long to run. On the other hand some people do analysis on test runs and try to find outliers that take unnecessary amount of time and including setup in the test time makes it difficult to determine what is happening, whether the test is slower than the others or just does expensive setup. At the moment I am working on new internals for Describe and It, and there it should be easier to track how long each user step (be it setup, test or teardown took) and how much time the framework took, analysis can then be done on the result of the test run rather than the nUnit output, the nUnit output should imho report the setup as part of the test.

[nohwnd]

@Tiberriver256 I think it should look like example 1, are changes needed?

[nohwnd]

@Tiberriver256 Sorry to ping you again, but I'd like to release soon, and this would be nice to include. Are there any changes needed to make it work like example 1? Thx

[Tiberriver256]

Hey @nohwnd, sorry for the eternal delay. Yes, there are some minor changes. I'll get them up here tonight.

[Tiberriver256]

Wow, that took a lot more tinkering to get the tests passing again after merging with the latest version on master. Let me know how it looks!

[nohwnd]

@Tiberriver256 Thanks a lot, I ended up releasing yesterday, I will put this into the next release, if there are no bugs in the current release then I will make one just for this.

[nohwnd]

Thank you, merged. 🎉