Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix threadsafe issue of GetLogger / GetCurrentClassLogger (+improve performance) #1310

Merged
merged 1 commit into from
Mar 21, 2016

Conversation

304NotModified
Copy link
Member

another try for #1262

Fix PrecalculateStackTraceUsage for threadsafe issues in objectscaner.FindReachableObjects

@@ -92,17 +94,21 @@ internal void PrecalculateStackTraceUsage()

// find all objects which may need stack trace
// and determine maximum
foreach (var item in ObjectGraphScanner.FindReachableObjects<IUsesStackTrace>(this))
// only the target can have IUsesStackTrace
if (Target != null)
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Don't you need to recurse NextInChain as well? In case those LayoutRenderers require stacktraces?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

AFAIK that isn't needed. This call is invoked for every targerwithchain. But please correct me if I missed something.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

From what I can see it's definitely needed: The root of the chain is used here to determine which kind of stacktrace is needed, then the chain itself is processed later in a loop.
The PrecalculateStackTraceUsage is also only called for the root of the chain, so only the StackTraceUsage of the root is valid.

@Taloth
Copy link

Taloth commented Mar 20, 2016

I noticed this PR after investigating an initialization performance issue when using ~150 loggers with 6 logging rules (on NLog 4.2.3). PrecalculateStackTraceUsage would end up calling the ObjectGraphScanner quite often, and we all know Reflection isn't fast. Disabling it reduced app startup from 8 sec to 1 sec, but that's by no means a solution.
Imagine my delight when discovering that someone was already improving it 😄

Doing the scanning during Initialize is definitely an improvement.

Allowing GetAllLayouts to do lazyloading is a bit risky, coz that potentially conflicts with another thread calling GetLogger. I assume there aren't any guarantees that the user calls ReconfigExistingLoggers after configuring, right?

Isn't it ridiculous the amount of work done to determine what kind of stacktrace is needed...

@304NotModified
Copy link
Member Author

@Taloth

Well getting stacktrace costs a lot at runtime.

But there is also a thread-safe issue here which I try to solve without many locks.

Can you test the performance after I get this working?

@codecov-io
Copy link

Current coverage is 74.99%

Merging #1310 into master will increase coverage by +0.01% as of 871f7c6

@@            master   #1310   diff @@
======================================
  Files          267     267       
  Stmts        15451   15458     +7
  Branches      1622    1622       
  Methods          0       0       
======================================
+ Hit          11586   11593     +7
  Partial        382     382       
  Missed        3483    3483       

Review entire Coverage Diff as of 871f7c6


Uncovered Suggestions

  1. +0.10% via ...gingConfiguration.cs#282...295
  2. +0.10% via ...gingConfiguration.cs#248...261
  3. +0.10% via ...argets/FileTarget.cs#1713...1725
  4. See 7 more...

Powered by Codecov. Updated on successful CI builds.

…ndReachableObjects

by replacing objectscanner and let SimpleLayout implement IUsesStackTrace
@304NotModified 304NotModified force-pushed the fix-threadsafe-PrecalculateStackTraceUsage branch from 8398327 to 1471656 Compare March 20, 2016 22:51
@304NotModified
Copy link
Member Author

As the unit test fails irregular:

Rebased other open PRs to repeatedly test this issue:
#1309, #1299, #1286, #1266, #1261

@304NotModified 304NotModified changed the title Fix threadsafe issue of ScanProperties - 4 Fix threadsafe issue of GetLogger / GetCurrentClassLogger (+improve performance) Mar 21, 2016
@304NotModified
Copy link
Member Author

All PRs are succeeding so tested at least 12 times (6 PRs)

304NotModified added a commit that referenced this pull request Mar 21, 2016
…aceUsage

Fix threadsafe issue of GetLogger / GetCurrentClassLogger (+improve performance)
@304NotModified 304NotModified merged commit 16a0bee into master Mar 21, 2016
@304NotModified 304NotModified added this to the 4.3 milestone Mar 21, 2016
@304NotModified 304NotModified added bug Bug report / Bug fix performance labels Mar 21, 2016
@Taloth
Copy link

Taloth commented Mar 21, 2016

Performance is good, same 1 s startup time as when I disabled it entirely.

However, you still need to process NextInChain. (I assume you missed my comment from earlier.)

Also, FindAllLayouts() currently recurses into Layout itself, which isn't needed. There is a performance gain when adding a predicate to the scanner, but it only becomes noticeable when I run ReconfigExistingLoggers like 100x in a loop, so personally i'm not too worried that it takes a whopping 8ms instead of 6ms.

@304NotModified
Copy link
Member Author

However, you still need to process NextInChain. (I assume you missed my comment from earlier.)

Missed indeed your 2nd comment. Will check now. Thanks!

@304NotModified
Copy link
Member Author

Also, FindAllLayouts() currently recurses into Layout itself, which isn't needed.

Can you elaborate on that? Thanks!

@Taloth
Copy link

Taloth commented Mar 22, 2016

FindAllLayouts uses ObjectGraphScanner, which checks all properties on the Target and it's hierarchy. When it finds a Layout instance it adds it to the resultset but it also it dives into the properties of the Layout and it's children (LayoutRenderers for example). So it scans more objects that strictly required.
But as I said it's no big deal, the performance difference is negligible.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Bug report / Bug fix performance
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants