AppenderSkeletion lock in DoAppend

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

AppenderSkeletion lock in DoAppend

Gert Kello
Hi.

I'm trying to create a database appender which high throughput... I looked at code in AppenderSekeletion.DoAppend() method and saw following comment:

    public void DoAppend(LoggingEvent loggingEvent)
    {
      // This lock is absolutely critical for correct formatting
      // of the message in a multi-threaded environment.  Without
      // this, the message may be broken up into elements from
      // multiple thread contexts (like get the wrong thread ID).

      lock (this)
      {

I would like to remove this lock from my code but there's a couple of issues I do not understand:
1. As I do not know the internals of log4net well enough I do not understand why lock is important for message formatting? Is it because the Layout.Format is not supposed to be thread safe? Or is it because the same instance of m_renderWriter could be used by multiple threads (well, usage of m_renderWriter is protected by another lock, added later. But AFAIK the RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)
2. The comment does not mention that lock is crucial for m_recursiveGuard to work correctly. That's my main complaint: I almost overlooked the issue of potentially skipped logging events.
3. What about implementations of IFilter.Decide? Are those (supposed to be) thread safe?

Gert
Reply | Threaded
Open this post in threaded view
|

AW: AppenderSkeletion lock in DoAppend

Dominik Psenner

Hi,

 

from what I can recall it could happen that the formatted representation of a logging event gets mixed up with data from other events and thus the characters streamed to a sink become garbage (i.e. a file, console, ..) if this lock is removed.

 

Internally a lot of things are cached to improve performance and these caches actually require proper locking.

 

But my memory might be wrong, so feel free to remove the lock and let several threads log events to your appender to see if it can handle it properly. J

 

Cheers

 

Von: Gert Kello [mailto:[hidden email]]
Gesendet: Mittwoch, 04. März 2015 09:28
An: [hidden email]
Bet
reff: AppenderSkeletion lock in DoAppend

 

Hi.

I'm trying to create a database appender which high throughput... I looked at code in AppenderSekeletion.DoAppend() method and saw following comment:

    public void DoAppend(LoggingEvent loggingEvent)
    {
      // This lock is absolutely critical for correct formatting
      // of the message in a multi-threaded environment.  Without
      // this, the message may be broken up into elements from
      // multiple thread contexts (like get the wrong thread ID).

      lock (this)
      {

I would like to remove this lock from my code but there's a couple of issues I do not understand:

1. As I do not know the internals of log4net well enough I do not understand why lock is important for message formatting? Is it because the Layout.Format is not supposed to be thread safe? Or is it because the same instance of m_renderWriter could be used by multiple threads (well, usage of m_renderWriter is protected by another lock, added later. But AFAIK the RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)

2. The comment does not mention that lock is crucial for m_recursiveGuard to work correctly. That's my main complaint: I almost overlooked the issue of potentially skipped logging events.

3. What about implementations of IFilter.Decide? Are those (supposed to be) thread safe?

Gert

Reply | Threaded
Open this post in threaded view
|

Re: AppenderSkeletion lock in DoAppend

Gert Kello
But what about this m_recursiveGuard? Is the recursion protection needed? Perhaps it is, if log saving code logs something by itself? (Like warning that database operation takes longer than expected)?

Well, as I plan to make the database saving asyn I need to tackle this problem anyway... I think I would like to log the performance problem. But not when the problem occurs during saving log about the same performance problem. Is there any guideline how to write such code? Something like using OnlyOnceErrorHandler or is there anything similar for warnings?

Gert

On 4 March 2015 at 15:38, Dominik Psenner <[hidden email]> wrote:

Hi,

 

from what I can recall it could happen that the formatted representation of a logging event gets mixed up with data from other events and thus the characters streamed to a sink become garbage (i.e. a file, console, ..) if this lock is removed.

 

Internally a lot of things are cached to improve performance and these caches actually require proper locking.

 

But my memory might be wrong, so feel free to remove the lock and let several threads log events to your appender to see if it can handle it properly. J

 

Cheers

 

Von: Gert Kello [mailto:[hidden email]]
Gesendet: Mittwoch, 04. März 2015 09:28
An: [hidden email]
Bet
reff: AppenderSkeletion lock in DoAppend

 

Hi.

I'm trying to create a database appender which high throughput... I looked at code in AppenderSekeletion.DoAppend() method and saw following comment:

    public void DoAppend(LoggingEvent loggingEvent)
    {
      // This lock is absolutely critical for correct formatting
      // of the message in a multi-threaded environment.  Without
      // this, the message may be broken up into elements from
      // multiple thread contexts (like get the wrong thread ID).

      lock (this)
      {

I would like to remove this lock from my code but there's a couple of issues I do not understand:

1. As I do not know the internals of log4net well enough I do not understand why lock is important for message formatting? Is it because the Layout.Format is not supposed to be thread safe? Or is it because the same instance of m_renderWriter could be used by multiple threads (well, usage of m_renderWriter is protected by another lock, added later. But AFAIK the RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)

2. The comment does not mention that lock is crucial for m_recursiveGuard to work correctly. That's my main complaint: I almost overlooked the issue of potentially skipped logging events.

3. What about implementations of IFilter.Decide? Are those (supposed to be) thread safe?

Gert


Reply | Threaded
Open this post in threaded view
|

AW: AppenderSkeletion lock in DoAppend

Dominik Psenner

A log event might be badly programmed and recursive by definition. Think of two objects that try each to log while trying to format each other:

 

A {

DoWork() {

   Log(“A: {0}”, B)

}

}

B {

DoWork () {

   Log(“B: {0}”, A)

}

}

 

I might be wrong, but something like that does the recursive guard detect and resolve.

 

For the other question you’ll have to accept my apologies because I can’t answer the question „how to write code“. J

 

Von: Gert Kello [mailto:[hidden email]]
Gesendet: Mittwoch, 04. März 2015 15:16
An: Log4NET User
Betreff: Re: AppenderSkeletion lock in DoAppend

 

But what about this m_recursiveGuard? Is the recursion protection needed? Perhaps it is, if log saving code logs something by itself? (Like warning that database operation takes longer than expected)?

Well, as I plan to make the database saving asyn I need to tackle this problem anyway... I think I would like to log the performance problem. But not when the problem occurs during saving log about the same performance problem. Is there any guideline how to write such code? Something like using OnlyOnceErrorHandler or is there anything similar for warnings?

 

Gert

 

On 4 March 2015 at 15:38, Dominik Psenner <[hidden email]> wrote:

Hi,

 

from what I can recall it could happen that the formatted representation of a logging event gets mixed up with data from other events and thus the characters streamed to a sink become garbage (i.e. a file, console, ..) if this lock is removed.

 

Internally a lot of things are cached to improve performance and these caches actually require proper locking.

 

But my memory might be wrong, so feel free to remove the lock and let several threads log events to your appender to see if it can handle it properly. J

 

Cheers

 

Von: Gert Kello [mailto:[hidden email]]
Gesendet: Mittwoch, 04. März 2015 09:28
An: [hidden email]
Bet
reff: AppenderSkeletion lock in DoAppend

 

Hi.

I'm trying to create a database appender which high throughput... I looked at code in AppenderSekeletion.DoAppend() method and saw following comment:

    public void DoAppend(LoggingEvent loggingEvent)
    {
      // This lock is absolutely critical for correct formatting
      // of the message in a multi-threaded environment.  Without
      // this, the message may be broken up into elements from
      // multiple thread contexts (like get the wrong thread ID).

      lock (this)
      {

I would like to remove this lock from my code but there's a couple of issues I do not understand:

1. As I do not know the internals of log4net well enough I do not understand why lock is important for message formatting? Is it because the Layout.Format is not supposed to be thread safe? Or is it because the same instance of m_renderWriter could be used by multiple threads (well, usage of m_renderWriter is protected by another lock, added later. But AFAIK the RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)

2. The comment does not mention that lock is crucial for m_recursiveGuard to work correctly. That's my main complaint: I almost overlooked the issue of potentially skipped logging events.

3. What about implementations of IFilter.Decide? Are those (supposed to be) thread safe?

Gert

 

Reply | Threaded
Open this post in threaded view
|

Re: AppenderSkeletion lock in DoAppend

Gert Kello
Sorry but I fail to understand this example... Log event programmed? I didn't know I can program it... (without changing log4net source).

So far I know/see two cases where recursive logging can happen:
1. Something called from Appender.Append calls anu ILog logging methods
2. According to comment in https://issues.apache.org/jira/browse/LOG4NET-288 the bad configuration can also cause the recursion.

I assume that's all that can cause recursions... As I plan to save logs from another thread I have to pay special attention to item 1. as any logging from database save procedure would cause the same logging to be executed again (tested). Without recursion but still flooding log system with endless messages.

But what about IFilter.Decide? Should I assume it is not threadsafe?

Gert


On 4 March 2015 at 16:51, Dominik Psenner <[hidden email]> wrote:

A log event might be badly programmed and recursive by definition. Think of two objects that try each to log while trying to format each other:

 

A {

DoWork() {

   Log(“A: {0}”, B)

}

}

B {

DoWork () {

   Log(“B: {0}”, A)

}

}

 

I might be wrong, but something like that does the recursive guard detect and resolve.

 

For the other question you’ll have to accept my apologies because I can’t answer the question „how to write code“. J

 

Von: Gert Kello [mailto:[hidden email]]
Gesendet: Mittwoch, 04. März 2015 15:16
An: Log4NET User
Betreff: Re: AppenderSkeletion lock in DoAppend

 

But what about this m_recursiveGuard? Is the recursion protection needed? Perhaps it is, if log saving code logs something by itself? (Like warning that database operation takes longer than expected)?

Well, as I plan to make the database saving asyn I need to tackle this problem anyway... I think I would like to log the performance problem. But not when the problem occurs during saving log about the same performance problem. Is there any guideline how to write such code? Something like using OnlyOnceErrorHandler or is there anything similar for warnings?

 

Gert

 

On 4 March 2015 at 15:38, Dominik Psenner <[hidden email]> wrote:

Hi,

 

from what I can recall it could happen that the formatted representation of a logging event gets mixed up with data from other events and thus the characters streamed to a sink become garbage (i.e. a file, console, ..) if this lock is removed.

 

Internally a lot of things are cached to improve performance and these caches actually require proper locking.

 

But my memory might be wrong, so feel free to remove the lock and let several threads log events to your appender to see if it can handle it properly. J

 

Cheers

 

Von: Gert Kello [mailto:[hidden email]]
Gesendet: Mittwoch, 04. März 2015 09:28
An: [hidden email]
Bet
reff: AppenderSkeletion lock in DoAppend

 

Hi.

I'm trying to create a database appender which high throughput... I looked at code in AppenderSekeletion.DoAppend() method and saw following comment:

    public void DoAppend(LoggingEvent loggingEvent)
    {
      // This lock is absolutely critical for correct formatting
      // of the message in a multi-threaded environment.  Without
      // this, the message may be broken up into elements from
      // multiple thread contexts (like get the wrong thread ID).

      lock (this)
      {

I would like to remove this lock from my code but there's a couple of issues I do not understand:

1. As I do not know the internals of log4net well enough I do not understand why lock is important for message formatting? Is it because the Layout.Format is not supposed to be thread safe? Or is it because the same instance of m_renderWriter could be used by multiple threads (well, usage of m_renderWriter is protected by another lock, added later. But AFAIK the RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)

2. The comment does not mention that lock is crucial for m_recursiveGuard to work correctly. That's my main complaint: I almost overlooked the issue of potentially skipped logging events.

3. What about implementations of IFilter.Decide? Are those (supposed to be) thread safe?

Gert

 


Reply | Threaded
Open this post in threaded view
|

AW: AppenderSkeletion lock in DoAppend

Dominik Psenner

Taking this to log4net dev since this goes well beyond the usage of log4net, too.

 

Logs are typically written by software that is programmed, aren’t they? Thus one could happen to recursively trying to log something in his source code without being aware of it. Maybe the example was not clear enough and I apologize for not being verbose enough.

 

I tried to say that a log event could try to get a formatted message of the event by doing an invoke of another method and that method could again try to format the log message by calling the other method. This then ends up in a cyclic/recursive invoke and I believe that the recursive check tries to tackle this issue so that the application does not crash by trying to log something that might be totally unimportant.

 

I’m not sure if I understand what you mean with not threadsafe. A method that is not threadsafe can only be not threadsafe if it modifies data that is out of scope. It’s up to you how you implement the interface, but it might well happen that data gets modified without you being aware of it. One good example is the GlobalContext, which can easily be used in a manner that is not threadsafe at all.

 

Cheers

 

Von: Gert Kello [mailto:[hidden email]]
Gesendet: Donnerstag, 05. März 2015 12:09
An: Log4NET User
Betreff: Re: AppenderSkeletion lock in DoAppend

 

Sorry but I fail to understand this example... Log event programmed? I didn't know I can program it... (without changing log4net source).

So far I know/see two cases where recursive logging can happen:

1. Something called from Appender.Append calls anu ILog logging methods

2. According to comment in https://issues.apache.org/jira/browse/LOG4NET-288 the bad configuration can also cause the recursion.

I assume that's all that can cause recursions... As I plan to save logs from another thread I have to pay special attention to item 1. as any logging from database save procedure would cause the same logging to be executed again (tested). Without recursion but still flooding log system with endless messages.

But what about IFilter.Decide? Should I assume it is not threadsafe?

 

Gert

 

 

On 4 March 2015 at 16:51, Dominik Psenner <[hidden email]> wrote:

A log event might be badly programmed and recursive by definition. Think of two objects that try each to log while trying to format each other:

 

A {

DoWork() {

   Log(“A: {0}”, B)

}

}

B {

DoWork () {

   Log(“B: {0}”, A)

}

}

 

I might be wrong, but something like that does the recursive guard detect and resolve.

 

For the other question you’ll have to accept my apologies because I can’t answer the question „how to write code“. J

 

Von: Gert Kello [mailto:[hidden email]]
Gesendet: Mittwoch, 04. März 2015 15:16
An: Log4NET User
Betreff: Re: AppenderSkeletion lock in DoAppend

 

But what about this m_recursiveGuard? Is the recursion protection needed? Perhaps it is, if log saving code logs something by itself? (Like warning that database operation takes longer than expected)?

Well, as I plan to make the database saving asyn I need to tackle this problem anyway... I think I would like to log the performance problem. But not when the problem occurs during saving log about the same performance problem. Is there any guideline how to write such code? Something like using OnlyOnceErrorHandler or is there anything similar for warnings?

 

Gert

 

On 4 March 2015 at 15:38, Dominik Psenner <[hidden email]> wrote:

Hi,

 

from what I can recall it could happen that the formatted representation of a logging event gets mixed up with data from other events and thus the characters streamed to a sink become garbage (i.e. a file, console, ..) if this lock is removed.

 

Internally a lot of things are cached to improve performance and these caches actually require proper locking.

 

But my memory might be wrong, so feel free to remove the lock and let several threads log events to your appender to see if it can handle it properly. J

 

Cheers

 

Von: Gert Kello [mailto:[hidden email]]
Gesendet: Mittwoch, 04. März 2015 09:28
An: [hidden email]
Bet
reff: AppenderSkeletion lock in DoAppend

 

Hi.

I'm trying to create a database appender which high throughput... I looked at code in AppenderSekeletion.DoAppend() method and saw following comment:

    public void DoAppend(LoggingEvent loggingEvent)
    {
      // This lock is absolutely critical for correct formatting
      // of the message in a multi-threaded environment.  Without
      // this, the message may be broken up into elements from
      // multiple thread contexts (like get the wrong thread ID).

      lock (this)
      {

I would like to remove this lock from my code but there's a couple of issues I do not understand:

1. As I do not know the internals of log4net well enough I do not understand why lock is important for message formatting? Is it because the Layout.Format is not supposed to be thread safe? Or is it because the same instance of m_renderWriter could be used by multiple threads (well, usage of m_renderWriter is protected by another lock, added later. But AFAIK the RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)

2. The comment does not mention that lock is crucial for m_recursiveGuard to work correctly. That's my main complaint: I almost overlooked the issue of potentially skipped logging events.

3. What about implementations of IFilter.Decide? Are those (supposed to be) thread safe?

Gert