Beefy Boxes and Bandwidth Generously Provided by pair Networks
Think about Loose Coupling
 
PerlMonks  

Perl::Critic policy for common Log::Log4perl mistake

by andreas1234567 (Vicar)
on Nov 07, 2011 at 16:59 UTC ( #936543=perlquestion: print w/ replies, xml ) Need Help??
andreas1234567 has asked for the wisdom of the Perl Monks concerning the following question:

I'm looking for a Perl::Critic policy related to Log::Log4perl. The policy should require every logging statement to be surrounded by a conditional testing for the given log level, as shown here. Running Devel::NYTProf has shown that this code, as noted by the Log::Log4perl module's author, can have a significant negative impact on performance.
# Correct: if($logger->is_error()) { $logger->error("Erroneous array: @super_long_array"); } # Wrong - should emit a Perl::Critic warning $logger->error("Erroneous array: @super_long_array");
Does such a policy exist? If not, are there policies that are similar that I can base this new one on?

--
No matter how great and destructive your problems may seem now, remember, you've probably only seen the tip of them. [1]

Comment on Perl::Critic policy for common Log::Log4perl mistake
Download Code
Re: Perl::Critic policy for common Log::Log4perl mistake
by jethro (Monsignor) on Nov 07, 2011 at 17:49 UTC

    How would Perl::Critic find out that @super_long_array is in fact a super long array? Note that the negative impact is only when the error message is really long and takes ages to expand. In the normal case warnings or error messages would be relatively short and the impact nonexistant.

      Perl::Critic is a static code analyzer and can of course, by definition, not know the runtime length of arrays.

      The intention is to create Perl::Critic policy to help track down all logging calls, and then based on the output, help identify which ones are likely to have a negative impact on performance.

      --
      No matter how great and destructive your problems may seem now, remember, you've probably only seen the tip of them. [1]

        I first wanted to reply that this would be nonsense because nobody puts big arrays into error logs (and I still stand by that). A perl_critic rule that produces 99% false positives is not a good perl_critic rule. But then it occured to me that debug-logs might have such calls more frequently.

        So you got a point, but only in so far as logging level 'debug' is concerned. You might flag all calls to debug that don't have such a if-clause and you actually would have a somewhat sensible rule IMO.

Re: Perl::Critic policy for common Log::Log4perl mistake
by hesco (Deacon) on Nov 07, 2011 at 19:01 UTC
    The OP here is not asking that Perl::Critic evaluate @super_long_array, but rather whether the call to $logger is appropriately wrapped by the conditional.

    if( $lal && $lol ) { $life++; }
    if( $insurance->rationing() ) { $people->die(); }
Re: Perl::Critic policy for common Log::Log4perl mistake
by thargas (Chaplain) on Nov 07, 2011 at 19:48 UTC
    Please read that link to Log4perl again. The Log4perl author is *not* suggesting that every logging call should be wrapped, but rather that *expensive* calls should be. Since only the application developer can be expected to be able to tell which calls would be expensive, IMHO using such a Perl::Critic policy (if it exists) would be both code bloat and slow down the application, exactly the opposite to the effect the OP seems to be trying to achieve.
      The following Benchmarked code snipped shows a 10-15% performance increase by simply wrapping the log calls. Note that it is just a scalar being logged (suppressed, actually), not even an array, an especially not a super-long array. I don't find it to be particularly bloated either:
      $ perl l4p_bench.pl x86_64-linux Rate fib_log_buffer fib_log_buffer_is +_chk fib_log_buffer 15605/s -- +-11% fib_log_buffer_is_chk 17454/s 12% + --
      --
      No matter how great and destructive your problems may seem now, remember, you've probably only seen the tip of them. [1]

        Then add this to your test:

        sub fib_no_log { my @fibonacci = (0, 1); my ($n, $sum) = (1, 0); while ($n < 1_000_000) { $n = $fibonacci[$#fibonacci] + $fibonacci[ $#fibonacci - 1 ]; push @fibonacci, $n; $sum += $n if (($n % 2) == 0); } return $sum; } ... 'fib_no_log' => sub { fib_no_log() },

        and you will get this result:

        Rate fib_log_buffer fib_log_buffer_is_chk f +ib_no_log fib_log_buffer 11712/s -- -13% + -68% fib_log_buffer_is_chk 13525/s 15% -- + -63% fib_no_log 36540/s 212% 170% + --

        Why? Because even the call to is_debug takes twice as long as the rest, the "meat" of your loop. Obviously you should have a perl_critic rule to warn from use of log4perl at all. Or avoid artificial benchmarks ;-)

Re: Perl::Critic policy for common Log::Log4perl mistake
by choroba (Abbot) on Nov 08, 2011 at 13:43 UTC
    Cannot you just create a new package inheriting from Log::Log4perl that wraps each call to error into is_error check?
      No because the string will be interpolated on the way in, so you won't avoid the hit. The only way to avoid the hit is to ensure the string never gets interpolated in the first place (it's not the log call that's slow, it's the string interpolation of a huge array).
Re: Perl::Critic policy for common Log::Log4perl mistake
by mje (Deacon) on Nov 10, 2011 at 16:07 UTC

    I wouldn't bother doing the check first, I just change the code to:

    $logger->error(sub {"Erroneous array: @super_long_array"});

    then I believe it does not get expanded until inside Log::Log4perl when it decides to log or not.

    So now all you need is a Perl Critic rule for using sub {} in logging ;-)

Log In?
Username:
Password:

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

How do I use this? | Other CB clients
Other Users?
Others drinking their drinks and smoking their pipes about the Monastery: (16)
As of 2014-07-22 15:35 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    My favorite superfluous repetitious redundant duplicative phrase is:









    Results (117 votes), past polls