Beefy Boxes and Bandwidth Generously Provided by pair Networks
Your skill will accomplish
what the force of many cannot
 
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 taking refuge in the Monastery: (8)
As of 2014-09-01 19:22 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    My favorite cookbook is:










    Results (16 votes), past polls