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

Commit ae50265

Browse files
pakrympakrym
authored
Optimize BeginScope performance (#929)
1 parent b454c5a commit ae50265

File tree

4 files changed

+122
-125
lines changed

4 files changed

+122
-125
lines changed

‎src/Microsoft.Extensions.Logging/Logger.cs

Lines changed: 12 additions & 73 deletions
Original file line numberDiff line numberDiff line change
@@ -9,40 +9,13 @@ namespace Microsoft.Extensions.Logging
99
{
1010
internal class Logger : ILogger
1111
{
12-
private readonly LoggerFactory _loggerFactory;
13-
14-
private LoggerInformation[] _loggers;
15-
16-
private int _scopeCount;
17-
18-
public Logger(LoggerFactory loggerFactory)
19-
{
20-
_loggerFactory = loggerFactory;
21-
}
22-
23-
public LoggerInformation[] Loggers
24-
{
25-
get { return _loggers; }
26-
set
27-
{
28-
var scopeSize = 0;
29-
foreach (var loggerInformation in value)
30-
{
31-
if (loggerInformation.CreateScopes)
32-
{
33-
scopeSize++;
34-
}
35-
}
36-
_scopeCount = scopeSize;
37-
_loggers = value;
38-
}
39-
}
40-
41-
public bool CaptureScopes { get; set; }
12+
public LoggerInformation[] Loggers { get; set; }
13+
public MessageLogger[] MessageLoggers { get; set; }
14+
public ScopeLogger[] ScopeLoggers { get; set; }
4215

4316
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
4417
{
45-
var loggers = Loggers;
18+
var loggers = MessageLoggers;
4619
if (loggers == null)
4720
{
4821
return;
@@ -80,7 +53,7 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
8053

8154
public bool IsEnabled(LogLevel logLevel)
8255
{
83-
var loggers = Loggers;
56+
var loggers = MessageLoggers;
8457
if (loggers == null)
8558
{
8659
return false;
@@ -124,56 +97,27 @@ public bool IsEnabled(LogLevel logLevel)
12497

12598
public IDisposable BeginScope<TState>(TState state)
12699
{
127-
var loggers = Loggers;
100+
var loggers = ScopeLoggers;
128101

129-
if (loggers == null || !CaptureScopes)
102+
if (loggers == null)
130103
{
131104
return NullScope.Instance;
132105
}
133106

134-
var scopeProvider = _loggerFactory.ScopeProvider;
135-
var scopeCount = _scopeCount;
136-
137-
if (scopeProvider != null)
107+
if (loggers.Length == 1)
138108
{
139-
// if external scope is used for all providers
140-
// we can return it's IDisposable directly
141-
// without wrapping and saving on allocation
142-
if (scopeCount == 0)
143-
{
144-
return scopeProvider.Push(state);
145-
}
146-
else
147-
{
148-
scopeCount++;
149-
}
150-
109+
return loggers[0].CreateScope(state);
151110
}
152111

153-
var scope = new Scope(scopeCount);
112+
var scope = new Scope(loggers.Length);
154113
List<Exception> exceptions = null;
155114
for (var index = 0; index < loggers.Length; index++)
156115
{
157-
var loggerInformation = loggers[index];
158-
if (!loggerInformation.CreateScopes)
159-
{
160-
continue;
161-
}
116+
var scopeLogger = loggers[index];
162117

163118
try
164119
{
165-
scopeCount--;
166-
// _loggers and _scopeCount are not updated atomically
167-
// there might be a situation when count was updated with
168-
// lower value then we have loggers
169-
// This is small race that happens only on configuraiton reload
170-
// and we are protecting from it by checkig that there is enough space
171-
// in Scope
172-
if (scopeCount >= 0)
173-
{
174-
var disposable = loggerInformation.Logger.BeginScope(state);
175-
scope.SetDisposable(scopeCount, disposable);
176-
}
120+
scope.SetDisposable(index, scopeLogger.CreateScope(state));
177121
}
178122
catch (Exception ex)
179123
{
@@ -186,11 +130,6 @@ public IDisposable BeginScope<TState>(TState state)
186130
}
187131
}
188132

189-
if (scopeProvider != null)
190-
{
191-
scope.SetDisposable(0, scopeProvider.Push(state));
192-
}
193-
194133
if (exceptions != null && exceptions.Count > 0)
195134
{
196135
throw new AggregateException(

‎src/Microsoft.Extensions.Logging/LoggerFactory.cs

Lines changed: 45 additions & 43 deletions
Original file line numberDiff line numberDiff line change
@@ -19,8 +19,7 @@ public class LoggerFactory : ILoggerFactory
1919
private volatile bool _disposed;
2020
private IDisposable _changeTokenRegistration;
2121
private LoggerFilterOptions _filterOptions;
22-
23-
internal LoggerExternalScopeProvider ScopeProvider { get; private set; }
22+
private LoggerExternalScopeProvider _scopeProvider;
2423

2524
public LoggerFactory() : this(Enumerable.Empty<ILoggerProvider>())
2625
{
@@ -50,15 +49,10 @@ private void RefreshFilters(LoggerFilterOptions filterOptions)
5049
lock (_sync)
5150
{
5251
_filterOptions = filterOptions;
53-
foreach (var logger in _loggers)
52+
foreach (var registeredLogger in _loggers)
5453
{
55-
var loggerInformation = logger.Value.Loggers;
56-
var categoryName = logger.Key;
57-
58-
ApplyRules(loggerInformation, categoryName, 0, loggerInformation.Length);
59-
60-
logger.Value.Loggers = loggerInformation;
61-
logger.Value.CaptureScopes = filterOptions.CaptureScopes;
54+
var logger = registeredLogger.Value;
55+
(logger.MessageLoggers, logger.ScopeLoggers) = ApplyFilters(logger.Loggers);
6256
}
6357
}
6458
}
@@ -74,11 +68,13 @@ public ILogger CreateLogger(string categoryName)
7468
{
7569
if (!_loggers.TryGetValue(categoryName, out var logger))
7670
{
77-
logger = new Logger(this)
71+
logger = new Logger
7872
{
7973
Loggers = CreateLoggers(categoryName),
80-
CaptureScopes = _filterOptions.CaptureScopes
8174
};
75+
76+
(logger.MessageLoggers, logger.ScopeLoggers) = ApplyFilters(logger.Loggers);
77+
8278
_loggers[categoryName] = logger;
8379
}
8480

@@ -97,18 +93,17 @@ public void AddProvider(ILoggerProvider provider)
9793
{
9894
AddProviderRegistration(provider, dispose: true);
9995

100-
foreach (var logger in _loggers)
96+
foreach (var existingLogger in _loggers)
10197
{
102-
var loggerInformation = logger.Value.Loggers;
103-
var categoryName = logger.Key;
98+
var logger = existingLogger.Value;
99+
var loggerInformation = logger.Loggers;
104100

101+
var newLoggerIndex = loggerInformation.Length;
105102
Array.Resize(ref loggerInformation, loggerInformation.Length + 1);
106-
var newLoggerIndex = loggerInformation.Length - 1;
107-
108-
SetLoggerInformation(ref loggerInformation[newLoggerIndex], provider, categoryName);
109-
ApplyRules(loggerInformation, categoryName, newLoggerIndex, 1);
103+
loggerInformation[newLoggerIndex] = new LoggerInformation(provider, existingLogger.Key);
110104

111-
logger.Value.Loggers = loggerInformation;
105+
logger.Loggers = loggerInformation;
106+
(logger.MessageLoggers, logger.ScopeLoggers) = ApplyFilters(logger.Loggers);
112107
}
113108
}
114109
}
@@ -123,50 +118,57 @@ private void AddProviderRegistration(ILoggerProvider provider, bool dispose)
123118

124119
if (provider is ISupportExternalScope supportsExternalScope)
125120
{
126-
if (ScopeProvider == null)
121+
if (_scopeProvider == null)
127122
{
128-
ScopeProvider = new LoggerExternalScopeProvider();
123+
_scopeProvider = new LoggerExternalScopeProvider();
129124
}
130125

131-
supportsExternalScope.SetScopeProvider(ScopeProvider);
126+
supportsExternalScope.SetScopeProvider(_scopeProvider);
132127
}
133128
}
134129

135-
private void SetLoggerInformation(ref LoggerInformation loggerInformation, ILoggerProvider provider, string categoryName)
136-
{
137-
loggerInformation.Logger = provider.CreateLogger(categoryName);
138-
loggerInformation.ProviderType = provider.GetType();
139-
loggerInformation.ExternalScope = provider is ISupportExternalScope;
140-
}
141-
142130
private LoggerInformation[] CreateLoggers(string categoryName)
143131
{
144132
var loggers = new LoggerInformation[_providerRegistrations.Count];
145-
for (int i = 0; i < _providerRegistrations.Count; i++)
133+
for (var i = 0; i < _providerRegistrations.Count; i++)
146134
{
147-
SetLoggerInformation(ref loggers[i], _providerRegistrations[i].Provider, categoryName);
135+
loggers[i] = new LoggerInformation(_providerRegistrations[i].Provider, categoryName);
148136
}
149-
150-
ApplyRules(loggers, categoryName, 0, loggers.Length);
151137
return loggers;
152138
}
153139

154-
private void ApplyRules(LoggerInformation[] loggers, string categoryName, int start, int count)
140+
private (MessageLogger[] MessageLoggers, ScopeLogger[] ScopeLoggers) ApplyFilters(LoggerInformation[] loggers)
155141
{
156-
for (var index = start; index < start + count; index++)
157-
{
158-
ref var loggerInformation = ref loggers[index];
142+
var messageLoggers = new List<MessageLogger>();
143+
var scopeLoggers = _filterOptions.CaptureScopes ? new List<ScopeLogger>() : null;
159144

145+
foreach (var loggerInformation in loggers)
146+
{
160147
RuleSelector.Select(_filterOptions,
161148
loggerInformation.ProviderType,
162-
categoryName,
149+
loggerInformation.Category,
163150
out var minLevel,
164151
out var filter);
165152

166-
loggerInformation.Category = categoryName;
167-
loggerInformation.MinLevel = minLevel;
168-
loggerInformation.Filter = filter;
153+
if (minLevel != null && minLevel > LogLevel.Critical)
154+
{
155+
continue;
156+
}
157+
158+
messageLoggers.Add(new MessageLogger(loggerInformation.Logger, loggerInformation.Category, loggerInformation.ProviderType, minLevel, filter));
159+
160+
if (!loggerInformation.ExternalScope)
161+
{
162+
scopeLoggers?.Add(new ScopeLogger(logger: loggerInformation.Logger, externalScopeProvider: null));
163+
}
169164
}
165+
166+
if (_scopeProvider != null)
167+
{
168+
scopeLoggers?.Add(new ScopeLogger(logger: null, externalScopeProvider: _scopeProvider));
169+
}
170+
171+
return (messageLoggers.ToArray(), scopeLoggers?.ToArray());
170172
}
171173

172174
/// <summary>
@@ -206,4 +208,4 @@ private struct ProviderRegistration
206208
public bool ShouldDispose;
207209
}
208210
}
209-
}
211+
}

‎src/Microsoft.Extensions.Logging/LoggerInformation.cs

Lines changed: 55 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -5,21 +5,26 @@
55

66
namespace Microsoft.Extensions.Logging
77
{
8-
internal struct LoggerInformation
8+
internal readonly struct MessageLogger
99
{
10-
public ILogger Logger { get; set; }
11-
12-
public string Category { get; set; }
10+
public MessageLogger(ILogger logger, string category, Type providerType, LogLevel? minLevel, Func<string, string, LogLevel, bool> filter)
11+
{
12+
Logger = logger;
13+
Category = category;
14+
ProviderType = providerType;
15+
MinLevel = minLevel;
16+
Filter = filter;
17+
}
1318

14-
public Type ProviderType { get; set; }
19+
public ILogger Logger { get; }
1520

16-
public LogLevel? MinLevel { get; set; }
21+
public string Category { get; }
1722

18-
public Func<string, string, LogLevel, bool> Filter { get; set; }
23+
public Type ProviderType { get; }
1924

20-
public bool ExternalScope { get; set; }
25+
public LogLevel? MinLevel { get; }
2126

22-
public bool CreateScopes => !ExternalScope && IsEnabled(LogLevel.Critical);
27+
public Func<string, string, LogLevel, bool> Filter { get; }
2328

2429
public bool IsEnabled(LogLevel level)
2530
{
@@ -36,4 +41,45 @@ public bool IsEnabled(LogLevel level)
3641
return true;
3742
}
3843
}
44+
45+
internal readonly struct ScopeLogger
46+
{
47+
public ScopeLogger(ILogger logger, IExternalScopeProvider externalScopeProvider)
48+
{
49+
Logger = logger;
50+
ExternalScopeProvider = externalScopeProvider;
51+
}
52+
53+
public ILogger Logger { get; }
54+
55+
public IExternalScopeProvider ExternalScopeProvider { get; }
56+
57+
public IDisposable CreateScope<TState>(TState state)
58+
{
59+
if (ExternalScopeProvider != null)
60+
{
61+
return ExternalScopeProvider.Push(state);
62+
}
63+
return Logger.BeginScope<TState>(state);
64+
}
65+
}
66+
67+
internal readonly struct LoggerInformation
68+
{
69+
public LoggerInformation(ILoggerProvider provider, string category) : this()
70+
{
71+
ProviderType = provider.GetType();
72+
Logger = provider.CreateLogger(category);
73+
Category = category;
74+
ExternalScope = provider is ISupportExternalScope;
75+
}
76+
77+
public ILogger Logger { get; }
78+
79+
public string Category { get; }
80+
81+
public Type ProviderType { get; }
82+
83+
public bool ExternalScope { get; }
84+
}
3985
}

‎test/Microsoft.Extensions.Logging.Test/LoggerFactoryTest.cs

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -132,6 +132,16 @@ public void BeginScope_ReturnsExternalSourceTokenDirectly()
132132
Assert.StartsWith(loggerProvider.ScopeProvider.GetType().FullName, scope.GetType().FullName);
133133
}
134134

135+
[Fact]
136+
public void BeginScope_ReturnsInternalSourceTokenDirectly()
137+
{
138+
var loggerProvider = new InternalScopeLoggerProvider();
139+
var loggerFactory = new LoggerFactory(new[] { loggerProvider });
140+
var logger = loggerFactory.CreateLogger("Logger");
141+
var scope = logger.BeginScope("Scope");
142+
Assert.Contains("LoggerExternalScopeProvider+Scope", scope.GetType().FullName);
143+
}
144+
135145
[Fact]
136146
public void BeginScope_ReturnsCompositeToken_ForMultipleLoggers()
137147
{

0 commit comments

Comments
 (0)