NLog 4.5 changelog

[304NotModified]

Update changelog

[snakefoot]

List of important changes in NLog 4.5

Features:

• Support for .Net Standard 2.0 Support .NET Standard 2.0 and move to VS 2017 #2263 + Introduced NLog.Wcf and Nlog.WindowsIdentity for .NET standard #2402
• Support for .Net Standard 1.5 NLog - NETSTANDARD1_5 #2341
• Support for .Net Standard 1.3 (and UWP) Support for UWP platform #2441 + Replace WINDOWS_UWP with NETSTANDARD1_3 to support UWP10 shared libraries #2597 (Remember to manually flush on app suspend).
• Introduced Structured logging Added Structured events / Message Templates #2208 + LogEventInfo.MessageTemplate - Subset of LogEventInfo.Properties #2262 + LogEventInfo.MessageFormatter - External Structured Logging Formatter #2244 + MessageTemplate renderer with support for mixed mode templates #2544
• Default file archive logic is now easier to use FileArchiveModeFactory - Extracted from FileTarget #1993
• Introduced InstallationContext.ThrowExceptions Option to throw exceptions when installation failed (ThrowExceptions on InstallationContext) #2214
• WebServiceTarget - Allow configuration of proxy address WebServiceTarget - Allow configuration of proxy address #2375
• WebServiceTarget - JsonPost with JsonLayout without being wrapped in parameter WebServiceTarget - JsonPost with support for single nameless parameter #2590
• Json conversion also supports object properties JsonSerializer - Serialize Object Properties into StringBuilder #2179, JsonLayout - Use capturetype and added MaxRecursionLimit and set default to 0 #2555
• event-properties layout-renderer can now render objects as json EventPropertiesLayoutRenderer - Support Json Format #2241
• exception layout-renderer can now render exceptions as json ExceptionLayoutRenderer - Support Serialize Format #2357
• ${guid}, added GeneratedFromLogEvent ${guid}, added GeneratedFromLogEvent #2226
• TraceTarget RawWrite to always perform Trace.WriteLine independent of LogLevel NLog prepends unspecified data to Trace target. #1968
• Adding OverflowAction options to BufferingTargetWrapper Adding OverflowAction options to BufferingTargetWrapper #2276
• WhenRepeatedFilter WhenRepeatedFilter - Filtering of identical LogEvents #2123 + WhenRepeatedFilter - Log after timeout #2297
• ${callsite} added CleanNamesOfAsyncContinuations option ${callsite} added CleanNamesOfAsyncContinuations option #2292
• ${ndlctiming} allows timing of ndlc-scopes NDLC - Perform low resolution scope timing #2377
• NLogViewerTarget - Enable override of the Logger-name NLogViewerTarget - Enable override of the Logger-name #2390
• ${sequenceid} added Create SequenceIdLayoutRenderer #2411
• Added "regex-matches" for filtering Added "regex-matches" condition method for filtering #2437
• ${gdc}, ${mdc} & {mdlc} - Support Format parameter ${gdc}, ${mdc} & {mdlc} - Support Format parameter #2500
• ${currentDir} added Added ${currentDir} #2491
• ${AssemblyVersion}: add type (File, Assembly, Informational) option ${AssemblyVersion}: add type (File, Assembly, Informational) option #2487
• FileTarget: Support byte order mark FileTarget: Support byte order mark (optional) #2456
• TargetWithContext - Easier to create custom NLog targets with support for MDLC and NDLC TargetWithContext - Easier to capture snapshot of MDLC and NDLC context #2467
• ${callname-filename} - Without line number callsite-filename renderer #2591
• MDC + MDLC with SetScoped property support Make Set methods of MDC and MDLC return IDisposable #2592
• LoggingConfiguration AddRule includes final-parameter add final param to AddRule Methods #2612

BugFixes:

• Improve archive stability during concurrent file access FileTarget - Perform archive retry when concurrent file access #1889
• FallbackGroup could lose log events FallbackGroup loses events with async targets #2265
• ${exception} - only include separator when items are available ${exception} - only include separator when items are available  #2257
• LogFactory - Fixes broken EventArgs for ConfigurationChanged LogFactory - Fixed EventArgs for ConfigurationChanged #1897
• Do not report wrapped targets as unused targets Do not report wrapped targets as unused targets #2290
• Added IIncludeContext, implemented missing properties Added IIncludeContext, implemented missing properties, added includeNdlc, sync NDLC and NDC #2117
• Improve logging of callsite linenumber for async-methods LogEventInfo.StackTrace moved into CallSiteInformation #2386
• NLogTraceListener - DisableFlush is enabled by default when AutoFlush=true NLogTraceListener - set DisableFlush true by default #2407
• NLogViewer - Better defaults for connection limits Updated NLog viewer target defaults #2404
• LoggingConfiguration.LoggingRules is not thread safe GetTargetsByLevelForLogger - LoggingConfiguration.LoggingRules is not thread safe #2393, LoggingConfiguration - Modify and clone LoggingRules under lock #2418
• Fix XmlLoggingConfiguration reloading Fix XmlLoggingConfiguration reloading #2475
• Database Target now supports EntityFramework ConnectionStrings Database target entity framework connection string #2510
• LoggingConfiguration.RemoveTarget now works while actively logging LoggingConfiguration - FindTargetByName should also find target + fix for logging on a target even after removed  #2549
• FileTarget does not fail on platforms without global mutex support FileTarget - Failing to CreateArchiveMutex should not stop logging #2604
• LoggingConfiguration does not fail when AutoReload is not possible on the platforms without FileWatcher MultiFileWatcher - Improve error handling if FileSystemWatcher fails #2603

Performance:

• More targets has OptimizeBufferReuse enabled by default TraceTarget - Enable OptimizeBufferReuse by default #1913 + Enable OptimizeBufferReuse for simple Target Wrappers (but not inherited) #1923 + WebServiceTarget - Enable OptimizeBufferReuse by default & Ability to add HTTP request headers #1912 + MemoryTarget - Enable OptimizeBufferReuse by default #1911 + EventLogTarget - Enable OptimizeBufferReuse by default #1910 + DebuggerTarget - Enable OptimizeBufferReuse by default #1909 + DatabaseTarget - Enable OptimizeBufferReuse by default #1908 + Colored- & ConsoleTarget - Enable OptimizeBufferReuse by default #1907 + Network/NLogViewer/Chainsaw Target - Enabled OptimizeBufferReuse by default, but not for sub classes #2560
• StringBuilderPool - Improved Layout Render Performance by reusing StringBuilders Added Structured events / Message Templates #2208
• JsonLayout - Improved Layout Performance, by optimizing use of StringBuilder Added Structured events / Message Templates #2208
• FileTarget - Faster byte-encoding of log messsages, by using crude Encoding.GetMaxByteCount() instead of exact Encoding.GetByteCount() Added Structured events / Message Templates #2208
• Target - Precalculate Layout should ignore sub-layouts for complex layout (Ex Json) Target - Precalculate Layout should ignore sub-layouts for complex layouts #2378
• MessageLayoutRenderer - Skip string.Format allocation (for caching) when writing to a single target, instead format directly into output buffer. Reduce string allocations for logevents with single target destination #2507

[304NotModified]

Thank you very much!

[snakefoot]

Performance Comparison of NLog 4.4 and NLog 4.5.

Most of the performance improvements disappears in the extra overhead of the new MessageTemplate-parser, but one can still see the reduced memory allocation.

One can also get a glimpse of the extra overhead introduced by parsing the message-template, and capturing the message-properties (NLog45-MT). The memory allocation increases along with the CPU-time.

Still the differences is so small, so I don't think anyone will actually notice 😃

• NLog45-Auto - Positional test message-format, where it detects old style and executes string.Format.
• NLog45-MT - Structured test message-format, where it allocates message-template-properties
• NLog45-SF - Positional test message-format where it forces old style string.Format (ParseMessageTemplates=false)

Logger Name	Messages	Size	Args	Threads	Loggers
PerfLogger	15.000.000	16	0	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	7.786	1.926.497	0	25	50	11.109	2.232,2
NLog45-Auto	7.862	1.907.720	0	22	46	11.328	2.174,8
NLog45-MT	7.882	1.902.961	0	21	44	11.046	2.174,8
NLog45-SF	7.529	1.992.249	0	23	47	11.281	2.175,0

Logger Name	Messages	Size	Args	Threads	Loggers
PerfLogger	15.000.000	128	2	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	28.746	521.805	0	50	101	34.359	6.126,3
NLog45-Auto	29.294	512.037	0	45	91	34.765	6.071,2
NLog45-MT	38.676	387.829	0	66	132	44.046	9.676,9
NLog45-SF	24.061	623.405	0	48	98	29.484	6.070,9

Logger Name	Messages	Size	Args	Threads	Loggers
PerfSyncLogger	10.000.000	16	0	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	7.234	1.382.270	0	0	150	7.312	1.487,8
NLog45-Auto	8.420	1.187.620	0	0	145	8.421	1.449,7
NLog45-MT	8.355	1.196.749	0	0	142	8.359	1.449,7
NLog45-SF	8.146	1.227.449	0	0	142	8.187	1.449,7

Logger Name	Messages	Size	Args	Threads	Loggers
PerfSyncLogger	10.000.000	128	2	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	22.116	452.147	0	0	406	22.140	4.082,0
NLog45-Auto	23.740	421.215	0	0	401	23.796	4.043,8
NLog45-MT	29.328	340.964	0	0	644	29.375	6.447,3
NLog45-SF	19.859	503.535	0	0	401	19.843	4.043,8

Logger Name	Messages	Size	Args	Threads	Loggers
Logger	10.000.000	16	0	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	21.000	476.172	0	30	61	35.312	4.999,3
NLog45-Auto	19.927	501.810	0	27	54	33.890	4.275,8
NLog45-MT	19.841	503.999	0	28	56	34.265	4.275,8
NLog45-SF	19.645	509.032	0	27	55	33.828	4.274,6

Logger Name	Messages	Size	Args	Threads	Loggers
Logger	10.000.000	128	2	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	29.592	337.919	0	44	88	52.500	9.797,4
NLog45-Auto	27.019	370.105	0	76	154	49.718	9.032,5
NLog45-MT	32.273	309.853	0	99	206	51.343	11.512,1
NLog45-SF	25.690	389.255	0	43	87	50.593	9.034,5

Logger Name	Messages	Size	Args	Threads	Loggers
Logger	10.000.000	64	2	2	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	25.592	390.740	0	38	77	68.156	7.366,7
NLog45-Auto	23.088	433.121	0	54	115	65.765	6.603,2
NLog45-MT	29.267	341.676	0	84	183	74.359	9.083,8
NLog45-SF	22.116	452.147	0	36	73	60.640	6.605,5

Logger Name	Messages	Size	Args	Threads	Loggers
Logger	10.000.000	64	2	4	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	42.338	236.190	0	33	66	107.703	7.369,3
NLog45-Auto	39.629	252.335	0	31	63	109.953	6.604,3
NLog45-MT	29.062	344.085	0	61	130	113.406	9.081,7
NLog45-SF	40.200	248.752	0	31	62	107.281	6.604,3

Logger Name	Messages	Size	Args	Threads	Loggers
Logger	10.000.000	64	2	8	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	61.379	162.921	0	30	61	199.218	7.377,2
NLog45-Auto	59.303	168.623	0	27	56	196.218	6.613,5
NLog45-MT	54.293	184.183	0	37	75	185.734	9.091,0
NLog45-SF	58.802	170.061	0	27	55	196.734	6.615,8

Logger Name	Messages	Size	Args	Threads	Loggers
JsonLogger	10.000.000	16	0	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	36.198	276.254	0	96	193	38.812	8.358,5
NLog45-Auto	32.983	303.182	0	27	57	35.421	2.825,9
NLog45-MT	32.613	306.618	0	25	53	35.156	2.825,8
NLog45-SF	31.984	312.651	0	28	58	34.453	2.825,7

Logger Name	Messages	Size	Args	Threads	Loggers
JsonLogger	10.000.000	128	2	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	56.170	178.028	0	137	275	58.921	19.577,8
NLog45-Auto	55.063	181.607	1	56	113	58.531	7.906,9
NLog45-MT	69.725	143.419	0	77	155	74.187	11.000,0
NLog45-SF	44.316	225.648	0	49	103	47.828	5.041,2

Logger Name	Messages	Size	Args	Threads	Loggers
PerfArchiveLogger	10.000.000	16	0	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	12.610	793.000	0	0	147	12.578	1.487,8
NLog45-Auto	12.056	829.398	0	0	141	12.015	1.449,7
NLog45-MT	12.181	820.922	0	0	142	12.125	1.449,7
NLog45-SF	11.745	851.415	0	0	143	11.765	1.449,7

Logger Name	Messages	Size	Args	Threads	Loggers
SyncLogger	10.000.000	16	0	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	31.195	320.560	0	0	247	31.046	2.479,7
NLog45-Auto	31.785	314.605	0	0	168	31.546	1.754,9
NLog45-MT	32.391	308.720	0	0	168	32.312	1.754,9
NLog45-SF	30.856	324.076	0	0	169	30.812	1.754,9

Logger Name	Messages	Size	Args	Threads	Loggers
SyncLogger	10.000.000	128	2	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	46.390	215.562	0	0	508	46.359	5.112,1
NLog45-Auto	47.355	211.169	0	0	435	47.218	4.349,2
NLog45-MT	54.458	183.626	0	0	666	54.343	6.752,5
NLog45-SF	43.704	228.811	0	0	434	43.687	4.349,3

Logger Name	Messages	Size	Args	Threads	Loggers
SimpleLogger	10.000.000	16	0	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	27.320	366.023	0	25	51	29.796	2.482,3
NLog45-Auto	26.474	377.717	0	16	35	28.921	1.757,6
NLog45-MT	26.624	375.587	0	15	34	28.906	1.757,6
NLog45-SF	26.274	380.593	0	15	33	28.578	1.757,6

Logger Name	Messages	Size	Args	Threads	Loggers
SimpleLogger	10.000.000	128	2	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	42.277	236.532	0	36	73	46.609	5.117,2
NLog45-Auto	41.035	243.690	0	32	66	44.515	4.354,2
NLog45-MT	48.814	204.858	0	46	94	52.875	6.757,9
NLog45-SF	38.244	261.474	0	33	67	42.046	4.354,1

Logger Name	Messages	Size	Args	Threads	Loggers
SimpleLogger	10.000.000	64	2	2	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	36.006	277.729	0	29	58	42.187	3.897,0
NLog45-Auto	35.582	281.039	0	22	46	41.343	3.133,6
NLog45-MT	43.285	231.022	0	38	79	49.093	5.536,1
NLog45-SF	33.665	297.040	0	21	45	39.156	3.131,7

Logger Name	Messages	Size	Args	Threads	Loggers
SimpleLogger	10.000.000	64	2	4	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	41.850	238.944	0	29	60	71.093	3.897,3
NLog45-Auto	38.907	257.022	0	24	49	60.296	3.134,3
NLog45-MT	46.438	215.338	0	41	83	70.078	5.540,4
NLog45-SF	37.166	269.058	0	23	49	55.234	3.134,1

Logger Name	Messages	Size	Args	Threads	Loggers
SimpleLogger	10.000.000	64	2	8	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	60.767	164.560	0	29	59	149.046	3.899,7
NLog45-Auto	56.868	175.844	0	22	47	146.203	3.136,2
NLog45-MT	64.014	156.214	0	42	85	153.375	5.541,0
NLog45-SF	56.572	176.764	0	22	46	146.796	3.136,1

Logger Name	Messages	Size	Args	Threads	Loggers
MultiLogger	10.000.000	16	0	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	19.500	512.806	1	59	147	25.265	4.841,5
NLog45-Auto	19.567	511.062	1	55	130	27.671	4.125,1
NLog45-MT	19.795	505.172	0	50	133	30.125	4.128,5
NLog45-SF	19.497	512.891	0	51	128	28.171	4.123,3

Logger Name	Messages	Size	Args	Threads	Loggers
MultiLogger	10.000.000	128	2	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Alloc (MB)
NLog44	32.587	306.870	5	118	530	81.093	9.679,5
NLog45-Auto	36.614	273.116	3	130	674	102.750	8.930,1
NLog45-MT	44.163	226.428	6	164	977	130.343	11.405,6
NLog45-SF	33.410	299.305	4	129	565	85.250	8.922,9

[304NotModified]

looks good!

MT will be only a good option if you're really using structured logging, isn't?

[304NotModified]

are the message count per thread? as more threads = slower? (comparing the 8 threads to the 4 and 2)

[snakefoot]

looks good!

Yes very happy about not having ruined performance completely for all existing users. And also very happy about giving good performance to those who wants to explore structured-logging.

MT will be only a good option if you're really using structured logging, isn't?

NLog45-MT is the same configuration as NLog45-Auto. I have just changed the performance-tester to generate structured-logging test-messages, so it starts to capture the message-properties (Activates the entire MessagetTemplate-Parser engine for real)

[snakefoot]

are the message count per thread? as more threads = slower? (comparing the 8 threads to the 4 and 2)

The message count is the same. Just more threads calling the logger-object concurrently. This gives an overhead when multiple threads are hitting the same target, thus slowing performance (waiting for the other threads to leave the target).

You can see the non-sync-tests performs better when going from 1 thread to 2 threads, but when reaching 4 threads then the target-monitor-lock starts to hurt. The monitor-lock is needed to protect the layoutrenderers as not all can handle multiple threads. I tried to minimize the scope of the target-lock with #1700

I guess one could consider replacing the lock-queue on the async-wrapper with the concurrentqueue, when using NetStandard2.0. But all earlier version of ConcurrentQueue actually performs worse than lock-queue, and those versions also generate a lot of extra allocations. This will help when all layout doesn't use layoutrenderer that require precalculation (See SimpleLogger-tests)

But again it is seldom that multi-threaded applications are so aggressive about logging, that their bottleneck becomes the NLog-targets. Usually threads seldom meet each other inside NLog.

[304NotModified]

@snakefoot do you like to write a post on nlog-project.org for this? (http://nlog-project.org/archives/)

[snakefoot]

Think you are doing a great job already. And the MessageTemplate logic is your creation.

[304NotModified]

See https://github.com/NLog/NLog/blob/master/CHANGELOG.md

@snakefoot
thanks for keeping the import changes up-to-date!