ゆーすけべー日記

Webアプリケーションが遅いとか感じる時って、僕の場合、I/Oがボトルネックなケースが多いのです。つまり、MySQLへクエリーを投げて返却を待つとか、memcachedにget/set等のメソッドを発行した時の待ち時間が長くかかってたり... とかです。そうすると計測して原因を突き止めたくなります。PerlのプロファイラはDevel::NYTProfとか色々ありますが、こうしたI/Oに関しての計測は「Devel::KYTProf」が便利です。適当な場所にて

use Devel::KYTProf;

するだけで標準エラー出力に「空気読んで」ウマいこと色付きで、I/O周りのかかった時間とどこの箇所か？を表示してくれます。

ただ、この「標準エラー出力に表示」ってのは開発時にターミナルで確認する分には便利なのですが、例えば本番環境などで一時的にパフォーマンスを計測するためにはちょっと不便なことがあります。出来れば確認がしやすいようにファイルに書き出したくなります。Devel::KYTProfではlogメソッドを実装してあるロガーを指定すれば、柔軟に出力を制御出来るので、それを利用してファイルに書き出すことが出来ます。

ネームスペースをどうするか？Mouse使っている！ってのは置いておいて以下のようなロガークラスを定義します。

package Nopaste::Logger;
use Mouse;
use Log::Dispatch;
use Term::ANSIColor qw/colorstrip/;
use File::Spec;
use Encode;

has 'filename' => ( is => 'ro', isa => 'Str', default => 'kytprof.log' );
has 'logger' => ( is => 'ro', isa => 'Log::Dispatch', lazy_build => 1 );

sub _build_logger {
    my $self = shift;
    my $file = File::Spec->catfile('./log/' . $self->filename);
    my $log = Log::Dispatch->new(
        outputs => [
            [ 'File', min_level => 'debug', filename => $file, mode => 'append' ],
        ],
   );
   return $log;
}

sub log {
    my ($self, %args) = @_;
    my $message = $args{message};
    $message = colorstrip($message);
    $message = encode_utf8($message);
    my $time = scalar localtime;
    $message = "[$time] $message";
    $self->logger->debug($message);
}

__PACKAGE__->meta->make_immutable();

1;

logクラスでは

• 表示するメッセージを引数から取得
• ファイルに書き出すのでカラー表示のためのいらない文字を削除する
• エンコード周りの処理
• タイムスタンプを追加

してからLog::Dispatchを使ってファイルに追加保存していきます。 これをWebアプリのコード内で使います。

use Devel::KYTProf;
use Nopaste::Logger;

...;

my $logger = Nopaste::Logger->new;
Devel::KYTProf->logger($logger);

今回の設定だと、アプリを実行しているディレクトリから見て「./log/kytprof.log」というファイルにログが出力されます。ファイルを覗いてみるとこんな感じ！

お、いい感じですね。おかげでmemcachedのgetが異様に時間かかってる！ってのが発見出来たりして面白いです。オレオレで試しでやってみているので他にいい方法があれば教えてください＞＜