Beefy Boxes and Bandwidth Generously Provided by pair Networks
XP is just a number
 
PerlMonks  

log4perl and efficiency

by erwan (Acolyte)
on Sep 12, 2011 at 16:46 UTC ( #925513=perlquestion: print w/ replies, xml ) Need Help??
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]"); + }

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]"); }
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
Re: log4perl and efficiency
by BrowserUk (Pope) 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.

      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

        If you like features, perhaps I can interest you in a camper van?

      If you're going to criticize it, you might as well mention some better alternatives.

        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.
Re: log4perl and efficiency
by Solo (Deacon) on Sep 12, 2011 at 17:17 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?

        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]" } );
        which may be easier to bulk modify in source while maintaining existing log levels. (or not. YMMV.)
Re: log4perl and efficiency
by erwan (Acolyte) 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!

      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]");

      with example B:

      $self->{logger}->trace('no interpolation');

      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.

        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]") }

        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]") }

        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.

Log In?
Username:
Password:

What's my password?
Create A New User
Node Status?
node history
Node Type: perlquestion [id://925513]
Front-paged by tye
help
Chatterbox?
and the web crawler heard nothing...

How do I use this? | Other CB clients
Other Users?
Others having an uproarious good time at the Monastery: (14)
As of 2014-08-01 12:59 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    Who would be the most fun to work for?















    Results (18 votes), past polls