Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Performance regression in xunit.assert between 2.4.2 and 2.5.0 (then more) in Assert.Equal with byte arrays #2806

Closed
jskeet opened this issue Oct 27, 2023 · 13 comments

Comments

@jskeet
Copy link

jskeet commented Oct 27, 2023

I noticed this with a unit test that compares large byte arrays. I haven't tested whether it applies to other types. (Byte arrays are probably the most common type to compare really large amounts of data.)

Repro: create a console app targeting net6.0, add a reference to xunit.assert, and replace Program.cs with:

using System.Diagnostics;
using System.Reflection;
using Xunit;

const int size = 50_000_000;
const int iterations = 5;
byte[] expected = new byte[size];
byte[] actual = new byte[size];

var version = typeof(Assert).Assembly.GetCustomAttributes<AssemblyFileVersionAttribute>().FirstOrDefault()?.Version;
Console.WriteLine($"xunit.assert version: {version}");
Console.WriteLine($"Test size: {size}");

for (int i = 0; i < iterations; i++)
{
    Stopwatch sw = Stopwatch.StartNew();
    Assert.Equal(expected, actual);
    sw.Stop();
    Console.WriteLine($"Iteration {i}: {sw.ElapsedMilliseconds}ms");
}

Change the project file to vary the version of xunit.assert being tested.

Results (in version order, running dotnet run -c Release):

xunit.assert version: 2.4.2
Test size: 50000000
Iteration 0: 7008ms
Iteration 1: 6812ms
Iteration 2: 6875ms
Iteration 3: 6857ms
Iteration 4: 6814ms

xunit.assert version: 2.5.0
Test size: 50000000
Iteration 0: 38876ms
Iteration 1: 39403ms
Iteration 2: 49416ms
Iteration 3: 55308ms
Iteration 4: 39648ms

xunit.assert version: 2.5.1
Test size: 50000000
Iteration 0: 45382ms
Iteration 1: 48564ms
Iteration 2: 44268ms
Iteration 3: 46000ms
Iteration 4: 64264ms

xunit.assert version: 2.5.2
Test size: 50000000
Iteration 0: 54069ms
Iteration 1: 42258ms
Iteration 2: 43719ms
Iteration 3: 44026ms
Iteration 4: 43563ms

xunit.assert version: 2.5.3
Test size: 50000000
Iteration 0: 42718ms
Iteration 1: 73810ms
Iteration 2: 44661ms
Iteration 3: 41220ms
Iteration 4: 46723ms

So it looks like there was a big regression between 2.4.2 and 2.5.0, then it was (maybe) made slightly worse in 2.5.1, and has since stayed steady? The large variation between iterations within a given version makes me suspect there's GC going on here, but I haven't looked into that.

@bradwilson
Copy link
Member

I can verify that here:

<PackageReference Include="xunit.assert" Version="2.4.2" />

xunit.assert version: 2.4.2
Test size: 50000000
Iteration 0: 4291ms
Iteration 1: 4228ms
Iteration 2: 4244ms
Iteration 3: 4253ms
Iteration 4: 4263ms

<PackageReference Include="xunit.assert" Version="2.5.3" />

xunit.assert version: 2.5.3
Test size: 50000000
Iteration 0: 20281ms
Iteration 1: 20183ms
Iteration 2: 20243ms
Iteration 3: 20379ms
Iteration 4: 20180ms

(I don't see the same variation that you do, but GC may be a good guess as to what's going on there. My test machine is an AMD R9-5900X with 64GB of RAM running Windows 11.)

So yes, there's definitely a performance regression. The assertion library was overhauled for v3, and then back-ported into 2.5.0 and later. I am surprised to discover it's this much slower, because I'm pretty sure most of what I did should have improved performance rather than reduced it (for example, ensuring we stop as much double enumeration as we could). The likely answer is that CollectionTracker, which is used for being able to print collections in error messages, needs optimization. My 95%+ guess is that the Dictionary<int, object> in the custom enumerator is a bad performer when given tons of items to look at, since it churns through them. A fixed ring buffer would likely fix this up quickly if that's the problem.


In the meantime, I may have a workaround for you that actually performs a LOT better than I could ever get with a fix to CollectionTracker. I tried the assertions from v3:

<PackageReference Include="xunit.v3.assert" Version="0.1.1-pre.302" />

xunit.assert version: 0.1.1
Test size: 50000000
Iteration 0: 36ms
Iteration 1: 3ms
Iteration 2: 2ms
Iteration 3: 3ms
Iteration 4: 3ms

The magic here boils down to treating arrays of un-managed types as spans: https://github.com/xunit/assert.xunit/blob/3bb3309722867df337161527182683b3adf32413/EqualityAsserts.cs#L34-L66

Unfortunately, no version of the v2 asserts is available in binary form that defines XUNIT_SPAN because spans are not available in netstandard1.1, the target of xunit.assert.

You can just use the v3 assertions in your v2 project (which is possible, although I have not pushed any v3 bits to NuGet because it's not ready for public consumption--not because of the assertion library, which is identical source between v2 and v3--but because I haven't made third party runners work yet, and that includes support for Visual Studio's Test Explorer and dotnet test). The one caveat I would put there is that it includes Assert.Skip, which is not supported on v2 (it requires runtime support).

You could also use the assertion library via source, ala:

<PropertyGroup>
  <DefineConstants>XUNIT_SPAN</DefineConstants>
</PropertyGroup>

<ItemGroup>
  <PackageReference Include="xunit.assert.source" Version="2.5.3" />
</ItemGroup>
xunit.assert version: 1.0.0.0
Test size: 50000000
Iteration 0: 35ms
Iteration 1: 3ms
Iteration 2: 2ms
Iteration 3: 2ms
Iteration 4: 2ms

Performance is identical to the v3, since the span path is now open to us.

For more information on using assert this way, check out the README on annotations: https://github.com/xunit/assert.xunit/#annotations

Currently in v2, we only define XUNIT_NULLABLE, but there are several more features and optimizations that could be added in a net6.0+ project: not just XUNIT_SPAN, but also XUNIT_IMMUTABLE_COLLECTIONS and XUNIT_VALUETASK.

...and as I describe all of this, it makes me want to just ship a net6.0 binary in 2.5.4 along with the netstandard1.1 binary. 😂

@jskeet
Copy link
Author

jskeet commented Oct 27, 2023

...and as I describe all of this, it makes me want to just ship a net6.0 binary in 2.5.4 along with the netstandard1.1 binary

That really sounds like a good idea to me - but my guess is that there'll be some interesting corner cases with the number of users xUnit has.

The regression definitely isn't a blocker for me; a bit of an inconvenience, but that's all. Please don't rush to put together an interim improvement on my account :)

@bradwilson
Copy link
Member

Well, there are two separate issues here in my mind:

(a) People have been wanting things like ValueTask support in the assertion library on v2, which I haven't been able to do without multi-targeting (and the new Span-based assertions would not only solve your problem, but make things a LOT faster)

(b) There is a performance regression, most likely from CollectionTracker, that needs to be fixed no matter what. My lazy has lost to your Stopwatch. 😁

@bradwilson
Copy link
Member

<PackageReference Include="xunit.assert" Version="2.5.4-pre.11" />

xunit.assert version: 2.5.4
Test size: 50000000
Iteration 0: 37ms
Iteration 1: 3ms
Iteration 2: 4ms
Iteration 3: 3ms
Iteration 4: 3ms

I'm not sure yet if this will ship as 2.5.4 or 2.6.0; I'm thinking maybe the latter because this is a decent sized change, adding the new binaries. Either way, there is a prerelease build on feedz.io if you want to verify on your end, which would be helpful to understand if you run into any other issues. Note that by having more signatures for assertions, it is possible that you may uncover method ambiguities where none existed previously, though the major time for that was moving from 2.4.2 => 2.5.x.

We have a ready-made NuGet.Config to add feedz.io to your package sources: https://xunit.net/docs/using-ci-builds

@bradwilson
Copy link
Member

bradwilson commented Oct 27, 2023

Hmm, ring buffer shaved a few percentage points off the time, but still nowhere near the old performance. (I bumped it down to 5 million from 50 million because time is valuable. 😂)

xunit.assert version: 2.4.2
Test size: 5000000
Iteration 0: 518ms
Iteration 1: 471ms
Iteration 2: 472ms
Iteration 3: 472ms
Iteration 4: 472ms
xunit.assert version: 2.5.3
Test size: 5000000
Iteration 0: 2947ms
Iteration 1: 2856ms
Iteration 2: 2855ms
Iteration 3: 2870ms
Iteration 4: 2885ms
xunit.assert version: 1.0.0.0
Test size: 5000000
Iteration 0: 2803ms
Iteration 1: 2738ms
Iteration 2: 2718ms
Iteration 3: 2720ms
Iteration 4: 2717ms

Ring buffer: xunit/assert.xunit@f184355?w=1

@bradwilson
Copy link
Member

bradwilson commented Oct 28, 2023

Cut a huge chunk out by not running unnecessary new code to support IComparable<Y> and IEquatable<Y> in addition to IComparable<X> and IEquatable<X> (and caching the expensive creation of those types, since they can't be done for "free" by the compiler). Gone from ~6x to ~1.9x.

xunit.assert version: 1.0.0.0
Test size: 5000000
Iteration 0: 1040ms
Iteration 1: 880ms
Iteration 2: 886ms
Iteration 3: 878ms
Iteration 4: 875ms

Conditional & caching: xunit/assert.xunit@6a94a86?w=1

@bradwilson
Copy link
Member

Another big chunk, down to CastEnumerator having terrible enumeration performance (❗). Needed to replace that with a little detection of IEnumerable<T> and reflection-invoking a generic method to create CollectionTracker<T> instead of CollectionTracker<object> with an IEnumerable<object> created from an IEnumerable and LINQ .Cast<object>().

xunit.assert version: 1.0.0.0
Test size: 5000000
Iteration 0: 721ms
Iteration 1: 612ms
Iteration 2: 621ms
Iteration 3: 629ms
Iteration 4: 619ms

Getting close enough now that if I can't find another big smoking gun, I might call it done.

AsTracker improvements: xunit/assert.xunit@b3e3c93?w=1

@bradwilson
Copy link
Member

Okay, this one's just embarrassing. 😂 Unused (expensive) line of code in the comparison hot path.

xunit.assert version: 1.0.0.0
Test size: 5000000
Iteration 0: 620ms
Iteration 1: 509ms
Iteration 2: 510ms
Iteration 3: 512ms
Iteration 4: 513ms

Shame 🔔 Shame 🔔 xunit/assert.xunit@e48a306?w=1

@bradwilson
Copy link
Member

One last comparison set with 50 million again:

xunit.assert version: 2.4.2
Test size: 50000000
Iteration 0: 4733ms
Iteration 1: 4739ms
Iteration 2: 4678ms
Iteration 3: 4720ms
Iteration 4: 4754ms
xunit.assert version: 1.0.0.0
Test size: 50000000
Iteration 0: 5355ms
Iteration 1: 5134ms
Iteration 2: 5110ms
Iteration 3: 5123ms
Iteration 4: 5171ms

I got within 10%, so I think I'm happy with where it landed. Nothing else seems like an obvious candidate for fixing.

Plus, in your specific example here, the newly available net6.0 assertion library means you get Span-based comparisons, which are roughly 150_000% faster (for the passing cases, anyways):

xunit.assert version: 1.0.0.0
Test size: 50000000
Iteration 0: 25ms
Iteration 1: 3ms
Iteration 2: 2ms
Iteration 3: 2ms
Iteration 4: 2ms

I'll be pushing this as a 2.6.0 release, since it made a few behavioral changes (none of which I expect to trip people up, but better to get them thinking it's a little more major than a simple bug fix). I also technically changed the contracts of some CollectionTracker-related things, though in truth I never expect anybody to be using those directly.

@bradwilson
Copy link
Member

Available in v2: 2.5.4-pre.12
Available in v3: 0.1.1-pre.304

@jskeet
Copy link
Author

jskeet commented Oct 28, 2023

That's amazing - thanks so much for all the time you've put into this :)

@jskeet
Copy link
Author

jskeet commented Oct 30, 2023

Confirmed that with 2.5.4-pre.12, my actual tests (for an experimental project) go down from 2m => 21s for .NET 6, and 3m3s => 51s for .NET 4.6.2. (I believe the difference there between frameworks is in my production code, but I'll dig into that when I have more time.)

Thanks again!

@bradwilson
Copy link
Member

thanks so much for all the time you've put into this

Confession: retirement leaves me very few opportunities to break out the performance profiling tools in Visual Studio, so this was a bit irresistible. 😂

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants