PHPプログラムのパフォーマンス可視化 #PHP

計測の話。

PHP7.1にて、 xhprofを使おうと思ったらどうも使えないので、 tideways_xhprofを使った。

インストール

phpenv を使っている環境にインストールをした。ドキュメントそのままで、ソースコードを落としてきて、下記のコマンドを実行。

git clone https://github.com/tideways/php-profiler-extension.git
cd php-profiler-extension
phpize
./configure
make
make test
make install
echo 'extension=tideways_xhprof.so' >> ~/.phpenv/versions/7.1.13/etc/conf.d/tideways.ini;
echo 'tideways.auto_prepend_library=0' >> ~/.phpenv/versions/7.1.13/etc/conf.d/tideways.ini

使い方

xhprof とほぼ使い方は同じで、実行関数名が少し違う程度だった。

使い方の確認を兼ねて、10万文字のテキストにそれぞれの文字の頭に1文字余計に追加するプログラムを作る。

処理方法は ~~よくやる間違い~~ ありがちなmb_substr でやる方法と、preg_split で分解してから処理する方法の２つを比べてみる。

mbstr.php

mb_substr で一文字ずつ取り出してみていく。

<?php

$a = makeRandom();

$length = mb_strlen($a);
$result = '';
for($i=0; $i < $length; $i++){
    $b = mb_substr($a, $i, 1);
    $result .= '-'.$b;
}

mbarray.php

preg_split で文字単位で分割し配列化してから、 foreach でループで回して処理をする。

<?php

$a = makeRandom();

$buff = preg_split('//u', $a);
$result = '';
foreach($buff as $b){
    $result .= '-'.$b;
}

run.php

上記２つのうち、指定した方を実行して、プロファイル結果を保存する。

<?php

tideways_xhprof_enable();

function makeRandom (){
    $length = 100000;
    $start = ord('あ');
    $end = ord('ん');
    $result = '';

    for($i = 0; $i < $length;$i++){
        $result .= chr(random_int($start,$end));
    }
    return $result;
}

require $argv[1];

file_put_contents(
    './' .$argv[1].'.xhprof',
    json_encode(tideways_xhprof_disable())
);

実行結果

$ /usr/bin/time php run.php mbstr.php
2.12user 0.04system 0:02.17elapsed 99%CPU (0avgtext+0avgdata 11860maxresident)k
0inputs+8outputs (0major+14834minor)pagefaults 0swaps

$ /usr/bin/time php run.php mbarray.php 
0.16user 0.03system 0:00.19elapsed 97%CPU (0avgtext+0avgdata 12200maxresident)k
0inputs+8outputs (0major+14913minor)pagefaults 0swaps

解析

実行後、mbarray.php.xhprof および mbstr.php.xhprof ができてるので、プロファイル結果を表で表示してみる。

これをするには tideways/toolkit が必要なので、インストールをする。

$ go get github.com/tideways/toolkit
$ ls -l ~/go/bin
drwxr-xr-x  3 yasui  staff    96B 10 23 20:06 ./
drwxr-xr-x  4 yasui  staff   128B 10 23 20:06 ../
-rwxr-xr-x  1 yasui  staff   4.6M 10 23 20:06 toolkit*

toolkit がインストールできたなら、実行パスを通して、実行をしてみる。　

$ PATH='~/go/bin':$PATH

ついでに一覧表以外にも、graphvizをインストールしているなら、グラフ化もしてみる。graphvizは HomeBrew で予めインストールしています。

mbstr のプロファイル結果

$ toolkit analyze-xhprof -m 0 mbstr.php.xhprof                                                                                                   git:master ? :S6
Showing XHProf data by Exclusive Wall-Time
+-------------------------+--------+------------+------------------------------+
|        FUNCTION         | COUNT  | WALL-TIME  | EXCL  WALL-TIME (>= 0.00 MS) |
+-------------------------+--------+------------+------------------------------+
| mb_substr               |  33334 | 1926.22 ms | 1926.22 ms                   |
| makeRandom              |      1 | 146.50 ms  | 133.92 ms                    |
| main()                  |      1 | 2101.69 ms | 28.86 ms                     |
| random_int              | 100000 | 7.96 ms    | 7.96 ms                      |
| chr                     | 100000 | 4.62 ms    | 4.62 ms                      |
| mb_strlen               |      1 | 0.12 ms    | 0.12 ms                      |
| tideways_xhprof_disable |      1 | 0.00 ms    | 0.00 ms                      |
+-------------------------+--------+------------+------------------------------+
Looking for a Web UI and SQL Profiling Support? Try our SaaS: https://tideways.io

$ toolkit generate-xhprof-graphviz -o mbstr.php.xhprof.dot mbstr.php.xhprof 
$ dot -Tsvg -o mbstr.php.xhprof.svg mbstr.php.xhprof.dot
$ open -a 'Google Chrome' mbstr.php.xhprof.svg

mbarray のプロファイル結果

$ toolkit analyze-xhprof -m 0 mbarray.php.xhprof                                                                                                 git:master ? :S6
Showing XHProf data by Exclusive Wall-Time
+-------------------------+--------+-----------+------------------------------+
|        FUNCTION         | COUNT  | WALL-TIME | EXCL  WALL-TIME (>= 0.00 MS) |
+-------------------------+--------+-----------+------------------------------+
| makeRandom              |      1 | 131.23 ms | 117.61 ms                    |
| random_int              | 100000 | 8.73 ms   | 8.73 ms                      |
| chr                     | 100000 | 4.89 ms   | 4.89 ms                      |
| main()                  |      1 | 132.59 ms | 0.97 ms                      |
| preg_split              |      1 | 0.39 ms   | 0.39 ms                      |
| tideways_xhprof_disable |      1 | 0.00 ms   | 0.00 ms                      |
+-------------------------+--------+-----------+------------------------------+
Looking for a Web UI and SQL Profiling Support? Try our SaaS: https://tideways.io


$ toolkit generate-xhprof-graphviz -o mbarray.php.xhprof.dot mbarray.php.xhprof
$ dot -Tsvg -o mbarray.php.xhprof.svg mbarray.php.xhprof.dot
$ open -a 'Google Chrome' mbarray.php.xhprof.svg

結果

mb_substr は呼び出し回数が多く、そして全体の実行速度も遅いです。これは mb_substr の使い方を少し間違えているのが原因かと。
mbarray.php の方は makeRandom がボトルネックになっておりそれがパフォーマンスに影響しているような図になっていますが、そもそも makeRandom の実行速度は mbstr.php も実行しているので問題はない。

という感じ。メソッド単位で見たい時は表を表示したらいいけど、大きなくくりだと呼び出しメソッドが多くなって見にくくなるので、適度に細目化するか、グラフ化したらちょっとわかるよという感じ。

toolkitには他にもオプションがあるけど、使い方わからん。

PHPプログラムのパフォーマンス可視化