in reply to log4perl and efficiency

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!

Replies are listed 'Best First'.
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]");

    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.

        Better yet, use a constant instead of a hashref lookup, and the whole if block will be obliterated at compile time when you disable debugging.

        use constant DEBUG => 0; ... if (DEBUG) { # complex logging, which disappears from the op tree }

        FWIW, my experience has been like Solo's, where you end up inadvertently evaluating the arguments to the logging methods, and this takes a lot of time (or a little bit of time in a tight loop that's called a zillion times).