業務中、機能を拡張するにあたり、PHPで構築されたサーバサイドの処理状況ならびに負荷をみるためにqcachegrindでプロファイルを観測する機会がありました。

…ふーん、なるほどね…

…ふんふん…

…

「全行程の処理割合が100%超えてるように見えるんだがどういうこと？」
「ツリーどうなってるの？よくわからん」
「結局一番やばいボトルネックどれよ」
「そもそも見方なんもわからん…」

脳内で複数の私が私会議を始めてしまったので、いろいろ試行して自分なりに運用方法を考えてみることにしました。

⚠注意⚠

当記事全編の主旨は「試行を通して仕様を想像・理解して運用を考える」になっております。参考程度に留めてください

環境¹

アプリ	バージョン
PHP	5.6.15
Xdebug	2.3.2

導入と運用方法

こちらの記事を参考にさせていただきました。
XDebugとqcachegrindを使ってPHPアプリのパフォーマンスボトルネックを見つける

試行

ひとまず以下のような、演算＋メソッド＋標準関数のみのソースで、メソッドを繰り返しcallするコードを用意しました。
これを実行したときのプロファイルを出力してqcachegrindで確認します。

test00.php

<?php
$a = range(1,100);
$b = array();
foreach ($a as $number) {
    $b[] = increaseNumber($number);
}
// 100回callされる
function increaseNumber($number){
    usleep(10000); // 0.1sのdelay
    return $number + 10;
}
var_dump($b);

想定通り、ひとくちサイズのプロファイルになりました。

最初に表示したプロファイルは「WEBからのリクエストを或るフレームワークが受信〜画面描画するまで」の処理を表現したものだったので、ControllerのdispatcherやViewへのassignなど、フレームワークの基礎レイヤの処理まで含めて表現していたので、非常に情報量が多く混乱していました。

この試行ではmainプロセスがいくつかのFunction（処理）を呼び出している程度なので、比較的落ち着いて見ることができそうです。

まだわからないことが多いので、色々試行してみます。

最小試行

以下のような、何もしないソースを実行してみました。

kyomu.php

<?php

mainプロセスのみのプロファイルになっているようです。ほんの少しですが処理時間もかかっています。

所要時間の単位

最初に実行したコードにて、繰り返し処理されるメソッドで都度0.01sのdelayを与えてみます。

test01.php

<?php
:
// 100回callされる
function increaseNumber($number)
{
    usleep(10000); // 0.01s
    return $number + 10;
}
:

追加したusleep()が全処理系で大きな遅延要素になったようです。想定する遅延は10000μs*100=1000000μsで、usleep()の所要時間値が1061362なので、表現単位はμsの模様。

Mapを見てみる

ここで{main}Functionを選択したまま、上ブロックのCallee Mapと下ブロックのCaller Mapを見てみます。

上はphp::usleepのSelfの数値が、下は{main}のIncl.の数値が出てますね。
なんだか遅延が大きすぎて見えにくい予感がしたので、遅延を1000μs毎に抑えたプロファイルで同図を見てみます。

上図に違いが出ました。他のFunction名とSelfの値が出てきました。
どうやら周りの色はフチではなくそれぞれのFunctionカラーであり、その包含関係を表現しているようです。

ひとまず、PHPプロセスが呼び出された場合、原初の{main}FunctionのCallee Mapをみて、大きな占有率を持っている末端メソッドに狙いを定めると良さそうです。

なお、これに反して下ブロックのCaller Mapは、「どこからcallされたのか」という全く逆方向に捉えたMapを提示します。

上下のブロックが「callした」or「callされた」という相反する視点の情報を提示することは、覚えておいて損はなさそうです。

同一の関数を複数の処理内でcallした場合

usleep()は、左ブロックにおける1Function（処理）として扱われました。では、複数の箇所から関数を呼び出したとき、どう見えるのでしょうか？
メソッド外でもusleep()をcallしてみます。

test02.php

<?php

$a = range(1,100);
$b = array();
foreach ($a as $number) {
    $b[] = increaseNumber($number);
}
// 100回callされる
function increaseNumber($number)
{
    usleep(1000); // 0.001s
    return $number + 10;
}
usleep(100000); // 0.1s
var_dump($b);

下ブロックCall Graphに違いが出ました。どうやら同一Functionの複数箇所からcallしている場合、一つのFunctionにCall Graphと情報が集約されるようです。

ここでFunctionphp::usleepを選択します。

Call Graphのフォーカスがphp::usleepに移動しました。よく見ると、各パネルに表示されている数値も{main}を選択している状況から微妙に変わっています。どういうことでしょうか？

どうやら以下のような考え方をすれば良さそうです。

`{main}`選択中

自身のFunction{main}は総処理時間237784（{main}のIncl.）
そのうちincreaseNumberを{main}がcallしたことによる処理時間が130275（increaseNumberのIncl.）
php::usleepは、{main}、increaseNumberからcallされており、それらによる総処理時間が225254（php:usleepのSelf）

`php::usleep`選択中

自身のFunctionphp:usleepは処理時間225254（php:usleepのSelf）
そのうちincreaseNumberからphp:usleepをcallしたことによる処理時間が125023（increaseNumberのIncl.からSelfを除いた数値）
{main}は、直接と、increaseNumberを経由するのとでphp::usleepをcallしており、それらによる総処理時間が225254（php:usleepのSelf）

つまり、あくまで「選択したFunciton」の視点で表現されています。Call Graphを見るときは「選択しているFunctionが主役なんだな」と意識して読むと良さそうです。

画面の見方

色々試行してみたので、そろそろつまるところの「この画面でどういうことができる？わかる？」というところをほぐしていけそうです。

メニューバー

No	読み取れること・使い方
1	`Incl.`と`Self`の表示値を、パーセンテージ or 実測値（μs）に切り替える。パーセンテージの場合、`{main}`Functionの`Incl.`が概ね100%になる
2	選択中のFunctionから、呼び出し元Functionに移動できる（おそらくは`Call Graph`準拠）

左ブロック

No	要素名	読み取れること・使い方
1	Incl.	includeの略。その処理が呼び出している処理（さらにその処理が呼び出している処理、さらにさらにその処理が…）の処理時間すべてを含めた(include)、合計処理時間
2	self	そのFunction内での純粋な処理（演算、代入等）に要した時間。ここが一番でかいところが最大のボトルネックと考えて概ね差し支えないと思う。なお、別のFunctionをcallしている場合、そのFunctionの処理に要した時間は含まない
3	Called	呼び出し回数。${O(N+1)}$とか実施していたりすると明らかにこの数字に出るため、目安にしやすい

右の上下ブロック

左ブロックで選択したFunctionに応じて情報が表示される上下のブロックです。

わかるものだけボタンごとに説明します。
Callee Map、Caller Mapは前項で説明したため割愛。

No	ブロック位置	ボタン名	読み取れること
1	上	Callers	どのFunction からcallされたか。`Time per call`カラムがあり、複数回callしている場合は、1callあたりの処理時間を提示している。当たり前だが末端処理だと顕著にレコードが出る
2	上	All Callers	どのFunction からcallされたか。`Callers`とほぼ同じだが、こちらは処理時間の換算が`Caller Map`と近く、直接呼ばれているもの以外も載っている
3	下	Callees	どのFunction をcallしたか。`Callers`と対になるもの。当たり前だが冒頭処理だと顕著にレコードが出る
4	下	All Callees	どのFunction をcallしたか。`Callees`とほぼ同じもので、`All Callers`と対になるもの。直接呼んでいるもの以外も載っている

なお、随所に出てくるDistanceカラムは、そのFunctionからcallしている別のFunctionがどれくらい離れているかを表現している模様。
そのFunction自体がcallしていれば1、そのFuncitonがcallしたFuncitonがcallしていれば2、...という感じ。

おわり

結局、総処理割合が100%を超えてしまっている直接の原因はわかりませんでした。ただ、総処理数か総処理時間が大きくなるとズレが大きくなるような気がします。
ズレることやズレ自体はあまり気にしなくて良さそうでした。

ひとまず今乗りこなせるツールとして運用が整理できて個人的にはよかったです。

運用さえわかればいくらでも活用できるはず！CIに含ませてやばい処理あったらアラート出して止めるとか！そのときにこのプロファイルをつければ説得力も改善方法もわかりやすいですよね！~~でももし日本語ドキュメントあるなら読みたい~~

引き続き、見える化データ化を促進して、考えることを止めないようにやっていきたいです。

最新のPHP（7.3）だと動作するxdebugがないようだったので、少々レガシーですがLaravel＆homesteadを導入した直後の安定した仮想環境下で実施しています ↩

qcachegrindでみるxdebugプロファイルのあるきかた