Optimize progress reporting by reusing StringBuilder #4360

lahma · 2023-04-21T16:12:52Z

When lookin at memory allocations during Jint.Tests.Test262 run, seems that most of the allocations come from NUnit itself (12%). Reporting test progress generates a lot of string so there's some room for improvement. Using reused StringBuilder to report progress.

The targets are OuterXml which always creates a new StringBuilder and TestStarted which manually concatenates a larger string. Now new GetOuterXml() allows providing reusable StringBuilder. Introduced new internal XmlExtensions that allows writing things in concise manner.

The root cause is more on the NUnit.Console side, but this should also help a bit.

stevenaw · 2023-04-23T17:46:40Z

src/NUnitFramework/framework/Internal/TestProgressReporter.cs

@@ -30,6 +31,9 @@ public TestProgressReporter(ICallbackEventHandler handler)

        #region ITestListener Members

+        [ThreadStatic]
+        private static StringBuilder? _testStartedStringBuilder;


This feels like a good step forward here, thanks! I don't have a great perfect model of the framework's approach to parallelization but this feels safe since we internally only use it on-stack.

I think this will still create a builder per thread. This change makes me curious if this opens the door to take this further in future PRs by making a formal pooling mechanism with rent/release mechanics so it's only at most a builder per thread in the worst case (ie, when all worker threads happen to be processing a TestStarted at the same time).

I think the easiest approach might be just taking the source from .NET: https://github.com/dotnet/runtime/blob/main/src/libraries/Common/src/System/Text/StringBuilderCache.cs , it's MIT licensed so should not be a problem and already battle-tested. Here I just tried to avoid bringing too much new stuff in, but I agree that general solution would be better.

Seems that NUnit would require larger than 360 chars default as it's building XML, Jint is using a pool which is not bound to threads which might work better here: https://github.com/sebastienros/jint/blob/main/Jint/Pooling/StringBuilderPool.cs

stevenaw · 2023-04-23T17:48:28Z

src/NUnitFramework/framework/Internal/TestProgressReporter.cs

@@ -39,19 +43,39 @@ public void TestStarted(ITest test)
            var parent = GetParent(test);
            try
            {
-                string report;
+                var report = _testStartedStringBuilder ??= new StringBuilder();


question: Should we set an initial capacity? I think it'll default to 16 but in either path below we likely require more

With MS version it would be 16, without initial the call after first will have larger StringBuilder with this original code.

stevenaw · 2023-04-23T17:53:36Z

src/NUnitFramework/framework/Internal/TestProgressReporter.cs

                if (test is TestSuite)
                {
+                    report
+                        .Append("<start-suite id=\"").Append(test.Id).Append('"')


comment: There was some duplicate of attributes in both paths here, but this move to StringBuilder also probably opens some opportunities for deduplication of XML attribute writing too in the future. Thanks!

Fixed in the latest force-push, adding common once before checking the type of requested output

lahma · 2023-04-24T16:44:33Z

So this might need some confirmation from the NUnit team, but by understanding, the TestProgressReporter seems to be called in sync fashion, so it should be safe to reuse the instance field for string builder. If this is not the case, thread-local or (thread-safe) pooled instance would be needed.

OsirisTerje · 2023-04-25T17:43:47Z

@lahma Some conflicts here now

lahma · 2023-04-25T18:20:09Z

Rebased, I believe these two of my PR will probably nicely conflict with each other so if either one gets merged, I'll rebase the other.

manfred-brands · 2023-04-26T11:41:30Z

@lahma I merged your other PR so could you resolve the merge conflicts in this one please?

lahma · 2023-04-26T12:04:08Z

@manfred-brands rebased and even got a green build!

lahma · 2023-04-26T16:27:23Z

I removed the TNode [ThreadStatic] StringBuilder as it was mostly now catering for first exploration of tests and didn't make sense to reuse. Other improvements via pooled StringBuilders from call sites do their magic well enough.

OsirisTerje · 2023-04-30T19:11:48Z

@manfred-brands @stevenaw Is this ready to be merged now? Any comments actually unresolved?

manfred-brands · 2023-05-01T00:42:59Z

@OsirisTerje I did not review as @stevenaw had some comments.

stevenaw

Thanks @lahma ! I've been revisiting this PR periodically hoping to have had the time to take it all in and process it. I think I've finally been able to give it the attention it deserves.

This looks great to me, thank you once again for the careful profiling. I've left one question requesting clarification from someone more in-the-know about the sealing of TestProgressListener and would appreciate a second pair of eyes in general, but overall this looks great ✅

stevenaw · 2023-05-01T00:18:28Z

src/NUnitFramework/framework/XmlExtensions.cs

+            if (text is null)
+                throw new ArgumentNullException(nameof(text));
+
+            text = EscapeInvalidXmlCharacters(text);


question: @lahma I noticed we added the call to EscapeInvalidXmlCharacters. Were there any other changes as part of moving this into an extensions file? It's tough to tell for sure

No other changes than ensuring the common fast path for "no need to encode anything".

stevenaw · 2023-05-01T00:19:40Z

src/NUnitFramework/framework/Internal/TestProgressReporter.cs

-                .Replace("'", "&apos;")
-                .Replace("<", "&lt;")
-                .Replace(">", "&gt;");
+            _stringBuilder.Clear();


stevenaw · 2023-05-01T00:20:47Z

src/NUnitFramework/framework/Internal/TestProgressReporter.cs

    {
-        static readonly Logger log = InternalTrace.GetLogger("TestProgressReporter");
+        private static readonly Logger log = InternalTrace.GetLogger("TestProgressReporter");


Thanks for making the visibility explicit

We should enable the StyleCop rule and do it for all fields.

I'm also partly confused about usage of regions (I personally don't like them) and braces (I usually always use them), maybe they could be part of the rule too if either one should not be used.

stevenaw · 2023-05-01T00:37:45Z

src/NUnitFramework/framework/Internal/TestProgressReporter.cs

@@ -11,19 +14,22 @@ namespace NUnit.Framework.Internal
    /// the async callbacks that are used to inform the client
    /// software about the progress of a test run.
    /// </summary>
-    public class TestProgressReporter : ITestListener
+    public sealed class TestProgressReporter : ITestListener


I understand how sealing a class can help performance, but I'm a little cautious about this one. I think ITestEventListener was removed as an extension point in the framework but is still an extension point within the engine. It's plausible that someone may've extended TestProgressReporter in their codebase to do this.
https://docs.nunit.org/articles/nunit-engine/extensions/creating-extensions/Event-Listeners.html?q=ITestListener

@OsirisTerje you have more experience at this level, but am I reading the docs right? I'm a little confused as we also have this, but I believe this page only indicates the removal as a framework extension point: https://docs.nunit.org/articles/nunit/technical-notes/usage/Addin-Replacement-in-the-Framework.html?q=ITestListener

Sorry for being a little late for the game. Would v4 be good time to seal (separate PR) all things that imaginable that doesn't break the current upstream (adapters, runners) and then if someone cries out just open in small point releases, opening sealed classes later isn't a breaking change but sealing too late is...

stevenaw · 2023-05-01T00:41:22Z

src/NUnitFramework/framework/Internal/TestProgressReporter.cs

+                writer.WriteAttributeStringSafe("fullname", test.FullName);
+                writer.WriteAttributeStringSafe("type", test.TestType);
+
+                if (isSuite)


Thank you 😄
I hadn't expected my earlier comment about this to make it into the PR but it's a welcome addition

stevenaw · 2023-05-01T00:52:39Z

@OsirisTerje I did not review as @stevenaw had some comments.

@manfred-brands seems we were both looking at this at the same time 😄 No obligation, but I'd appreciate a second pair of eyes if you're able.

manfred-brands

Only a tiny extra '!' null suppression operator that isn't needed.
I'll remove it on my next nullable change.

manfred-brands · 2023-05-01T11:20:10Z

src/NUnitFramework/framework/Internal/PropertyBag.cs

                {
                    TNode prop = properties.AddElement("property");

                    // TODO: Format as string
                    prop.AddAttribute("name", pair.Key);
-                    prop.AddAttribute("value", value.ToString()!);
+                    prop.AddAttribute("value", list[i]!.ToString()!);


Suggested change

prop.AddAttribute("value", list[i]!.ToString()!);

prop.AddAttribute("value", list[i].ToString()!);

list elements are not-null. Null suppression operator not needed.

manfred-brands · 2023-05-01T11:34:52Z

src/NUnitFramework/framework/Internal/TestProgressReporter.cs

    {
-        static readonly Logger log = InternalTrace.GetLogger("TestProgressReporter");
+        private static readonly Logger log = InternalTrace.GetLogger("TestProgressReporter");


We should enable the StyleCop rule and do it for all fields.

lahma marked this pull request as ready for review April 21, 2023 16:36

lahma marked this pull request as draft April 22, 2023 05:51

lahma mentioned this pull request Apr 23, 2023

Optimize WorkItemTracker nunit/nunit-console#1338

Merged

stevenaw reviewed Apr 23, 2023

View reviewed changes

lahma force-pushed the optimize-test-reporting branch from 3136660 to d874a5c Compare April 24, 2023 16:41

lahma marked this pull request as ready for review April 24, 2023 16:54

lahma force-pushed the optimize-test-reporting branch 2 times, most recently from 8e2762e to f5b0192 Compare April 25, 2023 06:15

OsirisTerje added the mergeconflicts This PR have merge conflicts label Apr 25, 2023

lahma force-pushed the optimize-test-reporting branch from f5b0192 to 26d6267 Compare April 25, 2023 18:14

lahma force-pushed the optimize-test-reporting branch 2 times, most recently from 4a5cdcb to 54b6f5e Compare April 26, 2023 05:20

lahma force-pushed the optimize-test-reporting branch from 54b6f5e to ba181eb Compare April 26, 2023 11:52

Optimize progress reporting by reusing StringBuilder

7579d15

lahma force-pushed the optimize-test-reporting branch from ba181eb to 7579d15 Compare April 26, 2023 16:26

OsirisTerje removed the mergeconflicts This PR have merge conflicts label Apr 30, 2023

stevenaw approved these changes May 1, 2023

View reviewed changes

manfred-brands approved these changes May 1, 2023

View reviewed changes

manfred-brands merged commit e0fcf96 into nunit:master May 1, 2023
5 checks passed

lahma deleted the optimize-test-reporting branch May 1, 2023 14:05

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Optimize progress reporting by reusing StringBuilder #4360

Optimize progress reporting by reusing StringBuilder #4360

lahma commented Apr 21, 2023 •

edited

stevenaw Apr 23, 2023

lahma Apr 24, 2023

lahma Apr 24, 2023

stevenaw Apr 23, 2023

lahma Apr 24, 2023

stevenaw Apr 23, 2023

lahma Apr 24, 2023

lahma commented Apr 24, 2023

OsirisTerje commented Apr 25, 2023

lahma commented Apr 25, 2023

manfred-brands commented Apr 26, 2023

lahma commented Apr 26, 2023

lahma commented Apr 26, 2023

OsirisTerje commented Apr 30, 2023

manfred-brands commented May 1, 2023

stevenaw left a comment

stevenaw May 1, 2023 •

edited

lahma May 1, 2023

stevenaw May 1, 2023

stevenaw May 1, 2023

manfred-brands May 1, 2023

lahma May 1, 2023

stevenaw May 1, 2023

lahma May 1, 2023

stevenaw May 1, 2023

stevenaw commented May 1, 2023

manfred-brands left a comment

manfred-brands May 1, 2023

manfred-brands May 1, 2023

	prop.AddAttribute("value", list[i]!.ToString()!);
	prop.AddAttribute("value", list[i].ToString()!);

Optimize progress reporting by reusing StringBuilder #4360

Optimize progress reporting by reusing StringBuilder #4360

Conversation

lahma commented Apr 21, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lahma commented Apr 24, 2023

OsirisTerje commented Apr 25, 2023

lahma commented Apr 25, 2023

manfred-brands commented Apr 26, 2023

lahma commented Apr 26, 2023

lahma commented Apr 26, 2023

OsirisTerje commented Apr 30, 2023

manfred-brands commented May 1, 2023

stevenaw left a comment

Choose a reason for hiding this comment

stevenaw May 1, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

stevenaw commented May 1, 2023

manfred-brands left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lahma commented Apr 21, 2023 •

edited

stevenaw May 1, 2023 •

edited