Time is reported incorrectly for xunit when different verbosity is used

[nohwnd]

full issue is in here in dotnet repo: https://github.com/dotnet/runtime/issues/98205#issuecomment-1941833846

This is probably linked to the fact that normal console logger is measuring execution by datetime.now and the minimal output logger is collecting first and last test from each dll, and then reporting the diff.

[bradwilson]

minimal output logger is collecting first and last test from each dll, and then reporting the diff.

I'll admit, you knocked me over with that. 😂

[rmunn]

Reproduction:

• Clone https://github.com/rmunn/dotnet-test-xunit-timing-repro
• Run dotnet test /v:q. Test duration is wrong: first test is not counted in total duration.
• Run dotnet test /v:n. Test duration is still wrong, in the same way.
• Run dotnet test --logger "console;verbosity=quiet". Test duration is still wrong, in the same way.
• Run dotnet test --logger "console;verbosity=normal". Test duration is correct.

[nohwnd]

This is happening because the logger reports the duration as the difference between the earliest StartTime and latest EndTime on all tests reported from each assembly. But XUnit is not reporting StartTime and EndTime, so we set them both to the same timestamp, meaning that the duration of the first test is missing. The problem is also mentioned here https://github.com/microsoft/vstest/issues/4156#issuecomment-1384209872

Running the same with MSTest does not show the problem:

@bradwilson would it be possible to report the start time and end time from xunit to fix this? If not we can approximate by subtracting duration from the time when the test was reported, but that solution is not great.

[bradwilson]

I can add this to v3. It's probably not possible in v2 due to the frozen abstractions layer.

[bradwilson]

This is working now in VSTest adapter 3.0.0-pre.12, for v1/v2/v3 test projects. https://xunit.net/docs/using-ci-builds

Fix commit: https://github.com/xunit/visualstudio.xunit/commit/3ad2641b40bc19f46406225aa9a8f7b367c36e58

Using the repro project, built against v2 Core Framework, and using VSTest adapter 3.0.0-pre.11:

And here it is running with 3.0.0-pre.12:

[bradwilson]

It's also worth noting that our calculation of execution time is a more accurate measure than just subtracting finish time from start time, especially if you're running w/ the old aggressive parallelism algorithm (this changed to a more conservative parallelism algorithm in 2.8.0 to make test timing more accurate, at the potential expense of total execution time).

I presume Test Explorer will continue to report our explicit execution time (aka Duration) in the UI?

[nohwnd]

Yes they are using duration, if you'd like to change it, please file a visual studio feedback issue so it can sit in their queue.

And thanks for fixing it for v3.

[nohwnd]

I checked the code and we simply assign UTC now when the test result is constructed to both StartTime and EndTime, so to fix it in v2 you could simply do the same and just subtract the Duration from the end time when constructing ObjectModel TestResult. I will do the same fix in vstest, but you will be able to ship it much quickker, mine would be in test.sdk 17.12, which will be out not sooner than in couple of months.

https://github.com/microsoft/vstest/blob/main/src/Microsoft.TestPlatform.ObjectModel/TestResult.cs#L34-L35

[bradwilson]

Yes they are using duration, if you'd like to change it, please file a visual studio feedback issue so it can sit in their queue.

Nope, this absolutely is what I want them to keep doing. 😁

I checked the code and we simply assign UTC now when the test result is constructed to both StartTime and EndTime, so to fix it in v2 you could simply do the same and just subtract the Duration from the end time when constructing ObjectModel TestResult. I will do the same fix in vstest, but you will be able to ship it much quickker, mine would be in test.sdk 17.12, which will be out not sooner than in couple of months.

Yes, I believe we'll be pushing everybody over to the v3 VSTest adapter before 2 months from now, so there's not much reason that I can see to make this change if it's just for our sake. Once our users upgrade to a 3.x build of xunit.runner.visualstudio, this will get fixed for all tests (v1, v2, and v3), as it's always our policy that our runners are backward compatible (and forward compatible within the same major Core Framework version), and the fix for this is entirely contained within the VSTest adapter.