綾小路龍之介の素人思考

[perl] プロファイラを用いた実行速度測定方法の比較(Devel::DProf、Devel::SmallProf、Devel::FastProf)

スクリプトの速度を比較したい場合に使うモジュールにサブルーチン単位のDevel::DProfと、行単位のDevel::SmallProf、Devel::FastProfがある。これらを使う方法とその比較、プロファイラを使うことによる実行速度の低下。

プロファイリングを行うスクリプトはprofiler_test.pl。

$ cat profiler_test.pl
#!/usr/bin/perl
use strict;
use warnings;

#use Data::Dumper;

my $data = func();
func0($data);
func1($data);

#print Dumper $data;
exit;

sub func {
    my $node0;
    foreach ( 0 .. 31 ) {
        $node0->{$_} = {};
        my $node1 = $node0->{$_};
        foreach ( 0 .. 31 ) {
            $node1->{$_} = {};
            my $node2 = $node1->{$_};
            foreach ( 0 .. 31 ) {
                $node2->{$_} = {};
                my $node3 = $node2->{$_};
                foreach ( 0 .. 31 ) {
                    $node3->{$_} = {};
                    my $node4 = $node3->{$_};
                    $node4->{func0} = 'func0';
                    $node4->{func1} = 'func1';
                }
            }
        }
    }
    return $node0;
}

sub func0 {
    my $node0 = shift;
    foreach ( keys %{$node0} ) {
        my $node1 = $node0->{$_};
        foreach ( keys %{$node1} ) {
            my $node2 = $node1->{$_};
            foreach ( keys %{$node2} ) {
                my $node3 = $node2->{$_};
                foreach ( keys %{$node3} ) {
                    my $node4 = $node3->{$_};
                    $node4->{func0} = 'func0';
                }
            }
        }
    }
}

sub func1 {
    my $node0 = shift;
    foreach my $k0 ( keys %{$node0} ) {
        foreach my $k1 ( keys %{ $node0->{$k0} } ) {
            foreach my $k2 ( keys %{ $node0->{$k0}->{$k1} } ) {
                foreach my $k3 ( keys %{ $node0->{$k0}->{$k1}->{$k2} } ) {
                    $node0->{$k0}->{$k1}->{$k2}->{$k3}->{func1} = 'func1';
                }
            }
        }
    }
}

速度はtimeコマンドで測定することにする。まずは単独で走らせたときの結果。

$ time perl profiler_test.pl

real 0m44.375s
user 0m4.816s
sys 0m0.116s

Devel::DProfを使う例。timeコマンドによれば速度の低下はほとんど無し。tmon.outがカレントディレクトリに作成され、これはdprofppで参照できる。

$ time perl -d:DProf profiler_test.pl

real 0m44.717s
user 0m4.820s
sys 0m0.148s
$ dprofpp tmon.out
Total Elapsed Time = 43.84998 Seconds
  User+System Time = 4.889983 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 43.3   2.120  2.120      1   2.1200 2.1200  main::func
 23.1   1.130  1.130      1   1.1300 1.1300  main::func1
 20.4   1.000  1.000      1   1.0000 1.0000  main::func0
 0.00       - -0.000      1        -      -  strict::bits
 0.00       - -0.000      1        -      -  strict::import
 0.00       - -0.000      1        -      -  warnings::import
 0.00       - -0.000      2        -      -  main::BEGIN

func0とfunc1は連想配列の中身を書き換える関数である。func0は連想配列へのアクセスにメモリ上の位置を使っている。func1は連想配列へのアクセスにキーを使っている。Devel::DProfの結果からメモリ上の位置を記憶させる方が(func0の方が)早いことがわかる。

Devel::SmallProfを使う例。timeコマンドによれば16倍程度に速度低下。smallprof.outがカレントディレクトリに作成され、これはcatコマンドなどで参照できる。

$ time perl -d:SmallProf profiler_test.pl

real 13m2.615s
user 1m17.213s
sys 0m9.753s
$ cat smallprof.out
           ================ SmallProf version 2.02 ================
                          Profile of profiler_test.pl                  Page 1
       =================================================================
    count wall tm  cpu time line
        0   0.00000   0.00000     1:#!/usr/bin/perl
        0   0.00000   0.00000     2:use strict;
        0   0.00000   0.00000     3:use warnings;
        0   0.00000   0.00000     4:
        0   0.00000   0.00000     5:#use Data::Dumper;
        0   0.00000   0.00000     6:
        1   0.00000   0.00000     7:my $data = func();
        1   0.00000   0.00000     8:func0($data);
        1   0.00000   0.00000     9:func1($data);
        0   0.00000   0.00000    10:
        0   0.00000   0.00000    11:#print Dumper $data;
        1   4.41105   0.48000    12:exit;
        0   0.00000   0.00000    13:
        0   0.00000   0.00000    14:sub func {
        1   0.00000   0.00000    15:    my $node0;
        1   0.00000   0.00000    16:    foreach ( 0 .. 31 ) {
       32   0.00001   0.00000    17:        $node0->{$_} = {};
       32   0.00003   0.00000    18:        my $node1 = $node0->{$_};
       32   0.00000   0.00000    19:        foreach ( 0 .. 31 ) {
     1024   0.03295   0.00000    20:            $node1->{$_} = {};
     1024   0.00033   0.01000    21:            my $node2 = $node1->{$_};
     1024   0.03236   0.01000    22:            foreach ( 0 .. 31 ) {
    32768   1.19528   0.20000    23:                $node2->{$_} = {};
    32768   0.77734   0.12000    24:                my $node3 = $node2->{$_};
    32768   1.03954   0.21000    25:                foreach ( 0 .. 31 ) {
  1048576  33.72827   6.53000    26:                    $node3->{$_} = {};
  1048576  28.13931   5.45000    27:                    my $node4 = $node3->{$_};
  1048576  36.07179   6.79000    28:                    $node4->{func0} =
  1048576  33.76210   6.58000    29:                    $node4->{func1} =
        0   0.00000   0.00000    30:                }
        0   0.00000   0.00000    31:            }
        0   0.00000   0.00000    32:        }
        0   0.00000   0.00000    33:    }
        1   0.00000   0.00000    34:    return $node0;
        0   0.00000   0.00000    35:}
        0   0.00000   0.00000    36:
        0   0.00000   0.00000    37:sub func0 {
        1   0.00000   0.00000    38:    my $node0 = shift;
        1   0.00001   0.00000    39:    foreach ( keys %{$node0} ) {
       32   0.00001   0.00000    40:        my $node1 = $node0->{$_};
       32   0.00049   0.00000    41:        foreach ( keys %{$node1} ) {
     1024   0.03294   0.01000    42:            my $node2 = $node1->{$_};
     1024   0.07621   0.00000    43:            foreach ( keys %{$node2} ) {
    32768   0.86101   0.18000    44:                my $node3 = $node2->{$_};
    32768   2.78642   0.55000    45:                foreach ( keys %{$node3} ) {
  1048576  28.38261   6.24000    46:                    my $node4 = $node3->{$_};
  1048576  29.96298   5.55000    47:                    $node4->{func0} =
        0   0.00000   0.00000    48:                }
        0   0.00000   0.00000    49:            }
        0   0.00000   0.00000    50:        }
        0   0.00000   0.00000    51:    }
        0   0.00000   0.00000    52:}
        0   0.00000   0.00000    53:
        0   0.00000   0.00000    54:sub func1 {
        1   0.00000   0.00000    55:    my $node0 = shift;
        1   0.00001   0.00000    56:    foreach my $k0 ( keys %{$node0} ) {
           ================ SmallProf version 2.02 ================
                          Profile of profiler_test.pl                  Page 2
       =================================================================
    count wall tm  cpu time line
       32   0.00037   0.00000    57:        foreach my $k1 ( keys %{ $node0-
     1024   0.10307   0.02000    58:            foreach my $k2 ( keys %{ $node0-
    32768   2.68094   0.46000    59:                foreach my $k3 ( keys %{
  1048576  34.89408   6.64000    60:                    $node0->{$k0}->{$k1}-
        0   0.00000   0.00000    61:                }
        0   0.00000   0.00000    62:            }
        0   0.00000   0.00000    63:        }
        0   0.00000   0.00000    64:    }
        0   0.00000   0.00000    65:}

Devel::FastProfを使う例。timeコマンドによれば1.6倍程度に速度低下。fastprof.outがカレントディレクトリに作成され、これはfprofppコマンドで参照できる。

$ time perl -d:FastProf profiler_test.pl

real 1m42.409s
user 0m7.993s
sys 0m3.384s
$ fprofpp -f fastprof.out
# fprofpp output format is:
# filename:line time count: source
profiler_test.pl:60 13.72410 1048576: $node0->{$k0}->{$k1}->{$k2}->{$k3}->{func1} = 'func1';
profiler_test.pl:29 11.09643 1048576: $node4->{func1} = 'func1';
profiler_test.pl:26 10.71653 1048576: $node3->{$_} = {};
profiler_test.pl:28 10.68122 1048576: $node4->{func0} = 'func0';
profiler_test.pl:47 9.70313 1048576: $node4->{func0} = 'func0';
profiler_test.pl:46 5.65761 1048576: my $node4 = $node3->{$_};
profiler_test.pl:27 5.00859 1048576: my $node4 = $node3->{$_};
profiler_test.pl:12 4.79216 1: exit;
profiler_test.pl:59 2.02908 32768: foreach my $k3 ( keys %{ $node0->{$k0}->{$k1}->{$k2} } ) {
profiler_test.pl:45 1.69200 32768: foreach ( keys %{$node3} ) {
profiler_test.pl:25 0.25556 32768: foreach ( 0 .. 31 ) {
profiler_test.pl:43 0.17796 1024: foreach ( keys %{$node2} ) {
profiler_test.pl:44 0.15651 32768: my $node3 = $node2->{$_};
profiler_test.pl:24 0.14754 32768: my $node3 = $node2->{$_};
profiler_test.pl:23 0.10395 32768: $node2->{$_} = {};
profiler_test.pl:58 0.07397 1024: foreach my $k2 ( keys %{ $node0->{$k0}->{$k1} } ) {
profiler_test.pl:22 0.03299 1024: foreach ( 0 .. 31 ) {
profiler_test.pl:42 0.00217 1024: my $node2 = $node1->{$_};
profiler_test.pl:20 0.00199 1024: $node1->{$_} = {};
profiler_test.pl:21 0.00078 1024: my $node2 = $node1->{$_};
profiler_test.pl:57 0.00047 32: foreach my $k1 ( keys %{ $node0->{$k0} } ) {
profiler_test.pl:41 0.00043 32: foreach ( keys %{$node1} ) {
profiler_test.pl:17 0.00007 32: $node0->{$_} = {};
profiler_test.pl:40 0.00006 32: my $node1 = $node0->{$_};
profiler_test.pl:19 0.00004 32: foreach ( 0 .. 31 ) {
profiler_test.pl:39 0.00002 1: foreach ( keys %{$node0} ) {
profiler_test.pl:18 0.00002 32: my $node1 = $node0->{$_};
profiler_test.pl:56 0.00001 1: foreach my $k0 ( keys %{$node0} ) {
profiler_test.pl:34 0.00000 1: return $node0;
profiler_test.pl:16 0.00000 1: foreach ( 0 .. 31 ) {
profiler_test.pl:8 0.00000 1: func0($data);
profiler_test.pl:9 0.00000 1: func1($data);
profiler_test.pl:7 0.00000 1: my $data = func();
profiler_test.pl:38 0.00000 1: my $node0 = shift;
profiler_test.pl:55 0.00000 1: my $node0 = shift;
profiler_test.pl:15 0.00000 1: my $node0;

リファレンス

  1. Devel::DProf - search.cpan.org
  2. dprofpp - search.cpan.org
  3. Devel::SmallProf - search.cpan.org
  4. Devel::FastProf - search.cpan.org
  5. fprofpp - search.cpan.org

ソーシャルブックマーク

  1. はてなブックマーク
  2. Google Bookmarks
  3. del.icio.us

ChangeLog

  1. Posted: 2010-04-05T20:29:45+09:00
  2. Modified: 2010-04-05T20:29:45+09:00
  3. Generated: 2017-06-17T23:09:31+09:00