Better Async performance with many concurrent logger threads (up to 500%+) - Async attribute and AsyncWrapper #2650

snakefoot · 2018-04-07T00:12:03Z

ConcurrentQueue works very well in NetCore2. But not sure when the improvements will get to NetFramework.

When 8 threads are attacking the same async-wrapper, then the ConcurrentRequestQueue performs twice as fast on NetCore2. This should help fix #2627

codecov · 2018-04-07T00:29:58Z

Codecov Report

Merging #2650 into master will decrease coverage by <1%.
The diff coverage is 81%.

@@           Coverage Diff           @@
##           master   #2650    +/-   ##
=======================================
- Coverage      81%     81%   -<1%     
=======================================
  Files         326     327     +1     
  Lines       24414   24564   +150     
  Branches     3107    3135    +28     
=======================================
+ Hits        19689   19793   +104     
- Misses       3863    3920    +57     
+ Partials      862     851    -11

snakefoot · 2018-04-09T20:58:52Z

After making some performance tests, then it looks like the allocations caused by ConcurrentQueue are dwarfed by the ones coming from NLog. Decided to enable the ConcurrentRequestQueue by default.

This is the performance results when combined together with #2653

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

Test Name	Time (ms)	Msgs/sec	GC1	GC0	CPU (ms)	Alloc (MB)
Master	11.522	867.848	20	41	16.156	6.256,8
PR (NetCore2)	11.431	874.762	22	46	14.296	Unknown
PR (Net471)	11.355	880.667	13	27	17.234	6.451,8

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

Test Name	Time (ms)	Msgs/sec	GC1	GC0	CPU (ms)	Alloc (MB)
Master	30.595	326.845	13	26	112.328	6.329,7
PR (NetCore2)	9.723	1.028.384	14	28	19.062	Unknown
PR (Net471)	11.213	891.809	9	18	18.281	6.539,0

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

Test Name	Time (ms)	Msgs/sec	GC1	GC0	CPU (ms)	Alloc (MB)
Master	41.264	242.337	13	26	158.953	6.338,1
PR (NetCore2)	9.669	1.034.186	14	28	17.109	Unknown
PR (Net471)	10.881	918.971	9	19	20.359	6.549,8

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

Test Name	Time (ms)	Msgs/sec	GC1	GC0	CPU (ms)	Alloc (MB)
Master	55.762	179.330	13	26	218.984	6.343,9
PR (NetCore2)	9.531	1.049.191	13	27	20.750	Unknown
PR (Net471)	10.956	912.693	9	18	23.406	6.556,8

snakefoot · 2018-04-09T21:11:23Z

Looks like the Net40 ConcurrencyQueue can seem dangerous:

https://blogs.msdn.microsoft.com/pfxteam/2012/05/08/concurrentqueuet-holding-on-to-a-few-dequeued-elements/
https://blog.mischel.com/2011/03/22/memory-leak-in-concurrentqueue/

Will only have it enabled by default on NETSTANDARD2_0 to avoid random complaints.

304NotModified · 2018-04-09T22:23:30Z

Wow! nice improvements

The queue is used for the async and buffering target wrapper, isn't? (Now on mobile)

snakefoot · 2018-04-09T22:31:09Z

The queue is used for the async and buffering target wrapper, isn't?

Nope it is only used by the AsyncTargetWrapper. The BufferingTargetWrapper uses a container called LogEventInfoBuffer.

304NotModified · 2018-04-09T22:41:44Z

I changed the title to make it more clear for outsiders :)

snakefoot · 2018-04-09T22:43:41Z

I changed the title to make it more clear for outsiders :)

Well you only see the performance improvement if you are very aggressive against one async-target. Normal users will probably see a very small performance drop (See my test with 1 thread). But it is a better out-of-the-box-experience for those special cases.

Also the performance improvement only works when ALL layout-renderers are thread-safe or thread-agnostic. See also #2653

src/NLog/Targets/Wrappers/AsyncTargetWrapper.cs

304NotModified · 2018-04-09T22:44:32Z

src/NLog/Targets/Wrappers/AsyncTargetWrapper.cs

+            get { return _requestQueue is AsyncRequestQueue; }
+            set
+            {
+                if (value != _requestQueue is AsyncRequestQueue)


I prefer the pattern matching syntax her, eg is AsyncRequestQueue queue (c# 7)

Not sure I understand, but will add some parentheses.

When pattern matching then the cast (line below) is not needed.

Still don't understand

304NotModified · 2018-04-09T22:46:12Z

src/NLog/Targets/Wrappers/ConcurrentRequestQueue.cs

+        /// <summary>
+        /// Gets the number of requests currently in the queue.
+        /// </summary>
+        public int Count => (int)_count;


Isn't this tricky?

The Count is only there for debugging. IsEmpty is the one used for decisions. Think the container (or computer) will break if more than two billion items.

OK clear, maybe we should set that in the <remarks>

src/NLog/Targets/Wrappers/AsyncTargetWrapper.cs

304NotModified

Looks good, some small questions about the structure of the code.

If preferred, I could also push a commit on this.

304NotModified · 2018-08-05T21:01:56Z

src/NLog/Targets/Wrappers/AsyncTargetWrapper.cs

+            get { return _requestQueue is AsyncRequestQueue; }
+            set
+            {
+                if (value != (_requestQueue is AsyncRequestQueue))


I would prefer having a backend boolean for this (e.g. _forceLockingQueue), and and reset _requestQueue if value != _forceLockingQueue .

That would be more logical IMO. What do you think?

src/NLog/Targets/Wrappers/AsyncTargetWrapper.cs

304NotModified · 2018-08-05T21:06:34Z

src/NLog/Targets/Wrappers/ConcurrentRequestQueue.cs

+        /// <summary>
+        /// Gets the number of requests currently in the queue.
+        /// </summary>
+        public int Count => (int)_count;


OK clear, maybe we should set that in the <remarks>

304NotModified · 2018-08-05T21:14:03Z

PS @snakefoot

As you may have noticed, we have now also a "dev" branch. I'm switching to the gitflow-workflow because:

PRs are too long open
There are too many features in a patch release, that should be in a minor release. (see semver

I use it also at work at some larger projects, it work pretty well.

This means that important bugfixes should be to "master", and need a "backport" to "dev".

snakefoot · 2018-08-06T10:08:55Z

I dont mind the current flow, where small PRs can race complicated PRs. But I can see the need for a place to prepare the 4.6 release and create beta version. Think it is okay that complicated PRs can stay pending for a long time. Kind of inspires you to make small and simple PRs. Something that I need to practise :)

304NotModified · 2018-08-06T13:55:25Z

Think it is okay that complicated PRs can stay pending for a long time. Kind of inspires you to make small and simple PRs. Something that I need to practise :)

yeah I like also small and simple PRs. Easier to review/test/understand.

snakefoot · 2018-08-12T16:47:34Z

@304NotModified Updated the PR with the requested changes.

304NotModified · 2018-08-14T20:08:28Z

nice!!

snakefoot · 2018-08-14T20:13:25Z

@304NotModified You merged this into NLog:master and not NLog:dev

304NotModified · 2018-08-14T20:17:19Z

ooops. thx

304NotModified · 2018-08-14T20:23:49Z

now on dev

snakefoot · 2019-02-21T22:45:26Z

Updated documentation: https://github.com/NLog/NLog/wiki/AsyncWrapper-target

304NotModified · 2019-02-22T14:20:09Z

thanks!

snakefoot force-pushed the AsyncConcurrentRequestQueue branch from f4f44d0 to 4a358b5 Compare April 7, 2018 00:14

snakefoot force-pushed the AsyncConcurrentRequestQueue branch 9 times, most recently from 9f0f9c5 to 445f666 Compare April 7, 2018 19:49

snakefoot mentioned this pull request Apr 7, 2018

LayoutRenderer ThreadSafe Attribute introduced to allow lock free Precalculate + other small performance improvements #2653

Merged

snakefoot force-pushed the AsyncConcurrentRequestQueue branch 3 times, most recently from af3d0b9 to efe6874 Compare April 9, 2018 20:52

snakefoot force-pushed the AsyncConcurrentRequestQueue branch from efe6874 to 7b972de Compare April 9, 2018 21:05

snakefoot force-pushed the AsyncConcurrentRequestQueue branch from 7b972de to 3ab6284 Compare April 9, 2018 21:15

304NotModified self-assigned this Apr 9, 2018

snakefoot force-pushed the AsyncConcurrentRequestQueue branch from 3ab6284 to e93760f Compare April 9, 2018 22:22

304NotModified added the performance label Apr 9, 2018

304NotModified added this to the 4.5.3 milestone Apr 9, 2018

304NotModified changed the title ~~ConcurrentRequestQueue depends on .NET ConcurrentQueue~~ Async wrapper/attribute, 300-500% performance improvement in .net 4.5+ and .net standard 2+ Apr 9, 2018

304NotModified approved these changes Apr 9, 2018

View reviewed changes

304NotModified added the needs documentation on wiki label Apr 9, 2018

snakefoot force-pushed the AsyncConcurrentRequestQueue branch from 7b5bb24 to 7c9c8b8 Compare July 29, 2018 10:42

304NotModified removed their assignment Aug 2, 2018

304NotModified reviewed Aug 5, 2018

View reviewed changes

snakefoot force-pushed the AsyncConcurrentRequestQueue branch from 7c9c8b8 to 31866a0 Compare August 12, 2018 14:24

ConcurrentRequestQueue depends on .NET ConcurrentQueue

36f9415

snakefoot force-pushed the AsyncConcurrentRequestQueue branch from 31866a0 to 36f9415 Compare August 12, 2018 14:38

304NotModified self-assigned this Aug 12, 2018

304NotModified changed the title ~~Async wrapper/attribute with better performance when many concurrent logger threads~~ Better Async performance with many concurrent logger threads (up to 500%+) - Async attribute and AsyncWrapper Aug 14, 2018

304NotModified removed the work in progress label Aug 14, 2018

304NotModified approved these changes Aug 14, 2018

View reviewed changes

304NotModified merged commit 523e8da into NLog:master Aug 14, 2018

304NotModified pushed a commit that referenced this pull request Aug 14, 2018

ConcurrentRequestQueue depends on .NET ConcurrentQueue (#2650)

df0b95f

snakefoot added a commit to snakefoot/NLog that referenced this pull request Aug 30, 2018

ConcurrentRequestQueue depends on .NET ConcurrentQueue (NLog#2650)

c6c2298

This was referenced Aug 31, 2018

AsyncTargetWrapper - TimeToSleepBetweenBatches changed default to 1ms #2890

Merged

AsyncTargetWrapper - Allow ForceLockingQueue = false on Net45 #2876

Merged

snakefoot added a commit to snakefoot/NLog that referenced this pull request Nov 4, 2018

ConcurrentRequestQueue depends on .NET ConcurrentQueue (NLog#2650)

4d9e9fc

snakefoot mentioned this pull request Jan 14, 2019

NLog 4.6 RTM todo #3080

Closed

304NotModified added the documentation done all docs done (wiki, api docs, lists on nlog-project.org, xmldocs) label Feb 22, 2019

snakefoot deleted the AsyncConcurrentRequestQueue branch April 4, 2020 13:09

pull-request-size bot added the size/L label Mar 16, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Better Async performance with many concurrent logger threads (up to 500%+) - Async attribute and AsyncWrapper #2650

Better Async performance with many concurrent logger threads (up to 500%+) - Async attribute and AsyncWrapper #2650

snakefoot commented Apr 7, 2018 •

edited

codecov bot commented Apr 7, 2018 •

edited

snakefoot commented Apr 9, 2018 •

edited

snakefoot commented Apr 9, 2018 •

edited

304NotModified commented Apr 9, 2018

snakefoot commented Apr 9, 2018

304NotModified commented Apr 9, 2018

snakefoot commented Apr 9, 2018 •

edited

304NotModified Apr 9, 2018

snakefoot Apr 9, 2018

304NotModified Apr 9, 2018

snakefoot Apr 11, 2018

304NotModified Apr 9, 2018

snakefoot Apr 9, 2018 •

edited

304NotModified Aug 5, 2018

304NotModified left a comment

304NotModified Aug 5, 2018

304NotModified Aug 5, 2018

304NotModified commented Aug 5, 2018

snakefoot commented Aug 6, 2018 via email •

edited

304NotModified commented Aug 6, 2018

snakefoot commented Aug 12, 2018

304NotModified commented Aug 14, 2018

snakefoot commented Aug 14, 2018 •

edited

304NotModified commented Aug 14, 2018 •

edited

304NotModified commented Aug 14, 2018

snakefoot commented Feb 21, 2019

304NotModified commented Feb 22, 2019

Better Async performance with many concurrent logger threads (up to 500%+) - Async attribute and AsyncWrapper #2650

Better Async performance with many concurrent logger threads (up to 500%+) - Async attribute and AsyncWrapper #2650

Conversation

snakefoot commented Apr 7, 2018 • edited

codecov bot commented Apr 7, 2018 • edited

Codecov Report

snakefoot commented Apr 9, 2018 • edited

snakefoot commented Apr 9, 2018 • edited

304NotModified commented Apr 9, 2018

snakefoot commented Apr 9, 2018

304NotModified commented Apr 9, 2018

snakefoot commented Apr 9, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

snakefoot Apr 9, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

304NotModified left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

304NotModified commented Aug 5, 2018

snakefoot commented Aug 6, 2018 via email • edited

304NotModified commented Aug 6, 2018

snakefoot commented Aug 12, 2018

304NotModified commented Aug 14, 2018

snakefoot commented Aug 14, 2018 • edited

304NotModified commented Aug 14, 2018 • edited

304NotModified commented Aug 14, 2018

snakefoot commented Feb 21, 2019

304NotModified commented Feb 22, 2019

snakefoot commented Apr 7, 2018 •

edited

codecov bot commented Apr 7, 2018 •

edited

snakefoot commented Apr 9, 2018 •

edited

snakefoot commented Apr 9, 2018 •

edited

snakefoot commented Apr 9, 2018 •

edited

snakefoot Apr 9, 2018 •

edited

snakefoot commented Aug 6, 2018 via email •

edited

snakefoot commented Aug 14, 2018 •

edited

304NotModified commented Aug 14, 2018 •

edited