How can I determine PerlLogHandler performance impact?

Question

I want to create a custom Apache2 log handler, and the template that is found on the apache site is:

#file:MyApache2/LogPerUser.pm
#---------------------------
package MyApache2::LogPerUser;

use strict;
use warnings;

use Apache2::RequestRec ();
use Apache2::Connection ();

use Fcntl qw(:flock);
use File::Spec::Functions qw(catfile);

use Apache2::Const -compile => qw(OK DECLINED);

sub handler {
  my $r = shift;

  my ($username) = $r->uri =~ m|^/~([^/]+)|;
  return Apache2::Const::DECLINED unless defined $username;

  my $entry = sprintf qq(%s [%s] "%s" %d %d\n),
      $r->connection->remote_ip, scalar(localtime),
      $r->uri, $r->status, $r->bytes_sent;

  my $log_path = catfile Apache2::ServerUtil::server_root,
      "logs", "$username.log";
  open my $fh, ">>$log_path" or die "can't open $log_path: $!";
  flock $fh, LOCK_EX;
  print $fh $entry;
  close $fh;

  return Apache2::Const::OK;
}
1;

What is the performance cost of the flocks? Is this logging process done in parallel, or in serial with the HTTP request? In parallel the performance would not matter as much, but I wouldn't want the user to wait another split second to add something like this.

Answer 1

Instead of worrying too much about what the costs might be, just try it and find out.

First, benchmark your current configuration using ab or your favorite webserver torture tester. Many people forget this first step.

Next, implement your change and try again. Compare the results.

Some links that might help. They may be a little dated, but the basics are the same:

• Howto: Performance Benchmarks a Webserver
• Stress-Test Apache With ab

Also remember, though, that you can do stuff after you've served the response. You don't have to do everything while the client is waiting for a response. And, I wouldn't sweat the flocks too much. If you don't like them there are various other ways around it, including:

• Writing to a different file per child and merging later
• Sending a message to a single process that sequences the messages
• Writing to a database (a more specific example of the single process idea)
• Setting up a custom log format and letting apache handle it

Answer 2

I've found the flocks to be a necessary evil, especially on Solaris, and I've had no performance issues even on a heavily loaded server. They're necessary when you're handling many concurrent requests; without them you'll get log entries written in the middle of other log entries. brian's workarounds will work but the second and third will introduce bottlenecks of their own which will probably be worse than the flocks.

By the way, the log handler runs after the request has been sent, so there's no performance impact on users if the log handler stalls momentarily. There also won't be a visible impact on ab's output until your server is overloaded, which will make it tough to distinguish the impact of the flocks. You'd have to watch some disk IO metrics while the ab test is running to see if there's a problem.