LayoutRenderers do not appear to be asynchronous inside an AsyncWrapper?

classic Classic list List threaded Threaded
10 messages Options
Reply | Threaded
Open this post in threaded view
|

LayoutRenderers do not appear to be asynchronous inside an AsyncWrapper?

John Culviner
I have created my own LayoutRenderer to do some heavy reflection and I have noticed that it appears to be blocking the thread calling Log even though I am using an AsyncWrapper.

To demonstrate, the below code with a sleep in it will block the main calling thread for 1 second:

    [LayoutRenderer("objectshredder")]
    public class ObjectShredderLayoutRenderer : LayoutRenderer
    {
        protected override void Append(StringBuilder builder, NLog.LogEventInfo logEvent)
        {
            System.Threading.Thread.Sleep(1000);
        }
    }

If I call the below code in my main thread (configured to use the "objectshredder" layout ) it will write one log entry a second blocking the main thread for 10000 seconds:

            for (int i = 0; i < 10000; i++)
            {
                nlog.Error("some text");
            }

//doesn't get here until 10000 seconds have gone by

I am using the default AsyncWrapper around a File target. Everything is stock in the configuration except adding the ${objectshredder} layout. I was under the impression that the above log call should queue up inside NLog since it is using an async wrapper and not block the main thread. Is there any way to get this behavior? I will take a look at the source code a little bit more too and see what I can find.

Thanks for the help!

John


Reply | Threaded
Open this post in threaded view
|

Re: LayoutRenderers do not appear to be asynchronous inside an AsyncWrapper?

Jarek Kowalski
Administrator
Can you post your config? That should work fine.

Jarek
NLog Blog
Reply | Threaded
Open this post in threaded view
|

Re: LayoutRenderers do not appear to be asynchronous inside an AsyncWrapper?

John Culviner
Hi Jarek, thanks for taking a look at this with me.

I made a new console application just to make sure something wasn't off in my environment below is the app.config I'm using:

<?xml version="1.0"?>
<configuration>

  <configSections>
    <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog"/>
  </configSections>

  <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

    <targets>
      <target name="asyncFile" xsi:type="AsyncWrapper">
        <target name="logfile" xsi:type="File" fileName="file.txt"
          layout="${longdate} ${message} ${objectshredder}"/>
      </target>
    </targets>

    <rules>
      <logger name="*" minlevel="Info" writeTo="asyncFile" />
    </rules>
  </nlog>

  <startup>
    <supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.0"/>
  </startup>
</configuration>

In order to make it easy to look at I also posted the whole project to reproduce the behavior here:
http://johnculviner.com/files/NLogCustomLayoutRenderer.zip

I'll also take a look at the NLog source to see if I can find anything there and keep you posted. Thanks again for the help!

John
Reply | Threaded
Open this post in threaded view
|

Re: LayoutRenderers do not appear to be asynchronous inside an AsyncWrapper?

Jarek Kowalski
Administrator
Ok, I get it now.

What's happening is that NLog is pre-computing the values of all
layouts before it enqueues asynchronous request. The reason is that it
does not know for sure whether all your layout renderers can be safely
computed on another thread. For example if you had a layout renderer
such as ${thread-id} it would return wrong value when computed on
async thread so it must be pre-computed.

The solution here is to mark you LR as [ThreadAgnostic] which will
defer pre-computation if all renderers are marked as such. The caveat
is that you now need to ensure that your rendering is functional on
any thread and only uses data included in LogEventInfo (since
obviously you cannot rely on things like TLS).

BTW. What is the purpose of ${objectshredder} ? Are you looking to
create CSV-like output?

Jarek
NLog Blog
Reply | Threaded
Open this post in threaded view
|

Re: LayoutRenderers do not appear to be asynchronous inside an AsyncWrapper?

John Culviner
Interesting! I hadn't even thought of the need to control what thread logging operations are running on but since your logging operations might be thread dependent that makes perfect sense.

I added the [ThreadAgnostic] and re-ran but I am still experiencing the issue. Perhaps something is wrong with my setup? I dug into the "jkowalski-NLog-f488cd2" RC2.0 source and did a search on ThreadAgnostic and didn't find it being read anywhere in the source (by looking at class attributes at run-time via reflection or what not), only being added as an attribute to various classes.

I have updated the link on my website to reflect this change http://johnculviner.com/files/NLogCustomLayoutRenderer.zip and the issue.

Any thoughts on what I might be missing?

As far as the "ObjectShredder": I thought it might be useful to log the full contents of objects passed into logging when an exception occurs or we are logging at a certain level. I was planning on using reflection to recurse through all the objects passed into the LogEventInfo.Parameters. Based on this I was going to log a basic recursive XML structure of the param object[] passed in. In my own config section I was going to control the maximum list size, recursion depth etc. that was allowed by the "shredder".

Since this object logging will likely only happen at the end of the object life in the main thread I am not worried about it being modified by the main thread while NLog's AsyncWrapper thread is looking at it. It would be nice if the main thread didn't get blocked by the possibly time consuming reflection (what if there is a big list or something... ahh!) since this feature would likely be very useful in a Prod environment. Another thought might be to build some sort of a cache of complied expression accessors to the properties of the objects as they are encountered at run-time to speed thing up (if this is even possible hmm...), then the reflection hit would only occur once.

Thanks for all the help with this, please let me know if there is anything else I could look at to help figure this out.

Thanks!

John
Reply | Threaded
Open this post in threaded view
|

Re: LayoutRenderers do not appear to be asynchronous inside an AsyncWrapper?

Jarek Kowalski
Administrator
Wow. I just realized that somehow I managed to remove code to handle
[ThreadAgnostic] attribute during one of the refactorings.

I don't know how it happened, but I'll be bringing it back. Thanks for
finding the issue - I'll share the code with you for private testing
before I check it in.

Jarek
NLog Blog
Reply | Threaded
Open this post in threaded view
|

Re: LayoutRenderers do not appear to be asynchronous inside an AsyncWrapper?

John Culviner
Ahh that makes sense. I've done that more times than I care to remember trust me! Thanks for the help. NLog is awesome by the way, I am very impressed with the amount of thought that was put into it and how flexible it is. Keep up the good work!

John
Reply | Threaded
Open this post in threaded view
|

Re: LayoutRenderers do not appear to be asynchronous inside an AsyncWrapper?

Jarek Kowalski
Administrator
Can you try the latest build and see whether it works for you? I fixed
handling of [ThreadAgnostic] and added a bunch of unit tests.

Sources: https://github.com/jkowalski/NLog
Binaries:http://nlog.codeplex.com/releases/view/69879

Jarek
NLog Blog
Reply | Threaded
Open this post in threaded view
|

Re: LayoutRenderers do not appear to be asynchronous inside an AsyncWrapper?

John Culviner
Awesome, works great now, thanks a lot for the help with this!

I ran my test with the sleep in there and it isn't blocking the main thread anymore. I also tried removing the [ThreadAgnostic] and it appears to not be blocking the main thread either. I always plan to not having it blocking, but did you say earlier that anything that isn't marked as [ThreadAgnostic] should run on the main thread (thus blocking it?). Either way thanks for the help, great job with NLog!

Also I was wondering could I get Wiki access, I was thinking it'd be cool to have a tutorial on how to make a custom LayoutRenderer since I have gone through the process here and I can put something in about the importance of ThreadAgnostic etc.

John
Reply | Threaded
Open this post in threaded view
|

Re: LayoutRenderers do not appear to be asynchronous inside an AsyncWrapper?

Jarek Kowalski
Administrator
Sure, create an account and tell me the login and I'll grant you access.

Jarek
NLog Blog