Devel::NYTProf を読む

2009-09-05 05:27

Devel::NYTProf は Perl むけのプロファイラだ。機能が豊富で、HTML による結果出力がきれいで、プロファイラ自身のオーバーヘッドが少ない、ということで最近の Perl 界隈では事実上の標準プロファイラになっていると思う。

Devel::NYTProf

Perl にはもともとデバッガ用のインターフェースがある。perldoc perldebguts で低レベルな詳細が perldoc DB で (暫定的なものとされているけど) 高レベルなインターフェースが確認できる。後者からすこし引用しておこう。

Perl debug information is frequently required not just by debuggers, but also by modules that need some “special” information to do their job properly, like profilers.

Devel::NYTProf もこれを使用している、だけではなかった。

ソースツリー

  • Changes
  • HACKING
  • INSTALL
  • MANIFEST
  • META.yml
  • Makefile.PL
  • NYTProf.xs
  • README
  • benchmark.pl
  • bin/
    • nytprofcg
    • nytprofcsv
    • nytprofhtml
  • demo/
  • lib/
    • Devel/
      • NYTProf/
      • NYTProf.pm
  • perftest.pl
  • ppport.h
  • t/
  • typemap
  • xt/

Devel::NYTProf のうちの計測部分は C で書かれた NYTProf.xs にある。HTML 出力部分は lib/ 以下ではなく bin/nytprofhtml にあり Template::Toolkit や HTML::Template にたよらない男らしいコードだった。

use すると読み込まれる lib/Devel/NYTProf.pm にコードはほとんど無い。

package Devel::NYTProf;

our $VERSION = '2.10';

package    # hide the package from the PAUSE indexer
    DB;

# Enable specific perl debugger flags.
# Set the flags that influence compilation ASAP so we get full details
# (sub line ranges etc) of modules loaded as a side effect of loading
# Devel::NYTProf::Core (ie XSLoader, strict, Exporter etc.)
# See "perldoc perlvar" for details of the $^P ($PERLDB) flags

$^P = 0x010     # record line range of sub definition
    | 0x100     # informative "file" names for evals
    | 0x200;    # informative names for anonymous subroutines

# XXX hack, need better option handling
my $use_db_sub = ($ENV{NYTPROF} && $ENV{NYTPROF} =~ m/\buse_db_sub=1\b/);

$^P |= 0x002    # line-by-line profiling via DB::DB (if $DB::single true)
    |  0x020    # start (after BEGINs) with single-step on
    if $use_db_sub;

require Devel::NYTProf::Core;    # loads XS

if ($use_db_sub) {               # install DB::DB sub
    *DB = ($] < 5.008008)
        ? sub { goto &DB_profiler }    # workaround bug in old perl versions (slow)
        : \&DB_profiler;
}

init_profiler();                       # provides true return value for module

perldbguts に登場する DB::DB は、環境変数 NYTPROF に設定がないと使われないのがわかる。では、NYTProf はどこで時間を測定してるんだろうか。

フック

NYTProf.pm にあった DB::init_profiler は NYTProf.xs の末尾のほうにある

MODULE = Devel::NYTProf     PACKAGE = DB

...

int
init_profiler()
    C_ARGS:
    aTHX

から 

/* Initial setup */
static int
init_profiler(pTHX)
{

...

    /* redirect opcodes for statement profiling */
    Newxc(PL_ppaddr_orig, OP_max, void *, orig_ppaddr_t);
    Copy(PL_ppaddr, PL_ppaddr_orig, OP_max, void *);
    if (profile_stmts && !use_db_sub) {
        PL_ppaddr[OP_NEXTSTATE]  = pp_stmt_profiler;
        PL_ppaddr[OP_DBSTATE]    = pp_stmt_profiler;
#ifdef OP_SETSTATE
        PL_ppaddr[OP_SETSTATE]   = pp_stmt_profiler;
#endif
        if (profile_leave) {
            PL_ppaddr[OP_LEAVESUB]   = pp_leaving_profiler;
            PL_ppaddr[OP_LEAVESUBLV] = pp_leaving_profiler;
            PL_ppaddr[OP_LEAVE]      = pp_leaving_profiler;
            PL_ppaddr[OP_LEAVELOOP]  = pp_leaving_profiler;
            PL_ppaddr[OP_LEAVEWRITE] = pp_leaving_profiler;
            PL_ppaddr[OP_LEAVEEVAL]  = pp_leaving_profiler;
            PL_ppaddr[OP_LEAVETRY]   = pp_leaving_profiler;
            PL_ppaddr[OP_DUMP]       = pp_leaving_profiler;
            PL_ppaddr[OP_RETURN]     = pp_leaving_profiler;
            /* natural end of simple loop */
            PL_ppaddr[OP_UNSTACK]    = pp_leaving_profiler;
            /* OP_NEXT is missing because that jumps to OP_UNSTACK */
            /* OP_EXIT and OP_EXEC need special handling */
            PL_ppaddr[OP_EXIT]       = pp_exit_profiler;
            PL_ppaddr[OP_EXEC]       = pp_exit_profiler;
        }
    }

    /* redirect opcodes for caller tracking */
    if (!sub_callers_hv)
        sub_callers_hv = newHV();
    if (!pkg_fids_hv)
        pkg_fids_hv = newHV();
    PL_ppaddr[OP_ENTERSUB] = pp_entersub_profiler;

につながっている。そう、コメントにある通り、Devel::NYTProf は Perl VM のディスパッチテーブルを書き換え、計測用の関数をあいだにはさんでいる。

複数種の命令に同じ関数をあてて大丈夫なのか心配なので pp_stmt_profiler, pp_leaving_profiler, pp_exit_profiler まで追ってみると

static OP *
pp_stmt_profiler(pTHX)                            /* handles OP_DBSTATE, OP_SETSTATE, etc */
{
    OP *op = run_original_op(PL_op->op_type);
    DB_stmt(aTHX_ NULL, op);
    return op;
}

static OP *
pp_leaving_profiler(pTHX)                         /* handles OP_LEAVESUB, OP_LEAVEEVAL, etc */
{
    OP *op = run_original_op(PL_op->op_type);
    DB_leave(aTHX_ op);
    return op;
}

static OP *
pp_exit_profiler(pTHX)                            /* handles OP_EXIT, OP_EXEC, etc */
{
    DB_leave(aTHX_ NULL);                         /* call DB_leave *before* run_original_op() */
    if (PL_op->op_type == OP_EXEC)
        finish_profile(aTHX);                     /* this is the last chance we'll get */
    return run_original_op(PL_op->op_type);
}

現在実行中の命令はグローバル変数 PL_op で参照できるので問題ないようだ。pp_entersub_profiler はすこし入り組んでいるので省略。

DB_stmt, DB_leave なんて名前の関数が内部でしか使われていないのは、VM に手を入れる手法が開発のごく初期には無かった (DB を使う手法が最初にあった) せいかもしれない。Devel::NYTProf の HISTORY からすこし引用しておく。

Then he went a little crazy and added a slew of new features, in addition to per‐sub and per‐block timing and subroutine caller tracking. These included the ’opcode interception’ method of profiling, ultra‐fast and robust inclusive subroutine timing, doubling performance, …

計測

フックがしかけられれば、そこから計測をすればいい。pp_leaving_profiler, pp_exit_profiler から DB_leave にいくと

    /* measure and output end time of previous statement
     * (earlier than it would have been done)
     * and switch back to measuring the 'calling' statement
     */
    DB_stmt(aTHX_ NULL, op);

pp_stmt_profiler とおなじかたちで DB_stmt を呼び出していた。

DB_stmt は以下のことをやっている。

  • 現在の時刻 - 前の時刻を計算
  • それを書き出し
  • 現在の時刻を保存

コードのうち、該当する部分だけを抜き出すとこうなる。

DB_stmt(pTHX_ COP *cop, OP *op)
{
...
    if (usecputime) {
...
    }
    else {
        get_time_of_day(end_time);
        get_ticks_between(start_time, end_time, elapsed, overflow);
    }

    if (last_executed_fid) {

        output_tag_int((unsigned char)((profile_blocks)
                        ? NYTP_TAG_TIME_BLOCK : NYTP_TAG_TIME_LINE), elapsed);
        output_int(last_executed_fid);
        output_int(last_executed_line);
...
    }

    if (usecputime) {
...
    }
    else {
        get_time_of_day(start_time);
    }
...
}

get_time_of_day は第1引数、get_ticks_between は第3, 4引数を破壊するマクロなのがわかりづらい。fid は file id なので、これで各ファイルの行について、前の命令をぬけてから (run_original_op の後に DB_stmt を呼んでいるので) 今回の命令を実行し終わるまでにかかった時間がわかる。

プロファイル結果のファイルサイズ

ちょっと余談。NYTProf.xs には zlib による圧縮が組み込まれている。さらにいうと圧縮前のファイルもバイナリ形式だし、整数は Procotol Buffers や SWF のように桁数に応じてバイト長が変わる。fread でさくっと読めるような形式じゃない。

圧縮の理由については NYTProf 2.04 gives you 90% smaller data files に説明がある。

One of the major drawbacks of statement-level profiling is the volume of data it generates while profiling your code. For every statement executed the profiler streams out the file id, the line number, and the time spent. For every statement! When trying to profile a full application doing real work the volume of data generated quickly becomes impractical to deal with. Multi-gigabyte files are common.

まとめと関連

Devel::NYTProf は Perl むけのプロファイラで、VM をフックすることでプロファイルのオーバーヘッドをちいさくしている。ちなみに、プロファイラの結果も圧縮されるのでちいさい。

個人的には VM のディスパッチテーブルなんて static でファイルスコープにしておきたいけど、公開されてるってことは変更されることも、たぶん設計の意図のうちなんだろう。

なお、Perl の VM については Perl5 フレキシビリティ、プロファイラ全般については プロファイラのしくみ が参考になります。

Leave a Reply