Help us understand the problem. What is going on with this article?

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

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

しゅくしょう.png

…ふーん、なるほどね…

…ふんふん…

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

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

⚠注意⚠

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

環境1

アプリ バージョン
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);

スクリーンショット 2019-12-02 22.03.28.png

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

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

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

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

最小試行

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

kyomu.php
<?php

スクリーンショット 2019-12-02 22.34.23.png

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

所要時間の単位

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

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

スクリーンショット 2019-12-02 22.46.42.png

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

Mapを見てみる

ここで{main}Functionを選択したまま、上ブロックのCallee Mapと下ブロックのCaller Mapを見てみます。
スクリーンショット 2019-12-02 23.20.40.png
上はphp::usleepSelfの数値が、下は{main}Incl.の数値が出てますね。
なんだか遅延が大きすぎて見えにくい予感がしたので、遅延を1000μs毎に抑えたプロファイルで同図を見てみます。
スクリーンショット 2019-12-02 23.24.24.png
上図に違いが出ました。他の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);

スクリーンショット 2019-12-03 0.33.34.png

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

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

スクリーンショット 2019-12-03 0.36.06.png

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

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

{main}選択中

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

php::usleep選択中

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

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

画面の見方

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

メニューバー

スクリーンショット 2019-12-03 1.07.15のコピー.png

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

左ブロック

スクリーンショット 2019-12-03 1.16.58.png

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

右の上下ブロック

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

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

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


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

Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
Comments
No comments
Sign up for free and join this conversation.
If you already have a Qiita account
Why do not you register as a user and use Qiita more conveniently?
You need to log in to use this function. Qiita can be used more conveniently after logging in.
You seem to be reading articles frequently this month. Qiita can be used more conveniently after logging in.
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
ユーザーは見つかりませんでした