[Catalyst] Very long request time weirdness

[luke saunders]

In order to get some info on how long requests were taking and where
the bottlenecks were we put some code into MyApp::finalize which wrote
info gained from $c->stats to the DB so we could easily check them
later (code given below). Occasionally we get a request where total
time ($c->stats->elapsed) is very long (more than 50 seconds) but each
individual action executes very quickly (they usually sum to less than
1 second). So presumably something is happening between the end action
and finalize which is taking ages, but what on earth could that be?

This is Catalyst::Runtime 5.7014 running on a Fastcgi system. This
only affects about 3 out of 35000 requests, but I'd still like to know
why it's happening. Any ideas?

sub finalize {
  my $c = shift;

  $c->NEXT::finalize( $c, @_ );
  return if $c->_static_file; # don't bother logging the serving of
static files
  return unless $c->config->{request_logging};

  my $request_log = {
    browser => $c->req->browser->browser_string(),
    browser_version => $c->req->browser->version(),
    path => join('', '/', $c->req->path),
    params => join('&', map { $_ . "=" . $c->req->params->{$_} } keys
%{$c->req->params}),
    total_time => $c->stats->elapsed,
    total_sql_time => sprintf('%0.6f',
$c->model('123peopleDB')->querylog->time_elapsed),
    query_count => $c->model('123peopleDB')->querylog->count
  };
  my $log_req_obj = $c->model('123peopleDB::LogRequest')->create($request_log);

  my @request_stages = $c->stats->report;
  foreach my $stage (@request_stages) {
    my $request_stage_log = {
      depth => $stage->[0],
      stage_name => ($stage->[3] ? '(Action) ' : '(Other) ') . $stage->[1],
      total_time => $stage->[2],
      total_sql_time => 0,
      query_count => 0
    };
    $log_req_obj->related_resultset('stages')->create($request_stage_log);
  }
}