Skip to content

Commit 4d6b8af

Browse files
trgiangvtrgiangv
committed
feat(benchmark): add latency and throughput benchmarks for ZLogger and Serilog
- Implement latency benchmarks to measure end-to-end logging performance - Add throughput benchmarks to evaluate message processing rates - Include memory allocation benchmarks to assess heap usage during logging - Create rendering benchmarks to test UI performance with RTF rendering
1 parent 4243248 commit 4d6b8af

39 files changed

Lines changed: 7574 additions & 112 deletions

File tree

‎Directory.Packages.props‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -34,5 +34,9 @@
3434
<PackageVersion Include="Microsoft.NET.Test.Sdk" Version="18.0.1" />
3535
<PackageVersion Include="Moq" Version="4.20.72" />
3636
<PackageVersion Include="coverlet.collector" Version="6.0.4" />
37+
<!--Benchmark-->
38+
<PackageVersion Include="BenchmarkDotNet" Version="0.15.8" />
39+
<PackageVersion Include="BenchmarkDotNet.Diagnostics.Windows" Version="0.15.8" />
40+
<PackageVersion Include="Microsoft.Extensions.Logging" Version="10.0.1" />
3741
</ItemGroup>
3842
</Project>

‎RevitDevTool.sln‎

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,8 @@ Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "ZLogger.RichTextBox.Winform
3232
EndProject
3333
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "ZLogger.RichTextBox.Winforms.Test", "source\ZLogger.RichTextBox.Winforms.Test\ZLogger.RichTextBox.Winforms.Test.csproj", "{4F28080D-268B-42CB-B36D-C25B61E6631C}"
3434
EndProject
35+
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "ZLogger.RichTextBox.Winforms.Benchmark", "source\ZLogger.RichTextBox.Winforms.Benchmark\ZLogger.RichTextBox.Winforms.Benchmark.csproj", "{E306B2C3-50BA-454F-8225-AE5EAC05FC62}"
36+
EndProject
3537
Global
3638
GlobalSection(SolutionConfigurationPlatforms) = preSolution
3739
Debug R21|x64 = Debug R21|x64
@@ -214,6 +216,30 @@ Global
214216
{4F28080D-268B-42CB-B36D-C25B61E6631C}.Release R25|x64.Build.0 = Release R25|Any CPU
215217
{4F28080D-268B-42CB-B36D-C25B61E6631C}.Release R26|x64.ActiveCfg = Release R26|Any CPU
216218
{4F28080D-268B-42CB-B36D-C25B61E6631C}.Release R26|x64.Build.0 = Release R26|Any CPU
219+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Debug R21|x64.ActiveCfg = Debug R21|Any CPU
220+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Debug R21|x64.Build.0 = Debug R21|Any CPU
221+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Debug R22|x64.ActiveCfg = Debug R22|Any CPU
222+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Debug R22|x64.Build.0 = Debug R22|Any CPU
223+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Debug R23|x64.ActiveCfg = Debug R23|Any CPU
224+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Debug R23|x64.Build.0 = Debug R23|Any CPU
225+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Debug R24|x64.ActiveCfg = Debug R24|Any CPU
226+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Debug R24|x64.Build.0 = Debug R24|Any CPU
227+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Debug R25|x64.ActiveCfg = Debug R25|Any CPU
228+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Debug R25|x64.Build.0 = Debug R25|Any CPU
229+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Debug R26|x64.ActiveCfg = Debug R26|Any CPU
230+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Debug R26|x64.Build.0 = Debug R26|Any CPU
231+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Release R21|x64.ActiveCfg = Release R21|Any CPU
232+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Release R21|x64.Build.0 = Release R21|Any CPU
233+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Release R22|x64.ActiveCfg = Release R22|Any CPU
234+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Release R22|x64.Build.0 = Release R22|Any CPU
235+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Release R23|x64.ActiveCfg = Release R23|Any CPU
236+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Release R23|x64.Build.0 = Release R23|Any CPU
237+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Release R24|x64.ActiveCfg = Release R24|Any CPU
238+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Release R24|x64.Build.0 = Release R24|Any CPU
239+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Release R25|x64.ActiveCfg = Release R25|Any CPU
240+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Release R25|x64.Build.0 = Release R25|Any CPU
241+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Release R26|x64.ActiveCfg = Release R26|Any CPU
242+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62}.Release R26|x64.Build.0 = Release R26|Any CPU
217243
EndGlobalSection
218244
GlobalSection(SolutionProperties) = preSolution
219245
HideSolutionNode = FALSE
@@ -224,5 +250,6 @@ Global
224250
{88E2CD4B-C261-481F-9107-12A39E604858} = {B8EFCA5F-814F-285C-A8CB-F00F14650265}
225251
{506A15B9-E4A1-49E7-8B6C-E528C0BE855B} = {B8EFCA5F-814F-285C-A8CB-F00F14650265}
226252
{4F28080D-268B-42CB-B36D-C25B61E6631C} = {B8EFCA5F-814F-285C-A8CB-F00F14650265}
253+
{E306B2C3-50BA-454F-8225-AE5EAC05FC62} = {B8EFCA5F-814F-285C-A8CB-F00F14650265}
227254
EndGlobalSection
228255
EndGlobal

‎source/RevitDevTool.Test/Log.cs‎

Lines changed: 25 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,7 @@ public override void Execute()
2323
Debug.WriteLine($"Critical failure in Step {stepNumber:000}");
2424
}
2525
stopwatch.Stop();
26-
Debug.WriteLine($"Total processing time: {stopwatch.ElapsedMilliseconds} ms");
26+
Trace.TraceWarning($"Total processing time: {stopwatch.ElapsedMilliseconds} ms");
2727
});
2828
}
2929
}
@@ -48,7 +48,7 @@ public override void Execute()
4848
Trace.WriteLine($"Critical failure in Step {stepNumber:000}");
4949
}
5050
stopwatch.Stop();
51-
Trace.WriteLine($"Total processing time: {stopwatch.ElapsedMilliseconds} ms");
51+
Trace.TraceWarning($"Total processing time: {stopwatch.ElapsedMilliseconds} ms");
5252
});
5353
}
5454
}
@@ -73,19 +73,40 @@ public override void Execute()
7373
Console.WriteLine($"Critical failure in Step {stepNumber:000}");
7474
}
7575
stopwatch.Stop();
76-
Console.WriteLine($"Total processing time: {stopwatch.ElapsedMilliseconds} ms");
76+
Trace.TraceWarning($"Total processing time: {stopwatch.ElapsedMilliseconds} ms");
7777
});
7878
}
7979
}
8080

8181
[UsedImplicitly]
8282
[Transaction(TransactionMode.Manual)]
83-
public class TraceColoredCmd : ExternalCommand
83+
public class BatchTraceColoredCmd : ExternalCommand
8484
{
8585
public override void Execute()
8686
{
8787
Trace.TraceInformation("This is an informational message.");
8888
Trace.TraceWarning("This is a warning message.");
8989
Trace.TraceError("This is an error message.");
9090
}
91+
}
92+
93+
[UsedImplicitly]
94+
[Transaction(TransactionMode.Manual)]
95+
public class BatchDebugLargeStringCmd : ExternalCommand
96+
{
97+
public override void Execute()
98+
{
99+
Task.Run(() =>
100+
{
101+
var stopwatch = Stopwatch.StartNew();
102+
stopwatch.Start();
103+
var largeString = new string('X', 1000);
104+
for (var i = 0; i < 1000; i++)
105+
{
106+
Debug.WriteLine(largeString);
107+
}
108+
stopwatch.Stop();
109+
Trace.TraceWarning($"Total time for large string logging: {stopwatch.ElapsedMilliseconds} ms");
110+
});
111+
}
91112
}

‎source/RevitDevTool/Host.cs‎

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@
22
using Microsoft.Extensions.Hosting;
33
using RevitDevTool.Controllers;
44
using RevitDevTool.Logging;
5+
using RevitDevTool.Logging.Serilog;
56
using RevitDevTool.Logging.ZLogger;
67
using RevitDevTool.Services;
78
using RevitDevTool.Services.Configuration;
@@ -61,14 +62,14 @@ private static void ConfigureServices(IServiceCollection services)
6162
services.AddHostedService<HostBackgroundController>();
6263

6364
// Serilog
64-
// services.AddSingleton<ILoggerFactory, SerilogLoggerFactory>();
65-
// services.AddSingleton<ITraceListenerFactory, SerilogTraceListenerFactory>();
66-
// services.AddSingleton<ILogOutputSink, SerilogRichTextBoxSink>();
65+
services.AddSingleton<ILoggerFactory, SerilogLoggerFactory>();
66+
services.AddSingleton<ITraceListenerFactory, SerilogTraceListenerFactory>();
67+
services.AddSingleton<ILogOutputSink, SerilogRichTextBoxSink>();
6768

6869
// ZLogger
69-
services.AddSingleton<ILoggerFactory, ZLoggerLoggerFactory>();
70-
services.AddSingleton<ITraceListenerFactory, ZLoggerTraceListenerFactory>();
71-
services.AddSingleton<ILogOutputSink, ZloggerRichTextBoxSink>();
70+
// services.AddSingleton<ILoggerFactory, ZLoggerLoggerFactory>();
71+
// services.AddSingleton<ITraceListenerFactory, ZLoggerTraceListenerFactory>();
72+
// services.AddSingleton<ILogOutputSink, ZloggerRichTextBoxSink>();
7273

7374
// Logging service
7475
services.AddSingleton<ILoggingService, LoggingService>();

‎source/RevitDevTool/Models/Trace/ConsoleRedirector.cs‎

Lines changed: 2 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -46,23 +46,19 @@ public override void Write(string? value)
4646
switch (eventType)
4747
{
4848
case TraceEventType.Error:
49-
case TraceEventType.Critical:
5049
System.Diagnostics.Trace.TraceError(value);
5150
break;
51+
case TraceEventType.Critical:
5252
case TraceEventType.Warning:
53-
System.Diagnostics.Trace.TraceWarning(value);
54-
break;
5553
case TraceEventType.Information:
56-
System.Diagnostics.Trace.TraceInformation(value);
57-
break;
5854
case TraceEventType.Verbose:
5955
case TraceEventType.Start:
6056
case TraceEventType.Stop:
6157
case TraceEventType.Suspend:
6258
case TraceEventType.Resume:
6359
case TraceEventType.Transfer:
6460
default:
65-
System.Diagnostics.Trace.WriteLine(value);
61+
Debug.WriteLine(value);
6662
break;
6763
}
6864
}

‎source/RevitDevTool/Theme/ThemeResources.cs‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -99,6 +99,7 @@ private void UpdateDesignTimeThemeDictionary()
9999
EnsureDarkResources();
100100
UpdateTo(_darkResources!);
101101
break;
102+
case AppTheme.Auto:
102103
default:
103104
EnsureLightResources();
104105
UpdateTo(_lightResources!);

‎source/ZLogger.RichTextBox.Winforms.Benchmark/BenchmarkConfig.cs‎

Lines changed: 48 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,48 @@
1+
using BenchmarkDotNet.Configs;
2+
using BenchmarkDotNet.Environments;
3+
using BenchmarkDotNet.Jobs;
4+
using BenchmarkDotNet.Toolchains.InProcess.Emit;
5+
6+
namespace ZLogger.RichTextBox.Winforms.Benchmark;
7+
8+
/// <summary>
9+
/// Custom BenchmarkDotNet configuration for Windows Forms projects.
10+
/// Uses InProcess toolchain to avoid net8.0-windows compatibility issues.
11+
/// </summary>
12+
public class WindowsFormsConfig : ManualConfig
13+
{
14+
public WindowsFormsConfig()
15+
{
16+
// Use InProcess toolchain - runs benchmarks in the same process
17+
// This avoids BenchmarkDotNet generating incompatible projects for net8.0-windows
18+
AddJob(Job.Default
19+
.WithRuntime(CoreRuntime.Core80)
20+
.WithToolchain(InProcessEmitToolchain.Instance)
21+
.WithId("InProcess"));
22+
23+
// Add default exporters and analyzers
24+
AddLogger(BenchmarkDotNet.Loggers.ConsoleLogger.Default);
25+
AddColumnProvider(BenchmarkDotNet.Columns.DefaultColumnProviders.Instance);
26+
AddExporter(BenchmarkDotNet.Exporters.MarkdownExporter.GitHub);
27+
AddExporter(BenchmarkDotNet.Exporters.HtmlExporter.Default);
28+
}
29+
}
30+
31+
/// <summary>
32+
/// Short run config for quick testing (not for final results)
33+
/// </summary>
34+
public class QuickConfig : ManualConfig
35+
{
36+
public QuickConfig()
37+
{
38+
AddJob(Job.Default
39+
.WithRuntime(CoreRuntime.Core80)
40+
.WithToolchain(InProcessEmitToolchain.Instance)
41+
.WithWarmupCount(1)
42+
.WithIterationCount(3)
43+
.WithId("Quick"));
44+
45+
AddLogger(BenchmarkDotNet.Loggers.ConsoleLogger.Default);
46+
AddColumnProvider(BenchmarkDotNet.Columns.DefaultColumnProviders.Instance);
47+
}
48+
}

‎source/ZLogger.RichTextBox.Winforms.Benchmark/BenchmarkDotNet.Artifacts/BenchmarkRun-20260114-022005.log‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,9 @@
1+
// Validating benchmarks:
2+
// * Assembly ZLogger.RichTextBox.Winforms.Benchmark which defines benchmarks references non-optimized ZLogger.RichTextBox.Winforms
3+
If you own this dependency, please, build it in RELEASE.
4+
If you don't, you can disable this policy by using 'config.WithOptions(ConfigOptions.DisableOptimizationsValidator)'.
5+
6+
// * Assembly ZLogger.RichTextBox.Winforms.Benchmark which defines benchmarks is non-optimized
7+
Benchmark was built without optimization enabled (most probably a DEBUG configuration). Please, build it in RELEASE.
8+
If you want to debug the benchmarks, please see https://benchmarkdotnet.org/articles/guides/troubleshooting.html#debugging-benchmarks.
9+

‎source/ZLogger.RichTextBox.Winforms.Benchmark/BenchmarkDotNet.Artifacts/BenchmarkRun-20260114-022029.log‎

Lines changed: 84 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,84 @@
1+
// Validating benchmarks:
2+
// ***** BenchmarkRunner: Start *****
3+
// ***** Found 82 benchmark(s) in total *****
4+
// ***** Building 1 exe(s) in Parallel: Start *****
5+
// start dotnet restore --nodeReuse:false /p:UseSharedCompilation=false /p:Deterministic=true /p:Optimize=true /p:ArtifactsPath="C:\Users\truon\source\repos\RevitDevTool\source\ZLogger.RichTextBox.Winforms.Benchmark\bin\Release\net8.0-windows\.NET 8.0-1/" /p:OutDir="C:\Users\truon\source\repos\RevitDevTool\source\ZLogger.RichTextBox.Winforms.Benchmark\bin\Release\net8.0-windows\.NET 8.0-1\bin\Release\net8.0/" /p:OutputPath="C:\Users\truon\source\repos\RevitDevTool\source\ZLogger.RichTextBox.Winforms.Benchmark\bin\Release\net8.0-windows\.NET 8.0-1\bin\Release\net8.0/" /p:PublishDir="C:\Users\truon\source\repos\RevitDevTool\source\ZLogger.RichTextBox.Winforms.Benchmark\bin\Release\net8.0-windows\.NET 8.0-1\publish/" in C:\Users\truon\source\repos\RevitDevTool\source\ZLogger.RichTextBox.Winforms.Benchmark\bin\Release\net8.0-windows\.NET 8.0-1
6+
// command took 0.75 sec and exited with 1
7+
// ***** Done, took 00:00:00 (0.84 sec) *****
8+
// Found 8 benchmarks:
9+
// LatencyBenchmark.'Serilog Latency': .NET 8.0(Runtime=.NET 8.0) [SampleCount=100]
10+
// LatencyBenchmark.'ZLogger Latency': .NET 8.0(Runtime=.NET 8.0) [SampleCount=100]
11+
// LatencyBenchmark.'Serilog Burst Latency': .NET 8.0(Runtime=.NET 8.0) [SampleCount=100]
12+
// LatencyBenchmark.'ZLogger Burst Latency': .NET 8.0(Runtime=.NET 8.0) [SampleCount=100]
13+
// LatencyBenchmark.'Serilog Latency': .NET 8.0(Runtime=.NET 8.0) [SampleCount=1000]
14+
// LatencyBenchmark.'ZLogger Latency': .NET 8.0(Runtime=.NET 8.0) [SampleCount=1000]
15+
// LatencyBenchmark.'Serilog Burst Latency': .NET 8.0(Runtime=.NET 8.0) [SampleCount=1000]
16+
// LatencyBenchmark.'ZLogger Burst Latency': .NET 8.0(Runtime=.NET 8.0) [SampleCount=1000]
17+
18+
Setup power plan (GUID: 8c5e7fda-e8bf-4a96-9a85-a6e23a8c635c FriendlyName: High performance)
19+
// Build Error: Standard output:
20+
21+
Standard error:
22+
Determining projects to restore...
23+
C:\Users\truon\source\repos\RevitDevTool\source\ZLogger.RichTextBox.Winforms.Benchmark\bin\Release\net8.0-windows\.NET 8.0-1\BenchmarkDotNet.Autogenerated.csproj : error NU1201: Project ZLogger.RichTextBox.Winforms.Benchmark is not compatible with net8.0 (.NETCoreApp,Version=v8.0). Project ZLogger.RichTextBox.Winforms.Benchmark supports: net8.0-windows7.0 (.NETCoreApp,Version=v8.0)
24+
Failed to restore C:\Users\truon\source\repos\RevitDevTool\source\ZLogger.RichTextBox.Winforms.Benchmark\bin\Release\net8.0-windows\.NET 8.0-1\BenchmarkDotNet.Autogenerated.csproj (in 61 ms).
25+
Restored C:\Users\truon\source\repos\RevitDevTool\source\ZLogger.RichTextBox.Winforms\ZLogger.RichTextBox.Winforms.csproj (in 179 ms).
26+
Restored C:\Users\truon\source\repos\RevitDevTool\source\ZLogger.RichTextBox.Winforms.Benchmark\ZLogger.RichTextBox.Winforms.Benchmark.csproj (in 180 ms).
27+
28+
// BenchmarkDotNet has failed to build the auto-generated boilerplate code.
29+
// It can be found in C:\Users\truon\source\repos\RevitDevTool\source\ZLogger.RichTextBox.Winforms.Benchmark\bin\Release\net8.0-windows\.NET 8.0-1
30+
// Please follow the troubleshooting guide: https://benchmarkdotnet.org/articles/guides/troubleshooting.html
31+
32+
// ** Remained 74 (90.2%) benchmark(s) to run. Estimated finish 2026-01-14 2:20 (0h 0m from now) **
33+
Successfully reverted power plan (GUID: 381b4222-f694-41f0-9685-ff5bb260df2e FriendlyName: Balanced)
34+
// ***** BenchmarkRunner: Finish *****
35+
36+
// * Export *
37+
BenchmarkDotNet.Artifacts\results\ZLogger.RichTextBox.Winforms.Benchmark.LatencyBenchmark-report.csv
38+
BenchmarkDotNet.Artifacts\results\ZLogger.RichTextBox.Winforms.Benchmark.LatencyBenchmark-report-github.md
39+
BenchmarkDotNet.Artifacts\results\ZLogger.RichTextBox.Winforms.Benchmark.LatencyBenchmark-report.html
40+
41+
// * Detailed results *
42+
LatencyBenchmark.'Serilog Latency': .NET 8.0(Runtime=.NET 8.0) [SampleCount=100]
43+
Runtime = ; GC =
44+
There are not any results runs
45+
46+
// * Summary *
47+
48+
BenchmarkDotNet v0.15.8, Windows 11 (10.0.26200.7462/25H2/2025Update/HudsonValley2)
49+
Intel Core Ultra 7 265K 3.90GHz, 1 CPU, 20 logical and 20 physical cores
50+
.NET SDK 9.0.307
51+
[Host] : .NET 8.0.22 (8.0.22, 8.0.2225.52707), X64 RyuJIT x86-64-v3
52+
53+
Job=.NET 8.0 Runtime=.NET 8.0
54+
55+
| Method | SampleCount | Mean | Error | Ratio | RatioSD | Rank | Alloc Ratio |
56+
|------------------ |------------ |-----:|------:|------:|--------:|-----:|------------:|
57+
| 'Serilog Latency' | 100 | NA | NA | ? | ? | ? | ? |
58+
59+
Benchmarks with issues:
60+
LatencyBenchmark.'Serilog Latency': .NET 8.0(Runtime=.NET 8.0) [SampleCount=100]
61+
62+
// * Warnings *
63+
BaselineCustomAnalyzer
64+
Summary -> A question mark '?' symbol indicates that it was not possible to compute the (Ratio, RatioSD, Alloc Ratio) column(s) because the baseline or benchmark could not be found, or the baseline value is too close to zero.
65+
66+
// * Legends *
67+
SampleCount : Value of the 'SampleCount' parameter
68+
Mean : Arithmetic mean of all measurements
69+
Error : Half of 99.9% confidence interval
70+
Ratio : Mean of the ratio distribution ([Current]/[Baseline])
71+
RatioSD : Standard deviation of the ratio distribution ([Current]/[Baseline])
72+
Rank : Relative position of current benchmark mean among all benchmarks (Arabic style)
73+
Alloc Ratio : Allocated memory ratio distribution ([Current]/[Baseline])
74+
1 ns : 1 Nanosecond (0.000000001 sec)
75+
76+
// * Diagnostic Output - MemoryDiagnoser *
77+
78+
79+
// ***** BenchmarkRunner: End *****
80+
Run time: 00:00:00 (0.47 sec), executed benchmarks: 0
81+
82+
Global total time: 00:00:01 (1.85 sec), executed benchmarks: 0
83+
// * Artifacts cleanup *
84+
Artifacts cleanup is finished

0 commit comments

Comments
 (0)