In the weeds with logging micro optimization

Great code provides detailed logging output during development. Generating this output isn't free, that's why it's usually turned off. But even when inactive, the debug logging code will have a non zero performance impact. Let's explore a few ways this can be approached and optimized.

While the total impact of any one discarded log message is small, the runtime cost can certainly become at least trivially significant with a bit of scale.

A simple debug log message

I was inspired to write while spelunking around internals of the Perl Mojolicious framework. Examples are placed in this context.

Here is a very simple Mojo web server route to return some JSON

$app->routes->get('/helo')->to(
  cb => sub ($c) {
  	$c->log->info('Some frood visited from ' . $c->tx->remote_address);
    
    return $c->render(
      json => {
      	helo         => 'friend',
        stay_a_while => 'and listen!',
      }
    );
  }
);

Line 3 throws a log message with the visitor's IP address. With the log level of info, this message will likely live on in the application's log archives.

Lines 5-10 renders a JSON response document Deckard might approve of.

A more expensive debug log message

Expanding on this a bit, let's generate a more detailed log message that only appears during development. If we were doing serious work here, we may want to generate several detailed or expensive debug messages along the way.

This message requires non trivial resources to generate. We allocate a hash, populate with data fetched from the request cycle, and even serialize some JSON with an encoder. Finally, we use Data::Dumper to turn this into a nicely formatted human readable screen dump of data.

The call to $c->log->debug() is smart enough to throw this log message away, unless the debug log level is enabled for the application. This monster message does not get added to the production server's application logs. Even so, the production server will burn time and ram assembling this log message before throwing it away.

$app->routes->get('/helo')->to(
  cb => sub ($c) {
  	$c->log->info('Some frood visited from ' . $c->tx->remote_address);
    
    # Generate a data structure and log to STDOUT with Data::Dumper
    my %debug_data = (
      request_id      => $c->req->request_id,
      request_address => $c->tx->remote_address,
      request_method  => $c->req->method,
      request_url     => $c->req->url->to_abs->to_string,
      request_params  => encode_json($c->req->params->to_hash),
    );
    $c->log->debug(Dumper \%debug_data);
    
    return $c->render(
      json => {
      	helo         => 'friend',
        stay_a_while => 'and listen!',
      }
    );
  }
);

Let's optimize the debug logging

There's more than one way to do it, or TMTOWTDI. The Perl ecosystem embraces this truth, and we're all better for it. Here are two approaches of many we might choose from.

If statement to the rescue!

The most obvious solution, but not the most elegant. Wrap the log debug code within an if statement. Ask Mojo:::Log if it's currently configured to ignore debug messages. If so, skip all the extra work.

if ($c->log->is_level('debug')) {
  # ... expensive debug operation
}

It's not, strictly speaking, free. We are dereferencing, calling a method and branching. But it's as free as we're going to get. There's a bit of developer overhead. Every time we write a debug log message, we need to decide if it's worth wrapping the log message in a conditional. Easy to skip or forget. Especially on simpler messages like these:

$c->log->debug("A $frood who really knows where his $towel is");

$c->log->debug(sprintf('I want my $%.02d!!!', $bully->lunch_money_amount);

$c->log->debug($foo->generate_expensive_log_message);

Each example here is a one-liner. We could skip the if statement. But each is doing more work than the last, generating a log message that is probably going to be discarded anyway.

Deciding to use, or not use, a conditional for every log message is an irritating bit of friction. For much of my career, I avoided that friction by simply always using the conditional. I assume the runtime saved outweighs the runtime wasted this way. But always, I felt every log message was uglier and more verbose than it had to be.

Wrap the expensive code in a callback

Log::Mojo accepts an anonymous subroutine in place of of a log message. If the log level is met, Log::Mojo executes the subroutine and expects lvalue array of log messages.

$c->log->debug(sub {return $foo->generate_expensive_log_message});

Using this approach, we're saved from writing redundant conditionals around every debug log message, and instead we get to write eyebrow raising callback functions.

Our earlier example benefits from this approach:

$app->routes->get('/helo')->to(
  cb => sub ($c) {
  	$c->log->info('Some frood visited from ' . $c->tx->remote_address);
    
    $c->log->debug(sub {
      # Generate a data structure and log to STDOUT with Data::Dumper
      my %debug_data = (
        request_id      => $c->req->request_id,
        request_address => $c->tx->remote_address,
        request_method  => $c->req->method,
        request_url     => $c->req->url->to_abs->to_string,
        request_params  => encode_json($c->req->params->to_hash),
      );
      return Dumper \%debug_data;
    });
    
    return $c->render(
      json => {
      	helo         => 'friend',
        stay_a_while => 'and listen!',
      }
    );
  }
);

I know I scowled the first time I saw a log event written like this one. But after about 90 seconds of rusty gears grinding, I was sold on this micro optimization. TMTOWTDI, and this one is at least slightly more fun.

Which style looks better?

# Using conditionals

$c->log->debug("A $frood who really knows where his $towel is")
  if $c->log->is_level('debug');

if ($c->log->is_level('debug')) {
  $c->log->debug(sprintf(
    'I want my $%.02d!!!',
    $bully->lunch_money_amount
  ));
}

if ($c->log->is_level('debug')) {
  $c->log->debug($foo->generate_expensive_log_message);
}

# Using callbacks

$c->log->debug(sub {"A $frood who really knows where his $towel is"});

$c->log->debug(sub {
  sprintf('I want my $%.02d!!!', $bully->lunch_money_amount);
});

$c->log->debug(sub { $c->log->debug($foo->generate_expensive_log_message )});

Okay mjac but who cares

Tiny optimizations are still optimizations. It's down in the weeds where performant software is born. Habitually making performant decisions automatically is key to productivity and performance.

I hope you enjoy the minor details as much as I do!

Thanks for reading.