You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4net-user@logging.apache.org by Graham Walsh <gr...@calyon.com> on 2009/02/25 14:33:15 UTC
DEBUG vs INFO
Hi,
I just switch from DEBUG to INFO in our application logging and the
difference is pretty much stunning. E.G. our perf has gone from 23
seconds down to 14 because of the change. Is this a known issue. i.e.
debug log level is expected to impose this kind of overhead.
Thanks
Graham
RE: DEBUG vs INFO
Posted by "Walden H. Leverich" <Wa...@TechSoftInc.com>.
> DEBUG info at no price.. so to speak
Can't help on the buffering, but your comment above isn't necessarily
correct at any rate. It depends on where the performance his of the
Debug() call is. Sure there's a hit on writing the log to disk, and the
buffering helps there, but there is also the hit of generating the text
for the debug call in the first place. There's the method call, there's
the string concatenation, there's likely numerous .ToString() calls, if
you're looking for line#s in the log file then there's the (high) cost
of getting that information. None of these issues will be removed by
buffering the write to disk. I'm not saying buffing won't buy you
something, it will. But it doesn't give you DEBUG at no price.
-Walden
--
Walden H Leverich III
Tech Software
(516) 627-3800 x3051
WaldenL@TechSoftInc.com <ma...@TechSoftInc.com>
http://www.TechSoftInc.com <http://www.techsoftinc.com/>
Quiquid latine dictum sit altum viditur.
(Whatever is said in Latin seems profound.)
RE: DEBUG vs INFO
Posted by Graham Walsh <gr...@calyon.com>.
Sorry, ignore that last email, its actually working as I want.
Does anybody know if its possible to configure a RichTextBoxAppender (log output goes to a rich text box, its a contribution by another engineer not the original author(s) of log4net, (I think). If I can get buffering in place for the RichTextBox appender, I will have the same output but without the overhead (i.e. DEBUG info at no price.. so to speak).
thanks
Graham
________________________________
From: WALSH, Graham (CALYON)
Sent: jeudi 26 février 2009 09:09
To: Log4NET User
Subject: RE: DEBUG vs INFO
sorry, but I'm having trouble with one part of this config, I always do. I have taken the BufferingForwardingAppender and put it in place, its works a treat.
I've also got another appender which is used to display log output in the GUI window. Now I want BufferingForwardingAppender (which logs to file) to log at debug level but my other appender (RichTextFormAppender) to log at just INFO level. I can't get this working though.
My (messy) log4net stuff looks like this, could anybody let me know how I can get the two levels of logging in place? Once thats done, I'm water tight in terms of delivery
thanks much
Graham
<log4net>
<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender" >
<bufferSize value="255" />
<lossy value="false" />
<evaluator type="log4net.Core.LevelEvaluator">
<threshold value="DEBUG"/>
</evaluator>
<appender-ref ref="RollingFile" />
</appender>
<appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
<file value="logs/NewLogFile.log" />
<appendToFile value="true" />
<maximumFileSize value="100MB" />
<maxSizeRollBackups value="-1" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%5level [%date] [%thread] %-30.30logger{2} %message%newline" />
</layout>
</appender>
<appender name="MainFormRichTextAppender" type="log4net.Appender.RichTextBoxAppender">
<appendToFile value="true" />
<maximumFileSize value="250000KB" />
<maxSizeRollBackups value="2" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date [%-2thread] %-5level %-70logger - %message%newline" />
</layout>
<code lang="XML" escaped="true">
<mapping>
<level value="DEBUG" />
<textColorName value="DarkGreen" />
<fontFamilyName value="Microsoft Sans Serif"/>
<pointSize value="6.75" />
</mapping>
<mapping>
<level value="INFO" />
<textColorName value="Black" />
<fontFamilyName value="Microsoft Sans Serif"/>
<pointSize value="6.75" />
</mapping>
<mapping>
<level value="WARN" />
<textColorName value="Blue" />
<fontFamilyName value="Microsoft Sans Serif"/>
<pointSize value="6.75" />
</mapping>
<mapping>
<level value="ERROR" />
<textColorName value="Red" />
<!--<bold value="true" />-->
<fontFamilyName value="Microsoft Sans Serif"/>
<pointSize value="6.75" />
</mapping>
<mapping>
<level value="FATAL" />
<textColorName value="Black" />
<fontFamilyName value="Microsoft Sans Serif"/>
<pointSize value="6.75" />
</mapping>
</code>
</appender>
<root>
<level value="DEBUG" />
<appender-ref ref="BufferingForwardingAppender" />
<appender-ref ref="MainFormRichTextAppender"/>
</root>
________________________________
From: Michael Schall [mailto:mike.schall@gmail.com]
Sent: mercredi 25 février 2009 20:36
To: Log4NET User
Subject: Re: DEBUG vs INFO
What appenders are you using? I assume one of them is the rolling file appender? How large is the log file produced with the setting at DEBUG vs INFO?
If you need to keep the debug information you can look at the BufferingForwardingAppender. The following will buffer 255 messages before writing to the file, unless there is a WARN or higher message, then the buffer is flushed immediately. This should hopefully let the error message that crashes the system still make it to the log file.:)
I don't know how your loggers are setup, but you can turn off at that level as well.
<log4net>
<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender" >
<bufferSize value="255" />
<lossy value="false" />
<evaluator type="log4net.Core.LevelEvaluator">
<threshold value="WARN"/>
</evaluator>
<appender-ref ref="RollingFile" />
</appender>
<appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
<file value="..\..\log\web.log" />
<appendToFile value="true" />
<maximumFileSize value="100MB" />
<maxSizeRollBackups value="-1" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%5level [%date] [%thread] %-30.30logger{2} %message%newline" />
</layout>
</appender>
<root>
<level value="DEBUG" />
<appender-ref ref="BufferingForwardingAppender" />
</root>
</log4net>
On Wed, Feb 25, 2009 at 8:31 AM, Walden H. Leverich <Wa...@techsoftinc.com> wrote:
Graham,
That's not a log4net issue as much as it's an issue in your application.
Sounds like your application (like many) makes lots of log.Debug()
calls, to log, um, debug information. By switching the logging from
DEBUG to INFO you've stopped all those log entries from being written to
disk. Even more, if your app developers were smart about it, they
checked the IsDebugEnabled property before making the log.Debug() call,
so you're not even evaluating the parms to that call, and sometimes that
can be quite expensive.
So, it's a "known issue" that logging more stuff takes more time, but I
wouldn't call it a bug.
-Walden
--
Walden H Leverich III
Tech Software
(516) 627-3800 x3051
WaldenL@TechSoftInc.com
http://www.TechSoftInc.com
Quiquid latine dictum sit altum viditur.
(Whatever is said in Latin seems profound.)
RE: DEBUG vs INFO
Posted by Graham Walsh <gr...@calyon.com>.
sorry, but I'm having trouble with one part of this config, I always do. I have taken the BufferingForwardingAppender and put it in place, its works a treat.
I've also got another appender which is used to display log output in the GUI window. Now I want BufferingForwardingAppender (which logs to file) to log at debug level but my other appender (RichTextFormAppender) to log at just INFO level. I can't get this working though.
My (messy) log4net stuff looks like this, could anybody let me know how I can get the two levels of logging in place? Once thats done, I'm water tight in terms of delivery
thanks much
Graham
<log4net>
<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender" >
<bufferSize value="255" />
<lossy value="false" />
<evaluator type="log4net.Core.LevelEvaluator">
<threshold value="DEBUG"/>
</evaluator>
<appender-ref ref="RollingFile" />
</appender>
<appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
<file value="logs/NewLogFile.log" />
<appendToFile value="true" />
<maximumFileSize value="100MB" />
<maxSizeRollBackups value="-1" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%5level [%date] [%thread] %-30.30logger{2} %message%newline" />
</layout>
</appender>
<appender name="MainFormRichTextAppender" type="log4net.Appender.RichTextBoxAppender">
<appendToFile value="true" />
<maximumFileSize value="250000KB" />
<maxSizeRollBackups value="2" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date [%-2thread] %-5level %-70logger - %message%newline" />
</layout>
<code lang="XML" escaped="true">
<mapping>
<level value="DEBUG" />
<textColorName value="DarkGreen" />
<fontFamilyName value="Microsoft Sans Serif"/>
<pointSize value="6.75" />
</mapping>
<mapping>
<level value="INFO" />
<textColorName value="Black" />
<fontFamilyName value="Microsoft Sans Serif"/>
<pointSize value="6.75" />
</mapping>
<mapping>
<level value="WARN" />
<textColorName value="Blue" />
<fontFamilyName value="Microsoft Sans Serif"/>
<pointSize value="6.75" />
</mapping>
<mapping>
<level value="ERROR" />
<textColorName value="Red" />
<!--<bold value="true" />-->
<fontFamilyName value="Microsoft Sans Serif"/>
<pointSize value="6.75" />
</mapping>
<mapping>
<level value="FATAL" />
<textColorName value="Black" />
<fontFamilyName value="Microsoft Sans Serif"/>
<pointSize value="6.75" />
</mapping>
</code>
</appender>
<root>
<level value="DEBUG" />
<appender-ref ref="BufferingForwardingAppender" />
<appender-ref ref="MainFormRichTextAppender"/>
</root>
________________________________
From: Michael Schall [mailto:mike.schall@gmail.com]
Sent: mercredi 25 février 2009 20:36
To: Log4NET User
Subject: Re: DEBUG vs INFO
What appenders are you using? I assume one of them is the rolling file appender? How large is the log file produced with the setting at DEBUG vs INFO?
If you need to keep the debug information you can look at the BufferingForwardingAppender. The following will buffer 255 messages before writing to the file, unless there is a WARN or higher message, then the buffer is flushed immediately. This should hopefully let the error message that crashes the system still make it to the log file.:)
I don't know how your loggers are setup, but you can turn off at that level as well.
<log4net>
<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender" >
<bufferSize value="255" />
<lossy value="false" />
<evaluator type="log4net.Core.LevelEvaluator">
<threshold value="WARN"/>
</evaluator>
<appender-ref ref="RollingFile" />
</appender>
<appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
<file value="..\..\log\web.log" />
<appendToFile value="true" />
<maximumFileSize value="100MB" />
<maxSizeRollBackups value="-1" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%5level [%date] [%thread] %-30.30logger{2} %message%newline" />
</layout>
</appender>
<root>
<level value="DEBUG" />
<appender-ref ref="BufferingForwardingAppender" />
</root>
</log4net>
On Wed, Feb 25, 2009 at 8:31 AM, Walden H. Leverich <Wa...@techsoftinc.com> wrote:
Graham,
That's not a log4net issue as much as it's an issue in your application.
Sounds like your application (like many) makes lots of log.Debug()
calls, to log, um, debug information. By switching the logging from
DEBUG to INFO you've stopped all those log entries from being written to
disk. Even more, if your app developers were smart about it, they
checked the IsDebugEnabled property before making the log.Debug() call,
so you're not even evaluating the parms to that call, and sometimes that
can be quite expensive.
So, it's a "known issue" that logging more stuff takes more time, but I
wouldn't call it a bug.
-Walden
--
Walden H Leverich III
Tech Software
(516) 627-3800 x3051
WaldenL@TechSoftInc.com
http://www.TechSoftInc.com
Quiquid latine dictum sit altum viditur.
(Whatever is said in Latin seems profound.)
RE: DEBUG vs INFO
Posted by Graham Walsh <gr...@calyon.com>.
Thanks Walden for the reply, that makes total sense. The error is on our part (we're in production with debug on as its a greenfield project).
This second reply to my question brings me to my point. What was actually happening (and this is speculation), is that my code changes related to performance we're having no impact on the results/times of our processing. I had introduced multi-threading in three or four areas of the code to reduce bottlenecks. They weren't having any impact. What I THINK was happening is that the DEBUG log messages were causing disk writes which were taking time and thus causing thrashing/lots of context switching. The new threads were working alright but kept being interrupted, hence the lack of any performance improvement with my changes.
With INFO on (and some changes to log level in key parts of the code) , the users will not be aware of the changes in log level. In addition I intend to fall back onto Michaels suggestion below. i.e. if they absolutely MUST have logging at DEBUG level, I'll try have it bufferred as indicated below.
thanks much for the replies.
G
________________________________
From: Michael Schall [mailto:mike.schall@gmail.com]
Sent: mercredi 25 février 2009 20:36
To: Log4NET User
Subject: Re: DEBUG vs INFO
What appenders are you using? I assume one of them is the rolling file appender? How large is the log file produced with the setting at DEBUG vs INFO?
If you need to keep the debug information you can look at the BufferingForwardingAppender. The following will buffer 255 messages before writing to the file, unless there is a WARN or higher message, then the buffer is flushed immediately. This should hopefully let the error message that crashes the system still make it to the log file.:)
I don't know how your loggers are setup, but you can turn off at that level as well.
<log4net>
<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender" >
<bufferSize value="255" />
<lossy value="false" />
<evaluator type="log4net.Core.LevelEvaluator">
<threshold value="WARN"/>
</evaluator>
<appender-ref ref="RollingFile" />
</appender>
<appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
<file value="..\..\log\web.log" />
<appendToFile value="true" />
<maximumFileSize value="100MB" />
<maxSizeRollBackups value="-1" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%5level [%date] [%thread] %-30.30logger{2} %message%newline" />
</layout>
</appender>
<root>
<level value="DEBUG" />
<appender-ref ref="BufferingForwardingAppender" />
</root>
</log4net>
On Wed, Feb 25, 2009 at 8:31 AM, Walden H. Leverich <Wa...@techsoftinc.com> wrote:
Graham,
That's not a log4net issue as much as it's an issue in your application.
Sounds like your application (like many) makes lots of log.Debug()
calls, to log, um, debug information. By switching the logging from
DEBUG to INFO you've stopped all those log entries from being written to
disk. Even more, if your app developers were smart about it, they
checked the IsDebugEnabled property before making the log.Debug() call,
so you're not even evaluating the parms to that call, and sometimes that
can be quite expensive.
So, it's a "known issue" that logging more stuff takes more time, but I
wouldn't call it a bug.
-Walden
--
Walden H Leverich III
Tech Software
(516) 627-3800 x3051
WaldenL@TechSoftInc.com
http://www.TechSoftInc.com
Quiquid latine dictum sit altum viditur.
(Whatever is said in Latin seems profound.)
Re: DEBUG vs INFO
Posted by Michael Schall <mi...@gmail.com>.
What appenders are you using? I assume one of them is the rolling file
appender? How large is the log file produced with the setting at DEBUG vs
INFO?
If you need to keep the debug information you can look at
the BufferingForwardingAppender. The following will buffer 255 messages
before writing to the file, unless there is a WARN or higher message, then
the buffer is flushed immediately. This should hopefully let the error
message that crashes the system still make it to the log file.:)
I don't know how your loggers are setup, but you can turn off at that level
as well.
<log4net>
<appender name="BufferingForwardingAppender"
type="log4net.Appender.BufferingForwardingAppender" >
<bufferSize value="255" />
<lossy value="false" />
<evaluator type="log4net.Core.LevelEvaluator">
<threshold value="WARN"/>
</evaluator>
<appender-ref ref="RollingFile" />
</appender>
<appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
<file value="..\..\log\web.log" />
<appendToFile value="true" />
<maximumFileSize value="100MB" />
<maxSizeRollBackups value="-1" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%5level [%date] [%thread] %-30.30logger{2}
%message%newline"
/>
</layout>
</appender>
<root>
<level value="DEBUG" />
<appender-ref ref="BufferingForwardingAppender" />
</root>
</log4net>
On Wed, Feb 25, 2009 at 8:31 AM, Walden H. Leverich <WaldenL@techsoftinc.com
> wrote:
> Graham,
>
> That's not a log4net issue as much as it's an issue in your application.
> Sounds like your application (like many) makes lots of log.Debug()
> calls, to log, um, debug information. By switching the logging from
> DEBUG to INFO you've stopped all those log entries from being written to
> disk. Even more, if your app developers were smart about it, they
> checked the IsDebugEnabled property before making the log.Debug() call,
> so you're not even evaluating the parms to that call, and sometimes that
> can be quite expensive.
>
> So, it's a "known issue" that logging more stuff takes more time, but I
> wouldn't call it a bug.
>
> -Walden
>
> --
> Walden H Leverich III
> Tech Software
> (516) 627-3800 x3051
> WaldenL@TechSoftInc.com
> http://www.TechSoftInc.com
>
> Quiquid latine dictum sit altum viditur.
> (Whatever is said in Latin seems profound.)
>
RE: DEBUG vs INFO
Posted by "Walden H. Leverich" <Wa...@TechSoftInc.com>.
Graham,
That's not a log4net issue as much as it's an issue in your application.
Sounds like your application (like many) makes lots of log.Debug()
calls, to log, um, debug information. By switching the logging from
DEBUG to INFO you've stopped all those log entries from being written to
disk. Even more, if your app developers were smart about it, they
checked the IsDebugEnabled property before making the log.Debug() call,
so you're not even evaluating the parms to that call, and sometimes that
can be quite expensive.
So, it's a "known issue" that logging more stuff takes more time, but I
wouldn't call it a bug.
-Walden
--
Walden H Leverich III
Tech Software
(516) 627-3800 x3051
WaldenL@TechSoftInc.com
http://www.TechSoftInc.com
Quiquid latine dictum sit altum viditur.
(Whatever is said in Latin seems profound.)