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

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

![しゅくしょう.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/101173/e516d170-ea45-5287-88cb-8ec575268f03.png)

…ふーん、なるほどね…


…ふんふん…




…




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

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

## ⚠注意⚠

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

# 環境[^1]

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

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

# 導入と運用方法

こちらの記事を参考にさせていただきました。
[XDebugとqcachegrindを使ってPHPアプリのパフォーマンスボトルネックを見つける](https://qiita.com/yudsuzuk/items/c3bafdceea77a8544e25)

# 試行

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

```php: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);
```

<img width="941" alt="スクリーンショット 2019-12-02 22.03.28.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/101173/66a8642d-afe4-02fb-ef47-f6b04ce5b8a2.png">


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

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

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

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

## 最小試行

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

```php:kyomu.php
<?php
```

<img width="941" alt="スクリーンショット 2019-12-02 22.34.23.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/101173/4cae88d5-2e9d-2881-f60f-a969ecf1f607.png">

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

## 所要時間の単位

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

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

<img width="941" alt="スクリーンショット 2019-12-02 22.46.42.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/101173/bb5e6e7d-9efc-855f-63d2-d20d604c343a.png">

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

## Mapを見てみる

ここで`{main}`Functionを選択したまま、上ブロックの`Callee Map`と下ブロックの`Caller Map`を見てみます。
<img width="940" alt="スクリーンショット 2019-12-02 23.20.40.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/101173/206a366f-3e81-dea0-62a1-2356532dd6e3.png">
上は`php::usleep`の`Self`の数値が、下は`{main}`の`Incl.`の数値が出てますね。
なんだか遅延が大きすぎて見えにくい予感がしたので、遅延を1000μs毎に抑えたプロファイルで同図を見てみます。
<img width="941" alt="スクリーンショット 2019-12-02 23.24.24.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/101173/318b88c0-dc73-048b-93fe-2348ebb1ad60.png">
上図に違いが出ました。他のFunction名と`Self`の値が出てきました。
どうやら周りの色はフチではなくそれぞれのFunctionカラーであり、その包含関係を表現しているようです。

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

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

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

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

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

```php: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);
```

<img width="939" alt="スクリーンショット 2019-12-03 0.33.34.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/101173/165446e7-3095-7e42-f8bc-1e90757281e1.png">

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

ここでFunction`php::usleep`を選択します。

<img width="941" alt="スクリーンショット 2019-12-03 0.36.06.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/101173/ec140f02-6216-09ea-3983-4043c80a27e1.png">

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

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

### `{main}`選択中

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

### `php::usleep`選択中

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

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

# 画面の見方

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

## メニューバー

<img width="715" alt="スクリーンショット 2019-12-03 1.07.15のコピー.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/101173/56d2cd2f-23ea-2e0d-e5a1-483a92b46e24.png">

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

## 左ブロック

<img width="391" alt="スクリーンショット 2019-12-03 1.16.58.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/101173/5b56cfd9-d4fc-0591-c881-d97546bb532a.png">

|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に含ませてやばい処理あったらアラート出して止めるとか！そのときにこのプロファイルをつければ説得力も改善方法もわかりやすいですよね！~~でももし日本語ドキュメントあるなら読みたい~~

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