v1.5 logging (version 2) #6408

Aaronontheweb · 2023-02-15T21:53:57Z

Changes

Checklist

For significant changes, please ensure that the following have been completed (delete if not relevant):

This change follows the Akka.NET API Compatibility Guidelines.
This change follows the Akka.NET Wire Compatibility Guidelines.
I have reviewed my own pull request.
Design discussion issue [Draft] Semantic Logging Support #6394 (comment)
Changes in public API reviewed, if any.
I have added website documentation for this feature.

Latest `dev` Benchmarks

BenchmarkDotNet=v0.13.2, OS=Windows 10 (10.0.19044.2486/21H2/November2021Update)
AMD Ryzen 7 1700, 1 CPU, 16 logical and 8 physical cores
.NET SDK=7.0.100
  [Host]     : .NET 7.0.0 (7.0.22.51805), X64 RyuJIT AVX2
  Job-WCODYP : .NET 7.0.0 (7.0.22.51805), X64 RyuJIT AVX2

InvocationCount=1  UnrollFactor=1

Method	Mean	Error	StdDev	Median	Ratio	RatioSD	Gen0	Gen1	Gen2	Allocated	Alloc Ratio
LogInfoNoParams	163.2 ns	3.25 ns	8.22 ns	160.3 ns	1.00	0.00	0.0110	0.0060	0.0010	64 B	1.00
LogInfo1Params	383.5 ns	19.88 ns	58.61 ns	401.0 ns	2.36	0.39	0.0250	0.0120	-	160 B	2.50
LogInfo2Params	401.8 ns	9.62 ns	28.21 ns	410.3 ns	2.47	0.22	0.0300	0.0150	-	192 B	3.00
LogInfoWithException	164.6 ns	3.26 ns	7.62 ns	160.9 ns	1.01	0.07	0.0100	0.0050	-	64 B	1.00
LogInfoWithException1Params	383.3 ns	20.53 ns	60.52 ns	398.9 ns	2.36	0.38	0.0260	0.0130	0.0010	160 B	2.50
LogInfoWithException2Params	408.3 ns	9.78 ns	28.82 ns	416.9 ns	2.51	0.22	0.0300	0.0150	-	192 B	3.00

This PR's Benchmarks

Include data from after this change here.

…methods

had to add missing `Akka.Event` namespace reference

Aaronontheweb · 2023-02-15T21:54:26Z

Going to run some benchmark numbers before I start calling the generic methods we support

Aaronontheweb · 2023-02-15T22:53:29Z

Current version's benchmarks - which is more or less performing the same work under the hood that the dev branch is doing:

BenchmarkDotNet=v0.13.2, OS=Windows 10 (10.0.19044.2604/21H2/November2021Update)
AMD Ryzen 7 1700, 1 CPU, 16 logical and 8 physical cores
.NET SDK=7.0.100
  [Host]     : .NET 7.0.0 (7.0.22.51805), X64 RyuJIT AVX2
  Job-KJHKWD : .NET 7.0.0 (7.0.22.51805), X64 RyuJIT AVX2

InvocationCount=1  UnrollFactor=1

Method	Mean	Error	StdDev	Median	Ratio	RatioSD	Gen0	Gen1	Gen2	Allocated	Alloc Ratio
LogInfoNoParams	169.9 ns	3.39 ns	7.73 ns	166.5 ns	1.00	0.00	0.0100	0.0050	-	64 B	1.00
LogInfo1Params	389.3 ns	20.87 ns	61.53 ns	388.4 ns	2.30	0.38	0.0250	0.0120	-	160 B	2.50
LogInfo2Params	408.1 ns	8.14 ns	23.86 ns	412.6 ns	2.41	0.19	0.0310	0.0160	0.0010	192 B	3.00
LogInfoWithException	169.1 ns	3.38 ns	8.47 ns	164.6 ns	1.00	0.08	0.0110	0.0060	0.0010	64 B	1.00
LogInfoWithException1Params	392.6 ns	20.44 ns	60.28 ns	397.0 ns	2.32	0.37	0.0260	0.0130	0.0010	160 B	2.50
LogInfoWithException2Params	409.2 ns	8.17 ns	23.45 ns	423.7 ns	2.41	0.18	0.0310	0.0160	0.0010	192 B	3.00

Aaronontheweb · 2023-02-16T02:53:56Z

Changed all method calls to use our new generic overloads (I'll need to compare before / after .DLL sizes to make sure we haven't done anything evil there) - performance for logging calls is basically now bounded at 260ish nanoseconds for up to 6 parameters.

BenchmarkDotNet=v0.13.2, OS=Windows 10 (10.0.19044.2604/21H2/November2021Update)
AMD Ryzen 7 1700, 1 CPU, 16 logical and 8 physical cores
.NET SDK=7.0.100
  [Host]     : .NET 7.0.0 (7.0.22.51805), X64 RyuJIT AVX2
  Job-PCKFPT : .NET 7.0.0 (7.0.22.51805), X64 RyuJIT AVX2

InvocationCount=1  UnrollFactor=1

Method	Mean	Error	StdDev	Median	Ratio	RatioSD	Gen0	Gen1	Gen2	Allocated	Alloc Ratio
LogInfoNoParams	169.9 ns	3.36 ns	7.31 ns	166.5 ns	1.00	0.00	0.0110	0.0060	0.0010	64 B	1.00
LogInfo1Params	260.7 ns	7.95 ns	23.44 ns	262.0 ns	1.54	0.16	0.0170	0.0090	0.0010	104 B	1.62
LogInfo2Params	261.1 ns	7.81 ns	23.02 ns	258.5 ns	1.54	0.15	0.0170	0.0090	0.0010	104 B	1.62
LogInfoWithException	164.6 ns	3.29 ns	7.22 ns	160.7 ns	0.97	0.03	0.0100	0.0050	-	64 B	1.00
LogInfoWithException1Params	266.7 ns	8.59 ns	25.34 ns	277.1 ns	1.58	0.17	0.0170	0.0090	0.0010	104 B	1.62
LogInfoWithException2Params	268.4 ns	8.34 ns	24.58 ns	277.8 ns	1.60	0.16	0.0170	0.0090	0.0010	104 B	1.62

Aaronontheweb · 2023-02-16T04:09:55Z

Moved all generic methods out of the ILoggingAdapter interface and onto extension methods instead. Simplified the surface area of the ILoggingAdapter significantly so it can be extended in the next phase of this logging overhaul. Had to expose the ILogFormatter on the API in order to do this.

Now down to about 240 ns.

BenchmarkDotNet=v0.13.2, OS=Windows 10 (10.0.19044.2604/21H2/November2021Update)
AMD Ryzen 7 1700, 1 CPU, 16 logical and 8 physical cores
.NET SDK=7.0.100
  [Host]     : .NET 7.0.0 (7.0.22.51805), X64 RyuJIT AVX2
  Job-MAIQQP : .NET 7.0.0 (7.0.22.51805), X64 RyuJIT AVX2

InvocationCount=1  UnrollFactor=1

Method	Mean	Error	StdDev	Median	Ratio	RatioSD	Gen0	Gen1	Gen2	Allocated	Alloc Ratio
LogInfoNoParams	163.6 ns	3.24 ns	7.70 ns	159.3 ns	1.00	0.00	0.0100	0.0050	-	64 B	1.00
LogInfo1Params	243.7 ns	8.28 ns	24.42 ns	245.5 ns	1.50	0.17	0.0170	0.0090	0.0010	104 B	1.62
LogInfo2Params	237.8 ns	8.40 ns	24.76 ns	247.3 ns	1.45	0.16	0.0170	0.0090	0.0010	104 B	1.62
LogInfoWithException	164.3 ns	3.28 ns	7.26 ns	160.4 ns	1.01	0.06	0.0100	0.0050	-	64 B	1.00
LogInfoWithException1Params	245.2 ns	8.33 ns	24.55 ns	256.2 ns	1.51	0.17	0.0170	0.0090	0.0010	104 B	1.62
LogInfoWithException2Params	246.5 ns	8.05 ns	23.73 ns	254.0 ns	1.51	0.17	0.0170	0.0090	0.0010	104 B	1.62

Aaronontheweb · 2023-02-16T04:19:04Z

@Arkatufus does this mean I killed the multi-node testkit?

[ERROR][02/16/2023 04:11:46.329][Thread 0015][akka://TestRunnerLogging/user/TcpLogger] Method not found: 'Void Akka.Event.ILoggingAdapter.Info(System.String, System.Object[])'.

Aaronontheweb

Detailed my changes, their rationales, and their benefits.

Aaronontheweb · 2023-02-16T04:21:31Z

src/contrib/testkits/Akka.TestKit.Xunit/Internals/Loggers.cs

@@ -48,7 +48,7 @@ private void Write(LogEvent e)
                if (e.Message is LogMessage msg)
                {
                    var message =
-                        $"Received a malformed formatted message. Log level: [{e.LogLevel()}], Template: [{msg.Format}], args: [{string.Join(",", msg.Args)}]";
+                        $"Received a malformed formatted message. Log level: [{e.LogLevel()}], Template: [{msg.Format}], args: [{string.Join(",", msg.Unformatted())}]";


We now have a standard method on LogMessage called Unformatted() which returns the non-formatted string contents of the payload. This is designed for troubleshooting format exceptions that occur in user / system log statements akin to what we have in 1.4.

Aaronontheweb · 2023-02-16T04:22:19Z

src/contrib/dependencyinjection/Akka.DependencyInjection/DependencyResolverSetup.cs

@@ -46,7 +47,7 @@ public static ServiceProviderSetup Create(IServiceProvider provider)
    /// The <see cref="IDependencyResolver"/> will be used to access previously registered services
    /// in the creation of actors and other pieces of infrastructure inside Akka.NET.
    ///
-    /// The constructor is internal. Please use <see cref="Create"/> to create a new instance.
+    /// The constructor is internal. Please use <see cref="Dispatch.SysMsg.Create"/> to create a new instance.


This is wrong and needs to be updated - I think I ReSharper'd this when I was trying to add using Akka.Event everywhere it was needed.

Aaronontheweb · 2023-02-16T04:23:14Z

src/contrib/cluster/Akka.Cluster.Sharding/ClusterSharding.cs

@@ -1383,7 +1384,7 @@ public IActorRef ShardRegion(string typeName)
        /// Retrieve the actor reference of the <see cref="Sharding.ShardRegion"/> actor that will act as a proxy to the
        /// named entity type running in another data center. A proxy within the same data center can be accessed
        /// with <see cref="Sharding.ShardRegion"/> instead of this method. The entity type must be registered with the
-        /// <see cref="StartProxy"/> method before it can be used here. Messages to the entity is always sent
+        /// <see cref="ClusterShardingGuardian.StartProxy"/> method before it can be used here. Messages to the entity is always sent


All of these ClusterShardingGuardian calls are wrong as well - I think this was a ReSharper'ing issue. I'll fix these.

Aaronontheweb · 2023-02-16T04:23:59Z

src/benchmark/Akka.Benchmarks/Logging/LoggingBenchmarks.cs

-
-            private void AddLogMessage(LogEvent m)
+
+            private LogEvent CreateLogEvent(LogLevel logLevel, object message, Exception cause = null)


Had to update the test logger in order to support the API changes made to ILoggingAdapter.

src/core/Akka.Streams/Dsl/Internal/InternalFlowOperations.cs

Aaronontheweb · 2023-02-16T04:54:57Z

src/core/Akka/Event/LogMessage.cs

+            Arg = arg;
+        }
+
+        public T Arg { get; }


Generic argument for the type of object that can be formatted - remember the generic constraint: must support IEnumerable<object>.

Aaronontheweb · 2023-02-16T04:55:17Z

src/core/Akka/Event/LogMessage.cs

+    /// <summary>
+    /// Works akin to the original <see cref="LogMessage"/> class with an array of objects as the format args.
+    /// </summary>
+    internal sealed class DefaultLogMessage : LogMessage


This is the type we use for handling old object[] calls on the logging APIs.

Aaronontheweb · 2023-02-16T04:59:24Z

src/core/Akka/Event/LogMessage.cs

+
+    internal readonly struct LogValues<T1, T2> : IReadOnlyList<object>
+    {
+        private readonly T1 _value1;


We don't allocate any arrays internally - rather we produce an IEnumerable<object> on-demand when the object is being read for formatting, rather than when it's originally allocated. This is the raison d'être for this entire design: defer allocations so they're out of the critical path of /user and /system actors.

We have 6 different generic versions of this readonly struct - each one uses the same technique to prevent allocations and the benchmarks demonstrate how this works.

Aaronontheweb · 2023-02-16T05:00:46Z

src/core/Akka/Event/ILoggingAdapter.cs

-        /// <param name="format">The message that is being logged.</param>
-        /// <param name="args">An optional list of items used to format the message.</param>
-        public void Info(string format, params object[] args) { }
+        void Log(LogLevel logLevel, Exception cause, LogMessage message);


ILoggingAdapter only supports two direct logging calls now:

void Log(LogLevel logLevel, Exception cause, LogMessage message); void Log(LogLevel logLevel, Exception cause, string format);

Everything else is inputted via the extension methods earlier in the file.

Aaronontheweb · 2023-02-16T05:01:43Z

src/core/Akka/Util/Reflection/ExpressionExtensions.cs

@@ -110,12 +110,11 @@ internal static class ExpressionBasedParser
                        }
                    }
                }
-                catch (Exception exception)


Fixed some compilation warnings here.

Aaronontheweb · 2023-02-16T05:05:24Z

Minus the issues with the MNTR, test suite passes.

I'm going to need to fix a few other issues found in this PR as well.

As for documentation - we'll need to document these changes in the https://github.com/akkadotnet/akka.net/blob/dev/docs/community/whats-new/akkadotnet-v1.5-upgrade-advisories.md area

Aaronontheweb · 2023-02-17T15:24:32Z

src/core/Akka/Event/ILoggingAdapter.cs

+        // /// <param name="logLevel">The level used to log the message.</param>
+        // /// <param name="format">The message that is being logged.</param>
+        // /// <param name="args">An optional list of items used to format the message.</param>
+        // void Log(LogLevel logLevel, string format, params object[] args);


Need to delete this (can do in later PR)

Arkatufus

LGTM

Microsoft does have their own class called FormattableString for these, but I think its too convoluted because it has to handle culture as well. This implementation should be better for our use case.

Aaronontheweb · 2023-02-17T21:18:51Z

Microsoft does have their own class called FormattableString for these, but I think its too convoluted because it has to handle culture as well. This implementation should be better for our use case.

When we start work on 1.6, at which point I'm thinking we'll ditch .NET Standard 2.0 and go full-bore on .NET 7/8, we can start taking advantage of some of these newer APIs.

Aaronontheweb · 2023-02-17T21:20:09Z

Ok, going nuclear on API changes for Akka.NET v1.5 starting now ;)

Aaronontheweb added 4 commits February 15, 2023 15:22

reworking the guts of the logging system

d9518bf

fixing compilation errors resulting from conversion to new extension …

21fbdcb

…methods

fixing more compilation issues

27d28b8

had to add missing `Akka.Event` namespace reference

fixed final compilation errors

dd1e80b

Aaronontheweb added 2 commits February 15, 2023 20:44

added static methods for all event calls

fb1b763

Merge branch 'dev' into semantic-logging

abda9db

Aaronontheweb added 2 commits February 15, 2023 21:47

simplified ILoggingAdapter API

f88c304

added API approvals

51d03b9

Aaronontheweb commented Feb 16, 2023

View reviewed changes

Aaronontheweb marked this pull request as ready for review February 16, 2023 05:05

Aaronontheweb added logging api-change perf labels Feb 16, 2023

Aaronontheweb added 3 commits February 16, 2023 07:42

fixed erroneous ReSharperisms

40fed72

added docs

bc4e844

fix typos and markdown linting

d0e20aa

Aaronontheweb added this to the 1.5.0 milestone Feb 16, 2023

Aaronontheweb requested a review from Arkatufus February 16, 2023 20:13

Aaronontheweb commented Feb 17, 2023

View reviewed changes

Arkatufus approved these changes Feb 17, 2023

View reviewed changes

Aaronontheweb merged commit 8fb39e5 into akkadotnet:dev Feb 17, 2023

Aaronontheweb deleted the semantic-logging branch February 17, 2023 21:20

Aaronontheweb mentioned this pull request Feb 20, 2023

Akka.NET v1.5.0-beta1 Release notes #6416

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

v1.5 logging (version 2) #6408

v1.5 logging (version 2) #6408

Aaronontheweb commented Feb 15, 2023 •

edited

Loading

Aaronontheweb commented Feb 15, 2023

Aaronontheweb commented Feb 15, 2023

Aaronontheweb commented Feb 16, 2023

Aaronontheweb commented Feb 16, 2023

Aaronontheweb commented Feb 16, 2023

Aaronontheweb left a comment

Aaronontheweb Feb 16, 2023

Aaronontheweb Feb 16, 2023

Aaronontheweb Feb 16, 2023

Aaronontheweb Feb 16, 2023

Aaronontheweb Feb 16, 2023

Aaronontheweb Feb 16, 2023

Aaronontheweb Feb 16, 2023

Aaronontheweb Feb 16, 2023

Aaronontheweb Feb 16, 2023

Aaronontheweb commented Feb 16, 2023

Aaronontheweb Feb 17, 2023

Arkatufus left a comment

Aaronontheweb commented Feb 17, 2023

Aaronontheweb commented Feb 17, 2023


		private void AddLogMessage(LogEvent m)

		private LogEvent CreateLogEvent(LogLevel logLevel, object message, Exception cause = null)

v1.5 logging (version 2) #6408

v1.5 logging (version 2) #6408

Conversation

Aaronontheweb commented Feb 15, 2023 • edited Loading

Changes

Checklist

Latest dev Benchmarks

This PR's Benchmarks

Aaronontheweb commented Feb 15, 2023

Aaronontheweb commented Feb 15, 2023

Aaronontheweb commented Feb 16, 2023

Aaronontheweb commented Feb 16, 2023

Aaronontheweb commented Feb 16, 2023

Aaronontheweb left a 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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Aaronontheweb commented Feb 16, 2023

Choose a reason for hiding this comment

Arkatufus left a comment

Choose a reason for hiding this comment

Aaronontheweb commented Feb 17, 2023

Aaronontheweb commented Feb 17, 2023

Aaronontheweb commented Feb 15, 2023 •

edited

Loading

Latest `dev` Benchmarks