DBIx::Class::QueriesTime

昨日に引き続きDBICでもやってみた。
こっちはSQLとBindも表示。

package DBIx::Class::QueriesTime;

use strict;

use warnings;

use vars qw( $VERSION );

$VERSION = 0.01;

package DBIx::Class::Storage::DBI;

use Time::HiRes qw( tv_interval gettimeofday );

no warnings 'redefine';

sub _execute {

  my ($self, $op, $extra_bind, $ident, @args) = @_;

  my ($sql, @bind) = $self->sql_maker->$op($ident, @args);

  unshift(@bind, @$extra_bind) if $extra_bind;

  if ($self->debug) {

      my @debug_bind = map { defined $_ ? $_ : 'NULL' } @bind;

      $self->debugfh->print("$sql: @debug_bind\n");

  }

  my $sth = $self->sth($sql,$op);

  croak "no sth generated via sql: $sql" unless $sth;

  @bind = map { ref $_ ? ''.$_ : $_ } @bind; # stringify args

  my $rv;

  if ($sth) {

    my $befor_query = [gettimeofday];

    $rv = $sth->execute(@bind);

    warn "query:$sql :",map { defined $_ ? $_ : 'NULL' } @bind,"\nquery time: ",tv_interval ( $befor_query );

  } else { 

    croak "'$sql' did not generate a statement.";

  }

  return (wantarray ? ($rv, $sth, @bind) : $rv);

}

1;

美しくないなぁ。
かなり元の_executeに依存しまくり。redefineだからしかたないのか。
しかしexecuteの部分の時間をとろうとするとこれしかないなぁ。

使い方はこんな感じ。

__PACKAGE__->load_components(qw/Core DB QueriesTime/);

結果はこんなの。

query:SELECT me.id, me.name FROM user2 me WHERE ( name = ? ) :nekokak

query time: 0.274815 at DBIx/Class/QueriesTime.pm line 28.

まぁ、$self->debugfh->printでログに出力してもよいかと思う。

後はDBI自体をHackするかですね。