From 65e87e5aa97ffb05b484685b8274f8c6ae1870c6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Christian=20K=C3=B6llner?= Date: Tue, 21 Apr 2020 18:54:16 +0200 Subject: [PATCH] improved test design added perf. profiling for StrictlyOrderedAwaitTask --- Benchmarking/CapnpProfile/CapnpProfile.csproj | 4 +- .../Capnp.Net.Runtime.Tests.csproj | 4 + Capnp.Net.Runtime.Tests/TcpRpcStress.cs | 7 -- Capnp.Net.Runtime.Tests/Util/TestBase.cs | 39 ++++++--- Capnp.Net.Runtime/Capnp.Net.Runtime.csproj | 4 +- .../Util/StrictlyOrderedAwaitTask.cs | 80 ++++++++++++++++++- 6 files changed, 112 insertions(+), 26 deletions(-) diff --git a/Benchmarking/CapnpProfile/CapnpProfile.csproj b/Benchmarking/CapnpProfile/CapnpProfile.csproj index 5db3e9c..f3757eb 100644 --- a/Benchmarking/CapnpProfile/CapnpProfile.csproj +++ b/Benchmarking/CapnpProfile/CapnpProfile.csproj @@ -12,8 +12,8 @@ - - + + diff --git a/Capnp.Net.Runtime.Tests/Capnp.Net.Runtime.Tests.csproj b/Capnp.Net.Runtime.Tests/Capnp.Net.Runtime.Tests.csproj index 0b26467..0057a55 100644 --- a/Capnp.Net.Runtime.Tests/Capnp.Net.Runtime.Tests.csproj +++ b/Capnp.Net.Runtime.Tests/Capnp.Net.Runtime.Tests.csproj @@ -18,6 +18,10 @@ DEBUG;TRACE + + TRACE;SOTASK_PERF + + diff --git a/Capnp.Net.Runtime.Tests/TcpRpcStress.cs b/Capnp.Net.Runtime.Tests/TcpRpcStress.cs index b24095c..7424277 100644 --- a/Capnp.Net.Runtime.Tests/TcpRpcStress.cs +++ b/Capnp.Net.Runtime.Tests/TcpRpcStress.cs @@ -53,7 +53,6 @@ namespace Capnp.Net.Runtime.Tests public void Cancel() { var t = new TcpRpcPorted(); - t.InitConsoleLogging(); Repeat(1000, t.Cancel); } @@ -61,7 +60,6 @@ namespace Capnp.Net.Runtime.Tests public void Embargo() { var t = new TcpRpcPorted(); - t.InitConsoleLogging(); Repeat(100, () => NewLocalhostTcpTestbed(TcpRpcTestOptions.ClientTracer | TcpRpcTestOptions.ClientFluctStream) @@ -72,7 +70,6 @@ namespace Capnp.Net.Runtime.Tests public void EmbargoServer() { var t2 = new TcpRpcInterop(); - t2.InitConsoleLogging(); Repeat(20, t2.EmbargoServer); } @@ -82,11 +79,9 @@ namespace Capnp.Net.Runtime.Tests // Some code paths are really rare during this test, therefore increased repetition count. var t = new TcpRpcPorted(); - t.InitConsoleLogging(); Repeat(1000, t.EmbargoNull); var t2 = new TcpRpcInterop(); - t2.InitConsoleLogging(); Repeat(100, t2.EmbargoNullServer); } @@ -94,7 +89,6 @@ namespace Capnp.Net.Runtime.Tests public void RetainAndRelease() { var t = new TcpRpcPorted(); - t.InitConsoleLogging(); Repeat(100, t.RetainAndRelease); } @@ -102,7 +96,6 @@ namespace Capnp.Net.Runtime.Tests public void PipelineAfterReturn() { var t = new TcpRpc(); - t.InitConsoleLogging(); Repeat(100, t.PipelineAfterReturn); } diff --git a/Capnp.Net.Runtime.Tests/Util/TestBase.cs b/Capnp.Net.Runtime.Tests/Util/TestBase.cs index 443e660..bad16c0 100644 --- a/Capnp.Net.Runtime.Tests/Util/TestBase.cs +++ b/Capnp.Net.Runtime.Tests/Util/TestBase.cs @@ -1,5 +1,6 @@ using Capnp.Net.Runtime.Tests.Util; using Capnp.Rpc; +using Capnp.Util; using Microsoft.Extensions.Logging; using Microsoft.VisualStudio.TestTools.UnitTesting; using System; @@ -351,6 +352,32 @@ namespace Capnp.Net.Runtime.Tests protected ILogger Logger { get; set; } + protected TestBase() + { + Logging.LoggerFactory?.Dispose(); +#pragma warning disable CS0618 + Logging.LoggerFactory = new LoggerFactory().AddConsole((msg, level) => true); +#pragma warning restore CS0618 + Logger = Logging.CreateLogger(); + if (Thread.CurrentThread.Name == null) + Thread.CurrentThread.Name = $"Test Thread {Thread.CurrentThread.ManagedThreadId}"; + +#if SOTASK_PERF + StrictlyOrderedTaskExtensions.Stats.Reset(); +#endif + } + + [TestCleanup] + public void TestCleanup() + { +#if SOTASK_PERF + Console.WriteLine($"StrictlyOrderedTask performance statistics:"); + Console.WriteLine($"AwaitInternal: max. {StrictlyOrderedTaskExtensions.Stats.AwaitInternalMaxOuterIterations} outer iterations"); + Console.WriteLine($"AwaitInternal: max. {StrictlyOrderedTaskExtensions.Stats.AwaitInternalMaxInnerIterations} inner iterations"); + Console.WriteLine($"OnCompleted: max. {StrictlyOrderedTaskExtensions.Stats.OnCompletedMaxSpins} iterations"); +#endif + } + protected static TcpRpcClient SetupClient(IPAddress addr, int port, TcpRpcTestOptions options = TcpRpcTestOptions.None) { var client = new TcpRpcClient(); @@ -404,18 +431,6 @@ namespace Capnp.Net.Runtime.Tests protected static LocalTestbed NewLocalTestbed() => new LocalTestbed(); - [TestInitialize] - public void InitConsoleLogging() - { - Logging.LoggerFactory?.Dispose(); -#pragma warning disable CS0618 - Logging.LoggerFactory = new LoggerFactory().AddConsole((msg, level) => true); -#pragma warning restore CS0618 - Logger = Logging.CreateLogger(); - if (Thread.CurrentThread.Name == null) - Thread.CurrentThread.Name = $"Test Thread {Thread.CurrentThread.ManagedThreadId}"; - } - /// /// Somewhat ugly helper method which ensures that both Tcp client and server /// are waiting for data reception from each other. This is a "balanced" state, meaning diff --git a/Capnp.Net.Runtime/Capnp.Net.Runtime.csproj b/Capnp.Net.Runtime/Capnp.Net.Runtime.csproj index 4773820..0ec7854 100644 --- a/Capnp.Net.Runtime/Capnp.Net.Runtime.csproj +++ b/Capnp.Net.Runtime/Capnp.Net.Runtime.csproj @@ -33,7 +33,7 @@ - + SOTASK_PERF @@ -43,6 +43,6 @@ - + diff --git a/Capnp.Net.Runtime/Util/StrictlyOrderedAwaitTask.cs b/Capnp.Net.Runtime/Util/StrictlyOrderedAwaitTask.cs index 7567bf3..f86cf53 100644 --- a/Capnp.Net.Runtime/Util/StrictlyOrderedAwaitTask.cs +++ b/Capnp.Net.Runtime/Util/StrictlyOrderedAwaitTask.cs @@ -53,18 +53,37 @@ namespace Capnp.Util } finally { +#if SOTASK_PERF + long outerCount = 0, innerCount = 0; +#endif + SpinWait.SpinUntil(() => { Action? continuations; - do + + while (true) { +#if SOTASK_PERF + ++innerCount; +#endif + continuations = (Action?)Interlocked.Exchange(ref _state, null); - continuations?.Invoke(); - } while (continuations != null); + if (continuations != null) + continuations(); + else + break; + } +#if SOTASK_PERF + ++outerCount; +#endif return Interlocked.CompareExchange(ref _state, s_seal, null) == null; }); + +#if SOTASK_PERF + StrictlyOrderedTaskExtensions.Stats.UpdateAwaitInternal(outerCount, innerCount); +#endif } } @@ -75,7 +94,16 @@ namespace Capnp.Util { bool first = false; +#if SOTASK_PERF + long spinCount = 0; +#endif + SpinWait.SpinUntil(() => { + +#if SOTASK_PERF + ++spinCount; +#endif + object? cur, next; cur = Volatile.Read(ref _state); first = false; @@ -102,6 +130,10 @@ namespace Capnp.Util return Interlocked.CompareExchange(ref _state, next, cur) == cur; }); +#if SOTASK_PERF + StrictlyOrderedTaskExtensions.Stats.UpdateOnCompleted(spinCount); +#endif + if (first) { AwaitInternal(); @@ -168,6 +200,48 @@ namespace Capnp.Util /// public static class StrictlyOrderedTaskExtensions { +#if SOTASK_PERF + public class Statistics + { + internal long _awaitInternalMaxOuterIterations; + internal long _awaitInternalMaxInnerIterations; + internal long _onCompletedMaxSpins; + + public long AwaitInternalMaxOuterIterations => Volatile.Read(ref _awaitInternalMaxOuterIterations); + public long AwaitInternalMaxInnerIterations => Volatile.Read(ref _awaitInternalMaxInnerIterations); + public long OnCompletedMaxSpins => Volatile.Read(ref _onCompletedMaxSpins); + + public void Reset() + { + Volatile.Write(ref _awaitInternalMaxOuterIterations, 0); + Volatile.Write(ref _awaitInternalMaxInnerIterations, 0); + Volatile.Write(ref _onCompletedMaxSpins, 0); + } + + internal static void InterlockedMax(ref long current, long value) + { + long existing; + do + { + existing = Volatile.Read(ref current); + if (value <= existing) return; + } while (Interlocked.CompareExchange(ref current, value, existing) != existing); + } + + internal void UpdateAwaitInternal(long outerCount, long innerCount) + { + InterlockedMax(ref _awaitInternalMaxOuterIterations, outerCount); + InterlockedMax(ref _awaitInternalMaxInnerIterations, innerCount); + } + + internal void UpdateOnCompleted(long spinCount) + { + InterlockedMax(ref _onCompletedMaxSpins, spinCount); + } + } + + public static readonly Statistics Stats = new Statistics(); +#endif /// /// Converts the task to a task-like object which enforces that all await operations from the same thread leave in the exact order they were issued. ///