Skip to content

Commit 5148b8f

Browse files
ngbrownngbrown
committed
Performance tests for new logging.
1 parent 6dc41c6 commit 5148b8f

File tree

1 file changed

+212
-0
lines changed

1 file changed

+212
-0
lines changed

‎src/NHibernate.Test/Logging/LoggerPerformanceTest.cs

Lines changed: 212 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@ public class LoggerPerformanceTest
1313
private static int infoLoggedCount = 0;
1414
private static int warnLoggedCount = 0;
1515

16+
[Obsolete("Tests obsolete methods")]
1617
private class MockLoggerFactory : ILoggerFactory
1718
{
1819
public IInternalLogger LoggerFor(string keyName)
@@ -26,6 +27,7 @@ public IInternalLogger LoggerFor(System.Type type)
2627
}
2728
}
2829

30+
[Obsolete("Tests obsolete methods")]
2931
private class MockLogger : IInternalLogger
3032
{
3133
public bool IsErrorEnabled { get; } = true;
@@ -105,6 +107,64 @@ public void WarnFormat(string format, params object[] args)
105107
}
106108
}
107109

110+
private class MockNHibernateLoggerFactory : INHibernateLoggerFactory
111+
{
112+
public IInternalLogger2 LoggerFor(string keyName)
113+
{
114+
return new MockLogger2();
115+
}
116+
117+
public IInternalLogger2 LoggerFor(System.Type type)
118+
{
119+
return new MockLogger2();
120+
}
121+
}
122+
123+
private class MockLogger2 : IInternalLogger2
124+
{
125+
private bool IsErrorEnabled { get; } = true;
126+
private bool IsFatalEnabled { get; } = true;
127+
private bool IsDebugEnabled { get; } = false;
128+
private bool IsInfoEnabled { get; } = false;
129+
private bool IsWarnEnabled { get; } = true;
130+
131+
public void Log(InternalLogLevel logLevel, InternalLogValues state, Exception exception)
132+
{
133+
if (!IsEnabled(logLevel)) return;
134+
135+
if (state.Args?.Length > 0)
136+
{
137+
errorLoggedCount += string.Format(state.Format, state.Args).Length;
138+
}
139+
else
140+
{
141+
errorLoggedCount += state.Format.Length;
142+
}
143+
}
144+
145+
public bool IsEnabled(InternalLogLevel logLevel)
146+
{
147+
switch (logLevel)
148+
{
149+
case InternalLogLevel.Trace:
150+
case InternalLogLevel.Debug:
151+
return IsDebugEnabled;
152+
case InternalLogLevel.Info:
153+
return IsInfoEnabled;
154+
case InternalLogLevel.Warn:
155+
return IsWarnEnabled;
156+
case InternalLogLevel.Error:
157+
return IsErrorEnabled;
158+
case InternalLogLevel.Fatal:
159+
return IsFatalEnabled;
160+
case InternalLogLevel.None:
161+
return !IsFatalEnabled;
162+
default:
163+
throw new ArgumentOutOfRangeException(nameof(logLevel), logLevel, null);
164+
}
165+
}
166+
}
167+
108168
private static void ResetCounts()
109169
{
110170
errorLoggedCount = 0;
@@ -125,6 +185,7 @@ private static long GetCounts()
125185
[TestCase(3)]
126186
[TestCase(4)]
127187
[TestCase(5)]
188+
[Obsolete("Tests obsolete methods")]
128189
public void OldLoggerFactoryTimingsForDisabledLogging(int iteration)
129190
{
130191
ResetCounts();
@@ -153,6 +214,7 @@ public void OldLoggerFactoryTimingsForDisabledLogging(int iteration)
153214
[TestCase(3)]
154215
[TestCase(4)]
155216
[TestCase(5)]
217+
[Obsolete("Tests obsolete methods")]
156218
public void OldLoggerFactoryTimingsForEnabledLogging(int iteration)
157219
{
158220
ResetCounts();
@@ -174,5 +236,155 @@ public void OldLoggerFactoryTimingsForEnabledLogging(int iteration)
174236
GetCounts(),
175237
stopwatch.ElapsedMilliseconds);
176238
}
239+
240+
[Test, Explicit("High-iteration performance test")]
241+
[TestCase(1)]
242+
[TestCase(2)]
243+
[TestCase(3)]
244+
[TestCase(4)]
245+
[TestCase(5)]
246+
[Obsolete("Tests obsolete methods")]
247+
public void OldLoggerFactoryThunkedTimingsForDisabledLogging(int iteration)
248+
{
249+
ResetCounts();
250+
ILoggerFactory loggerFactory = new MockLoggerFactory();
251+
LoggerProvider.SetLoggersFactory(loggerFactory);
252+
IInternalLogger2 logger2 = LoggerProvider.LoggerFor(this.GetType());
253+
254+
var stopwatch = Stopwatch.StartNew();
255+
var iterationCount = 10000000;
256+
for (int i = 0; i < iterationCount; i++)
257+
{
258+
logger2.Debug("message");
259+
logger2.Debug("message with parameters {0}, {1}", "string", 5);
260+
}
261+
262+
stopwatch.Stop();
263+
Console.WriteLine(
264+
"{0} wrote {1:N0} characters to log in {2} ms",
265+
nameof(OldLoggerFactoryThunkedTimingsForDisabledLogging),
266+
GetCounts(),
267+
stopwatch.ElapsedMilliseconds);
268+
}
269+
270+
[Test, Explicit("High-iteration performance test")]
271+
[TestCase(1)]
272+
[TestCase(2)]
273+
[TestCase(3)]
274+
[TestCase(4)]
275+
[TestCase(5)]
276+
[Obsolete("Tests obsolete methods")]
277+
public void OldLoggerFactoryThunkedTimingsForEnabledLogging(int iteration)
278+
{
279+
ResetCounts();
280+
ILoggerFactory loggerFactory = new MockLoggerFactory();
281+
LoggerProvider.SetLoggersFactory(loggerFactory);
282+
IInternalLogger2 logger2 = LoggerProvider.LoggerFor(this.GetType());
283+
284+
var stopwatch = Stopwatch.StartNew();
285+
var iterationCount = 10000000;
286+
for (int i = 0; i < iterationCount; i++)
287+
{
288+
logger2.Warn("message");
289+
logger2.Warn("message with parameters {0}, {1}", "string", 5);
290+
}
291+
292+
stopwatch.Stop();
293+
Console.WriteLine(
294+
"{0} wrote {1:N0} characters to log in {2} ms",
295+
nameof(OldLoggerFactoryThunkedTimingsForEnabledLogging),
296+
GetCounts(),
297+
stopwatch.ElapsedMilliseconds);
298+
}
299+
300+
[Test, Explicit("High-iteration performance test")]
301+
[TestCase(1)]
302+
[TestCase(2)]
303+
[TestCase(3)]
304+
[TestCase(4)]
305+
[TestCase(5)]
306+
[Obsolete("Tests obsolete methods")]
307+
public void NewLoggerFactoryTimingsForDisabledLogging(int iteration)
308+
{
309+
ResetCounts();
310+
INHibernateLoggerFactory loggerFactory = new MockNHibernateLoggerFactory();
311+
LoggerProvider.SetLoggersFactory(loggerFactory);
312+
IInternalLogger2 logger2 = LoggerProvider.LoggerFor(this.GetType());
313+
314+
var stopwatch = Stopwatch.StartNew();
315+
var iterationCount = 10000000;
316+
for (int i = 0; i < iterationCount; i++)
317+
{
318+
logger2.Debug("message");
319+
logger2.Debug("message with parameters {0}, {1}", "string", 5);
320+
}
321+
322+
stopwatch.Stop();
323+
Console.WriteLine(
324+
"{0} wrote {1:N0} characters to log in {2} ms",
325+
nameof(NewLoggerFactoryTimingsForDisabledLogging),
326+
GetCounts(),
327+
stopwatch.ElapsedMilliseconds);
328+
}
329+
330+
[Test, Explicit("High-iteration performance test")]
331+
[TestCase(1)]
332+
[TestCase(2)]
333+
[TestCase(3)]
334+
[TestCase(4)]
335+
[TestCase(5)]
336+
[Obsolete("Tests obsolete methods")]
337+
public void NewLoggerFactoryTimingsForEnabledLogging(int iteration)
338+
{
339+
ResetCounts();
340+
INHibernateLoggerFactory loggerFactory = new MockNHibernateLoggerFactory();
341+
LoggerProvider.SetLoggersFactory(loggerFactory);
342+
IInternalLogger2 logger2 = LoggerProvider.LoggerFor(this.GetType());
343+
344+
var stopwatch = Stopwatch.StartNew();
345+
var iterationCount = 10000000;
346+
for (int i = 0; i < iterationCount; i++)
347+
{
348+
logger2.Warn("message");
349+
logger2.Warn("message with parameters {0}, {1}", "string", 5);
350+
}
351+
352+
stopwatch.Stop();
353+
Console.WriteLine(
354+
"{0} wrote {1:N0} characters to log in {2} ms",
355+
nameof(NewLoggerFactoryTimingsForEnabledLogging),
356+
GetCounts(),
357+
stopwatch.ElapsedMilliseconds);
358+
}
359+
360+
[Test, Explicit("High-iteration performance test")]
361+
[TestCase(1)]
362+
[TestCase(2)]
363+
[TestCase(3)]
364+
[TestCase(4)]
365+
[TestCase(5)]
366+
[Obsolete("Tests obsolete methods")]
367+
public void NewLoggerFactoryTimingsForNoLogging(int iteration)
368+
{
369+
ResetCounts();
370+
INHibernateLoggerFactory loggerFactory = new NoLoggingLoggerFactory();
371+
LoggerProvider.SetLoggersFactory(loggerFactory);
372+
IInternalLogger2 logger2 = LoggerProvider.LoggerFor(this.GetType());
373+
374+
var stopwatch = Stopwatch.StartNew();
375+
var iterationCount = 10000000;
376+
for (int i = 0; i < iterationCount; i++)
377+
{
378+
logger2.Debug("message");
379+
logger2.Debug("message with parameters {0}, {1}", "string", 5);
380+
}
381+
382+
stopwatch.Stop();
383+
Console.WriteLine(
384+
"{0} wrote {1:N0} characters to log in {2} ms",
385+
nameof(NewLoggerFactoryTimingsForDisabledLogging),
386+
GetCounts(),
387+
stopwatch.ElapsedMilliseconds);
388+
}
177389
}
178390
}

0 commit comments

Comments
 (0)