Skip to content
This repository was archived by the owner on Dec 13, 2018. It is now read-only.

Commit cc90113

Browse files
authored
Decrease logging overhead (#917)
1 parent 03970f7 commit cc90113

File tree

12 files changed

+418
-211
lines changed

12 files changed

+418
-211
lines changed

.gitignore

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -29,3 +29,4 @@ project.lock.json
2929
.build/
3030
.testPublish/
3131
global.json
32+
BenchmarkDotNet.Artifacts/

Logging.sln

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -60,6 +60,10 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Extensions.Loggin
6060
EndProject
6161
Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Extensions.Logging.Analyzer.Test", "test\Microsoft.Extensions.Logging.Analyzer.Test\Microsoft.Extensions.Logging.Analyzer.Test.csproj", "{C0391E46-FD04-4D52-BE40-1F21CE83E037}"
6262
EndProject
63+
Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "benchmarks", "benchmarks", "{0BE8FABE-0FE7-4DF1-ABDE-27BB0D86F881}"
64+
EndProject
65+
Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Logging.Performance", "benchmarks\Logging.Performance\Logging.Performance.csproj", "{67B77ED1-8827-4088-8724-4A0AF4351FB7}"
66+
EndProject
6367
Global
6468
GlobalSection(SolutionConfigurationPlatforms) = preSolution
6569
Debug|Any CPU = Debug|Any CPU
@@ -134,6 +138,10 @@ Global
134138
{C0391E46-FD04-4D52-BE40-1F21CE83E037}.Debug|Any CPU.Build.0 = Debug|Any CPU
135139
{C0391E46-FD04-4D52-BE40-1F21CE83E037}.Release|Any CPU.ActiveCfg = Release|Any CPU
136140
{C0391E46-FD04-4D52-BE40-1F21CE83E037}.Release|Any CPU.Build.0 = Release|Any CPU
141+
{67B77ED1-8827-4088-8724-4A0AF4351FB7}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
142+
{67B77ED1-8827-4088-8724-4A0AF4351FB7}.Debug|Any CPU.Build.0 = Debug|Any CPU
143+
{67B77ED1-8827-4088-8724-4A0AF4351FB7}.Release|Any CPU.ActiveCfg = Release|Any CPU
144+
{67B77ED1-8827-4088-8724-4A0AF4351FB7}.Release|Any CPU.Build.0 = Release|Any CPU
137145
EndGlobalSection
138146
GlobalSection(SolutionProperties) = preSolution
139147
HideSolutionNode = FALSE
@@ -156,6 +164,7 @@ Global
156164
{6D921637-507E-4CDC-8C5F-C3D6B62D118C} = {699DB330-0095-4266-B7B0-3EAB3710CA49}
157165
{99DF369F-40A4-4088-8308-1C361B59DF4E} = {699DB330-0095-4266-B7B0-3EAB3710CA49}
158166
{C0391E46-FD04-4D52-BE40-1F21CE83E037} = {09920C51-6220-4D8D-94DC-E70C13446187}
167+
{67B77ED1-8827-4088-8724-4A0AF4351FB7} = {0BE8FABE-0FE7-4DF1-ABDE-27BB0D86F881}
159168
EndGlobalSection
160169
GlobalSection(ExtensibilityGlobals) = postSolution
161170
SolutionGuid = {BA58E3CA-3A01-46A7-B57F-FD7A188EDC79}
Lines changed: 55 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,55 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
3+
4+
using System;
5+
using BenchmarkDotNet.Attributes;
6+
using Microsoft.Extensions.DependencyInjection;
7+
8+
namespace Microsoft.Extensions.Logging.Performance
9+
{
10+
[AspNetCoreBenchmark]
11+
public class FormattingBenchmarks : LoggingBenchmarkBase
12+
{
13+
private ILogger _logger;
14+
15+
[Benchmark]
16+
public void TwoArguments()
17+
{
18+
TwoArgumentErrorMessage(_logger, 1, "string", Exception);
19+
}
20+
21+
[Benchmark(Baseline = true)]
22+
public void NoArguments()
23+
{
24+
NoArgumentErrorMessage(_logger, Exception);
25+
}
26+
27+
[GlobalSetup]
28+
public void Setup()
29+
{
30+
var services = new ServiceCollection();
31+
services.AddLogging();
32+
services.AddSingleton<ILoggerProvider, LoggerProvider<MessageFormattingLogger>>();
33+
34+
_logger = services.BuildServiceProvider().GetService<ILoggerFactory>().CreateLogger("Logger");
35+
}
36+
37+
public class MessageFormattingLogger: ILogger
38+
{
39+
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
40+
{
41+
formatter(state, exception);
42+
}
43+
44+
public bool IsEnabled(LogLevel logLevel)
45+
{
46+
return true;
47+
}
48+
49+
public IDisposable BeginScope<TState>(TState state)
50+
{
51+
return null;
52+
}
53+
}
54+
}
55+
}
Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,20 @@
1+
<Project Sdk="Microsoft.NET.Sdk">
2+
3+
<PropertyGroup>
4+
<TargetFramework>netcoreapp2.2</TargetFramework>
5+
<RootNamespace>Microsoft.Extensions.Logging.Performance</RootNamespace>
6+
<OutputType>Exe</OutputType>
7+
<IsPackable>false</IsPackable>
8+
</PropertyGroup>
9+
10+
<ItemGroup>
11+
<ProjectReference Include="..\..\src\Microsoft.Extensions.Logging\Microsoft.Extensions.Logging.csproj" />
12+
</ItemGroup>
13+
14+
<ItemGroup>
15+
<PackageReference Include="BenchmarkDotNet" Version="$(BenchmarkDotNetPackageVersion)" />
16+
<PackageReference Include="Microsoft.AspNetCore.BenchmarkRunner.Sources" Version="$(MicrosoftAspNetCoreBenchmarkRunnerSourcesPackageVersion)" />
17+
<PackageReference Include="Microsoft.Extensions.DependencyInjection" Version="$(MicrosoftExtensionsDependencyInjectionPackageVersion)" />
18+
</ItemGroup>
19+
20+
</Project>
Lines changed: 40 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,40 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
3+
4+
using System;
5+
6+
namespace Microsoft.Extensions.Logging.Performance
7+
{
8+
public class LoggingBenchmarkBase
9+
{
10+
protected static readonly Action<ILogger, Exception> NoArgumentTraceMessage = LoggerMessage.Define(LogLevel.Trace, 0, "Message");
11+
protected static readonly Action<ILogger, Exception> NoArgumentErrorMessage = LoggerMessage.Define(LogLevel.Error, 0, "Message");
12+
13+
protected static readonly Action<ILogger, int, string, Exception> TwoArgumentTraceMessage = LoggerMessage.Define<int, string>(LogLevel.Trace, 0, "Message {Argument1} {Argument2}");
14+
protected static readonly Action<ILogger, int, string, Exception> TwoArgumentErrorMessage = LoggerMessage.Define<int, string>(LogLevel.Error, 0, "Message {Argument1} {Argument2}");
15+
16+
protected static Exception Exception = ((Func<Exception>)(() => {
17+
try
18+
{
19+
throw new Exception();
20+
}
21+
catch (Exception ex)
22+
{
23+
return ex;
24+
}
25+
}))();
26+
27+
public class LoggerProvider<T>: ILoggerProvider
28+
where T: ILogger, new()
29+
{
30+
public void Dispose()
31+
{
32+
}
33+
34+
public ILogger CreateLogger(string categoryName)
35+
{
36+
return new T();
37+
}
38+
}
39+
}
40+
}
Lines changed: 90 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,90 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
3+
4+
using System;
5+
using BenchmarkDotNet.Attributes;
6+
using Microsoft.Extensions.DependencyInjection;
7+
8+
namespace Microsoft.Extensions.Logging.Performance
9+
{
10+
[AspNetCoreBenchmark]
11+
public class LoggingOverheadBenchmark: LoggingBenchmarkBase
12+
{
13+
private ILogger _logger;
14+
15+
[Benchmark]
16+
public void NoArguments_FilteredByLevel()
17+
{
18+
_logger.LogTrace(Exception, "Message");
19+
}
20+
21+
// Baseline as this is the fastest way to do nothing
22+
[Benchmark(Baseline = true)]
23+
public void NoArguments_DefineMessage_FilteredByLevel()
24+
{
25+
NoArgumentTraceMessage(_logger, Exception);
26+
}
27+
28+
[Benchmark]
29+
public void NoArguments()
30+
{
31+
_logger.LogError(Exception, "Message");
32+
}
33+
34+
[Benchmark]
35+
public void NoArguments_DefineMessage()
36+
{
37+
NoArgumentErrorMessage(_logger, Exception);
38+
}
39+
40+
[Benchmark]
41+
public void TwoArguments()
42+
{
43+
_logger.LogError(Exception, "Message {Argument1} {Argument2}", 1, "string");
44+
}
45+
46+
[Benchmark]
47+
public void TwoArguments_FilteredByLevel()
48+
{
49+
_logger.LogTrace(Exception, "Message {Argument1} {Argument2}", 1, "string");
50+
}
51+
52+
[Benchmark]
53+
public void TwoArguments_DefineMessage()
54+
{
55+
TwoArgumentErrorMessage(_logger, 1, "string", Exception);
56+
}
57+
58+
[Benchmark]
59+
public void TwoArguments_DefineMessage_FilteredByLevel()
60+
{
61+
TwoArgumentTraceMessage(_logger, 1, "string", Exception);
62+
}
63+
64+
[GlobalSetup]
65+
public void Setup()
66+
{
67+
var services = new ServiceCollection();
68+
services.AddLogging();
69+
services.AddSingleton<ILoggerProvider, LoggerProvider<NoopLogger>>();
70+
_logger = services.BuildServiceProvider().GetService<ILoggerFactory>().CreateLogger("Logger");
71+
}
72+
}
73+
74+
public class NoopLogger : ILogger
75+
{
76+
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
77+
{
78+
}
79+
80+
public bool IsEnabled(LogLevel logLevel)
81+
{
82+
return true;
83+
}
84+
85+
public IDisposable BeginScope<TState>(TState state)
86+
{
87+
return null;
88+
}
89+
}
90+
}
Lines changed: 72 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,72 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
3+
4+
using BenchmarkDotNet.Attributes;
5+
using Microsoft.Extensions.DependencyInjection;
6+
7+
namespace Microsoft.Extensions.Logging.Performance
8+
{
9+
[AspNetCoreBenchmark]
10+
public class ScopesOverheadBenchmark: LoggingBenchmarkBase
11+
{
12+
private ILogger _logger;
13+
14+
[Params(true, false)]
15+
public bool HasISupportLoggingScopeLogger { get; set; } = false;
16+
17+
// Baseline as this is the fastest way to do nothing
18+
[Benchmark(Baseline = true)]
19+
public void FilteredByLevel()
20+
{
21+
TwoArgumentTraceMessage(_logger, 1, "string", Exception);
22+
}
23+
24+
[Benchmark]
25+
public void FilteredByLevel_InsideScope()
26+
{
27+
using (_logger.BeginScope("string"))
28+
{
29+
TwoArgumentTraceMessage(_logger, 1, "string", Exception);
30+
}
31+
}
32+
33+
[Benchmark]
34+
public void NotFiltered()
35+
{
36+
TwoArgumentErrorMessage(_logger, 1, "string", Exception);
37+
}
38+
39+
[Benchmark]
40+
public void NotFiltered_InsideScope()
41+
{
42+
using (_logger.BeginScope("string"))
43+
{
44+
TwoArgumentErrorMessage(_logger, 1, "string", Exception);
45+
}
46+
}
47+
48+
[GlobalSetup]
49+
public void Setup()
50+
{
51+
var services = new ServiceCollection();
52+
services.AddLogging();
53+
if (HasISupportLoggingScopeLogger)
54+
{
55+
services.AddSingleton<ILoggerProvider, LoggerProviderWithISupportExternalScope>();
56+
}
57+
else
58+
{
59+
services.AddSingleton<ILoggerProvider, LoggerProvider<NoopLogger>>();
60+
}
61+
62+
_logger = services.BuildServiceProvider().GetService<ILoggerFactory>().CreateLogger("Logger");
63+
}
64+
65+
class LoggerProviderWithISupportExternalScope: LoggerProvider<NoopLogger>, ISupportExternalScope
66+
{
67+
public void SetScopeProvider(IExternalScopeProvider scopeProvider)
68+
{
69+
}
70+
}
71+
}
72+
}

build/dependencies.props

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,8 +3,10 @@
33
<MSBuildAllProjects>$(MSBuildAllProjects);$(MSBuildThisFileFullPath)</MSBuildAllProjects>
44
</PropertyGroup>
55
<PropertyGroup Label="Package Versions">
6+
<BenchmarkDotNetPackageVersion>0.10.13</BenchmarkDotNetPackageVersion>
67
<InternalAspNetCoreSdkPackageVersion>3.0.0-alpha1-20181004.7</InternalAspNetCoreSdkPackageVersion>
78
<MicrosoftAspNetCoreAnalyzerTestingPackageVersion>3.0.0-alpha1-10584</MicrosoftAspNetCoreAnalyzerTestingPackageVersion>
9+
<MicrosoftAspNetCoreBenchmarkRunnerSourcesPackageVersion>3.0.0-alpha1-10584</MicrosoftAspNetCoreBenchmarkRunnerSourcesPackageVersion>
810
<MicrosoftAspNetCoreTestingPackageVersion>3.0.0-alpha1-10584</MicrosoftAspNetCoreTestingPackageVersion>
911
<MicrosoftCodeAnalysisCSharpWorkspacesPackageVersion>2.8.0</MicrosoftCodeAnalysisCSharpWorkspacesPackageVersion>
1012
<MicrosoftExtensionsConfigurationAbstractionsPackageVersion>3.0.0-alpha1-10584</MicrosoftExtensionsConfigurationAbstractionsPackageVersion>

src/Microsoft.Extensions.Logging.Abstractions/Internal/FormattedLogValues.cs

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,7 @@ namespace Microsoft.Extensions.Logging.Internal
1313
/// LogValues to enable formatting options supported by <see cref="M:string.Format"/>.
1414
/// This also enables using {NamedformatItem} in the format string.
1515
/// </summary>
16-
public class FormattedLogValues : IReadOnlyList<KeyValuePair<string, object>>
16+
public readonly struct FormattedLogValues : IReadOnlyList<KeyValuePair<string, object>>
1717
{
1818
internal const int MaxCachedFormatters = 1024;
1919
private const string NullFormat = "[null]";
@@ -46,6 +46,10 @@ public FormattedLogValues(string format, params object[] values)
4646
});
4747
}
4848
}
49+
else
50+
{
51+
_formatter = null;
52+
}
4953

5054
_originalMessage = format ?? NullFormat;
5155
_values = values;

0 commit comments

Comments
 (0)