log4perl and efficiency

erwan has asked for the wisdom of the Perl Monks concerning the following question:

Hi all,

Facing some efficiency issues with a quite complex program, I used NYTProf to profile it. I noticed that the logging operations (using Log4perl) require a significant amount of time (about 25%), so I tried to disable logging by setting the log level to OFF. Nothing is logged (of course), but according to NYTProf the time taken by Log4perl is still the same. I thought that as soon as level was OFF calls to log4perl would have exited immediately, but it seems there are a lot of internal computations whatever the level (?).

I have already optimized the most frequent calls in the following way:

        if ($self->{logger}->is_trace()) { 
            $self->{logger}->trace("total NbObsThis $i=$nbObservedThis
+NGram->[$i]; nbObsAll $i=$nbObservedAllNGrams->[$i]; total=$totalObse
+rvedAll; nbExpected $i=$nbExpectedThis[$i]; chisq = $chiSquare[$i]");
+ 
        }
[download]

and I was very surprised when I saw that even this simple call to is_trace() (when the log level is OFF) is very costly (takes 30% of the time spent in a sub called very often).

Of course I can create my own condition like

        
if ($loggingOn) {
$self->{logger}->trace("total NbObsThis $i=$nbObservedThisNGram->[$i];
+ nbObsAll $i=$nbObservedAllNGrams->[$i]; total=$totalObservedAll; nbE
+xpected $i=$nbExpectedThis[$i]; chisq = $chiSquare[$i]"); 
        }
[download]

but it doesn't seem very elegant to add my own "optimized level" to the usual ones. Do you have any other ideas? Maybe something I missed about Log4perl?

Thank you!

Comment on log4perl and efficiency Select or Download Code

Replies are listed 'Best First'.
Re: log4perl and efficiency by Solo (Deacon) on Sep 12, 2011 at 17:17 UTC
The Log::Log4perl POD has a section with ways to improve log4perl performance. It looks to me like you should wrap that log string into a function so it doesn't need to interpolate when logging is off.	[reply]
Re^2: log4perl and efficiency by erwan (Sexton) on Sep 12, 2011 at 17:30 UTC
Unless I misunderstood, that's what I did. well, not using a function but the "if (condition) { log }" does the same thing, doesn't it?	[reply]
Re^3: log4perl and efficiency by Solo (Deacon) on Sep 12, 2011 at 17:44 UTC
That's one approach. I was suggesting: `$self->{logger}->trace( sub { "total NbObsThis $i=$nbObservedThisNGram +->[$i]; nbObsAll $i=$nbObservedAllNGrams->[$i]; total=$totalObservedA +ll; nbExpected $i=$nbExpectedThis[$i]; chisq = $chiSquare[$i]" } );` [download] which may be easier to bulk modify in source while maintaining existing log levels. (or not. YMMV.)	[reply] [d/l]
Re^4: log4perl and efficiency by erwan (Sexton) on Sep 12, 2011 at 17:54 UTC
Re: log4perl and efficiency by BrowserUk (Patriarch) on Sep 12, 2011 at 16:56 UTC
Maybe something I missed about Log4perl? Yes. It is over-engineered, over-complicated garbage that turn what is (should be) nothing more than a condition print into a steaming heap of CPU-sucking OO tortoulinni Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error. "Science is about questioning the status quo. Questioning authority". In the absence of evidence, opinion is indistinguishable from prejudice.	[reply]
Re^2: log4perl and efficiency by Anonymous Monk on Sep 12, 2011 at 18:43 UTC
If you're going to criticize it, you might as well mention some better alternatives.	[reply]
Re^3: log4perl and efficiency by BrowserUk (Patriarch) on Sep 12, 2011 at 18:53 UTC
See Log::Tiny. Or Log::StdLog. Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error. "Science is about questioning the status quo. Questioning authority". In the absence of evidence, opinion is indistinguishable from prejudice.	[reply]
Re^2: log4perl and efficiency by Anonymous Monk on Sep 12, 2011 at 17:23 UTC
Yes. It is over-engineered, over-complicated garbage that turn what is (should be) nothing more than a condition print into a steaming heap off CPU-sucking OO tortoulinni Also known as features	[reply]
Re^3: log4perl and efficiency by BrowserUk (Patriarch) on Sep 12, 2011 at 17:58 UTC
If you like features, perhaps I can interest you in a camper van?	[reply]
Re: log4perl and efficiency by erwan (Sexton) on Sep 12, 2011 at 18:19 UTC
ok so basically nothing can be done except not calling Log4perl at all in the frequently executed code. tested using a variable $self->{disable_logger} initialized once if the level is OFF and tested before calling log4perl (instead of $logger->is_debug()): my program takes about 25% less time, as expected... Log4perl is a bit disappointing, indeed. Thank you for your answers!	[reply]
Re^2: log4perl and efficiency by Solo (Deacon) on Sep 12, 2011 at 18:29 UTC
I really think this has more to do with variable interpolation than it does with log4perl. Comparing example A: `$self->{logger}->trace("total NbObsThis $i=$nbObservedThisNGram->[$i]; + nbObsAll $i=$nbObservedAllNGrams->[$i]; total=$totalObservedAll; nbE +xpected $i=$nbExpectedThis[$i]; chisq = $chiSquare[$i]");` [download] with example B: `$self->{logger}->trace('no interpolation');` [download] would be useful to demonstrate the difference in overhead between perl internals and log4perl. You're going to be stuck with interpolation performance no matter what logging framework you use.	[reply] [d/l] [select]
Re^3: log4perl and efficiency by erwan (Sexton) on Sep 12, 2011 at 19:03 UTC
I don't think so, I mean in the first place I got rid of this interpolation problem by testing the log level using a call to Log4perl: `if ($self->{logger}->is_trace()) { # for efficiency (not to compute th +e expression) $self->{logger}->trace("total NbObsThis $i=$nbObservedThis +NGram->[$i]; nbObsAll $i=$nbObservedAllNGrams->[$i]; total=$totalObse +rvedAll; nbExpected $i=$nbExpectedThis[$i]; chisq = $chiSquare[$i]") }` [download] It helped indeed, but the cost of "is_trace()" was still prohibitive. Then I added a new variable $self->{disableLogger} set to true if the level is OFF (testing the log level only once) and replaced the condition with `if (!$self->{disableLogger} && $self->{logger}->is_trace()) { # test f +or efficiency (not to compute the expression) { $self->{logger}->trace("total NbObsThis $i=$nbObservedThis +NGram->[$i]; nbObsAll $i=$nbObservedAllNGrams->[$i]; total=$totalObse +rvedAll; nbExpected $i=$nbExpectedThis[$i]; chisq = $chiSquare[$i]") }` [download] and this takes way less time (according to NYTProf). As previously said, it seems that a simple call to is_debug() (no interpolation) implies a complex (and long) computation in Log4perl.	[reply] [d/l] [select]
Re^4: log4perl and efficiency by ForgotPasswordAgain (Priest) on Sep 12, 2011 at 22:20 UTC