PHP開発時におけるデバッグ／プロファイリングの手段・ツール3+2選

Toshihiko Kimura
  • このエントリーをはてなブックマークに追加
  • Evernoteに保存

こんにちは。ライトな記事を担当しているリスペクトの木村です。

PHPの開発時に大変お世話になるデバッグやプロファイリングの手段ですが、探してみると種類が沢山あって、どれを使えばいいのか迷ってしまいます。
そこで、その中から普段使用しているツールや手段をいくつかご紹介したいと思います。

ちなみに、私はCakePHPがメインなので、「CakePHPでの開発時によく利用しているもの」に絞ったものになります。

今回の環境

  • CentOS 6.6
  • PHP 5.5.25
  • CakePHP 2.6.1

今回の手段やツール

主に、次の5つを用途や場面に合わせて使い分けています。

ツール 用途 デバッグ時 プロファイリング時
var_dump() とにかく変数の中身や関数の返り値を見たい時に ○
Xdebug／debug() ある程度整形された状態でvar_dump()したい時に ○
DebugKit CakePHP上での処理状態や実行時間、リクエストデータを確認したい時に ○ ○
ChromeLogger 表示画面に影響を与えずに各種の値を確認したい時に ○
Blackfire 処理の流れや処理時間を細かく追いたい時に ○

基本的にはフレームワークを問わず使えるものが多いのですが、debug()やDebugKitはCakePHP固有のものになっています。

デバッグとプロファイリングの違い

ご存じの方も多いとは思いますが、デバッグとプロファイリングでは役割が異なります。

デバッグは、広義ではバグやエラーの原因を突き止めて修正する手段の事を指します。
デバッグの手法や流れは利用するツールや環境によって大きく異なりますが、今回は「変数の中身や関数の返値を画面上やログへ出力するデバッグ」という部分に主眼を置いて説明したいと思います。
例えば、Xdebug+IDEを利用してブレークポイント／ステップ実行をするデバッグや、gdbやphpdbgを利用した深いところまで追跡するデバッグについては今回は扱いません。

対してプロファイリングは、プログラム実行時における様々な情報を収集して確認する手段を指します。
関数の呼び出し頻度や実行時間の収集によって、全体的なパフォーマンスの確認やアプリケーション内に存在するボトルネックを確認するために使われます。
デバッガーやプロファイラーは後ほど紹介するCakePHPのDebugKitのように、フレームワークであれば標準機能やオプションとして用意されている場合が多いですし、XdebugのようにPHPのエクステンションとして用意されている場合もあります。
本格的に追おうとするとエクステンション系のプロファイラーになるので導入障壁が高いのですが・・・その分の価値はあります。

個人的には、利用頻度としてはデバッグ系が一番多いです。
プロファイリング系は開発の後半になると使い始めたり、開発中にパフォーマンスが気になるようであればそのタイミングでちょっと見てみたりしています。

という訳で、一つ一つ見てみたいと思います。

var_dump()

知らない人はいないはず、ほぼ説明不要のvar_dump()関数です。
var_dump()は引数に変数や関数を渡すと、その中身や返り値を画面上に表示してくれます。

<?php
$str = 'a';
$array = array('a' => 'b', 'c' => 'd');

var_dump($str);
var_dump($array);
var_dump(is_array($str));

上記のような感じで値を渡すと、

string(1) "a"
array(2) {
  ["a"]=>
  string(1) "b"
  ["c"]=>
  string(1) "d"
}
bool(false)

こんな感じで出力されます。

また、引数は複数渡す事もできます。

<?php
$str = 'a';
$array = array('a' => 'b', 'c' => 'd');

var_dump($str, $array, is_array($str));

この場合は・・・

string(1) "a"
array(2) {
  ["a"]=>
  string(1) "b"
  ["c"]=>
  string(1) "d"
}
bool(false)

3つ続けて実行した時と同じ出力になりました。

ブラウザ上で確認する場合は、var_dump()の前後を<pre>タグで囲うと若干見やすくなります。

02
この表示が・・・

01
こうなります。少し見やすくなりました。

var_dump()はちょっとしたデータを確認したりするのには楽です。「とりあえずどんな値が入っているか確認したい」という時はよくあるので、頻繁に使っています。

ただ、配列やオブジェクトを表示しようとすると整形されずに表示されてしまいます。
上記のように前後に<pre>を挟めば何とか表示できますが・・・それでも毎度挟むのは少し手間です。

そういった場合は、次に紹介するXdebugやCakePHPで利用可能なdebug()関数を利用する事で整形して表示してくれます。

Xdebug

Xdebugも、定番のデバッガーです。(今回は2.3.2を使用しています)
PHPには標準で入っていないため、別途導入する必要があります。
Windowsの場合はコンパイル済みの拡張が配布されていますし、それ以外の場合はpecl install xdebugで導入する事ができます。

PHPUnitでコードカバレッジを確認するのにも必要なので、入っている開発環境は意外と多いかもしれません。

Xdebugを入れるとすぐに受けられる恩恵が、「var_dump()の機能拡張」です。
先ほど試したvar_dump()のデモで比較すると、出力が全然異なります。

01
この表示が・・・

07
こうなります。<pre>タグでの囲みは不要です。

整形してくれて便利なのですが、その一方、表示したいものの要素が多かったり階層が深かったりすると省略されてしまいます。

<?php

$array = array(
  'a' => array(
    'b' => array(
      'c' => array(
        'd' => array(
          'e'
        )
      )
    )
  )
);
var_dump($array);

↓
08

制限を緩和したかったり全て表示したい場合は、下記の設定を変更する必要があります。

  • xdebug.var_display_max_children / 表示する子要素の数。デフォルトは128
  • xdebug.var_display_max_data / 表示する要素の数。デフォルトは512
  • xdebug.var_display_max_depth / 表示する階層の深さ。デフォルトは3

それぞれ数値を指定するか、-1にすると無制限で表示されるようになります。
php.iniで設定する他に、ini_set()や.htaccessのphp_valueでも設定可能です。

また、Xdebugが有効だとエラー発生時に次のようにスタックトレースを表示してくれたり・・・

09

トレースログやプロファイリングデータの出力なんかも可能ですし、IDEと連動してリモートデバッグもできたりします。

debug()

CakePHPを使っていると利用可能になるdebug()関数は、グローバル関数なのでどこでも使えます。
Xdebugのように別途ライブラリをインストールする必要もありません。
ただし、出力はConfig/core.phpで定義するDebug Levelが1または2(Development Mode)の場合のみ表示されます。

<?php
$str = 'a';
$array = array('a' => 'b', 'c' => 'd');

debug($str);
debug($array);
debug(is_array($str));

03

こんな感じで、var_dump()するよりも若干見やすく整形して、どのファイルの何行目で呼び出されているかも合わせて表示してくれます。

また、第二引数にfalseを指定すると、スタイルが適用されずに単なるテキストとして表示されます。

～
debug($str, false);
～

05

第三引数もあり、ここにfalseを指定するとどのファイルの何行目で呼び出されたか、の表示を非表示にする事ができます。
(めったに使いませんが・・・)

～
debug($str, true, false);
～

06

このように、Xdebug／debug()を利用する事で見やすく出力できるようになりました。
特に階層が深い配列やオブジェクトなんかは無加工のままvar_dump()すると追うのが大変なので、こういう見やすくしてくれる手段が存在するのは非常に有り難いです。

これでデバッグがより快適に行えるようになりましたが、var_dump()やdebug()のような「画面に出力する」系を使うと出力する場所によってはレイアウトが崩れてしまう場合が十分にあります。
また、設定や場面によっては画面に表示できないという場合もあるので、その場合は確認するためにわざわざ設定を調整する・・・という作業も必要になります。

ログに出力すれば良いのですが、フレームワークを利用していない場合はわざわざログ生成回りのロジックを用意しなければならないので、少し億劫な時もあります。
そんな時は、Chrome Loggerを使って、画面に影響を与えずにデバッグを行えるようにします。

Chrome Logger

Chrome Loggerは、サーバサイドアプリケーションでの出力ログをChromeのDeveloper ToolsにあるConsoleパネルから見られるようにしてくれる、ちょっと変わり種のツールです。
上記サイトにある対応している言語一覧を見ると、PHPの他にもRubyやPython、さらにはGoにも対応しています。

導入

非常に簡単です。

  1. Chrome Web StoreからChromeのExtensionを導入する
  2. PHPの場合は https://github.com/ccampbell/chromephp にライブラリが置いてあるので、「ChromePhp.php」をダウンロードしてincludeする、もしくはComposerで導入

これだけです。

使ってみる

プログラム側は、出力したいタイミングでChromePhp::log()を使用して、引数にテキストを渡すだけです。
他にも、ChromePhp::warn()やChromePhp::error()で出力するログの種類を変えられたり、ChromePhp::group()でそれ以降の出力をグループ化する事もできます。

Chrome側は、Chrome Loggerのボタンが表示されているので、ここを1回クリックしてOnの状態(アイコンが黒から青くなります)にしておく事で受信できるようになります。

10
上の画像の一番右のボタンです。この状態でOnになっています。

実行してみるとこんな感じで出力されます。

<?php
require_once 'ChromePhp.php';
ChromePhp::log('log');
ChromePhp::warn('warning');
ChromePhp::error('error');

ChromePhp::group('group');
ChromePhp::log('log');
ChromePhp::warn('warning');
ChromePhp::error('error');

11

仕組み

その仕組みは結構簡単です。
ライブラリや公式のTech Specを眺めていると分かりますが、「X-ChromeLogger-Data」というヘッダにbase64化したjsonデータを紛れ込ませて送信しているだけです。
ライブラリの394行目を見ると、値をエンコードしてheader()で送信しています。
DeveloperConsoleを見ても、確かにヘッダに含まれています。

12

そのため、output_bufferingがOffの環境でデータ出力後にログを出力しようとすると、Headers already sentや、 Cannot modify header informationが表示されます。

13

また、標準関数やフレームワークでの関数とは違い、そのままですと環境を問わず出力してしまうという所にも注意が必要です。
受信用のChrome Extension自体は誰でも入れられますので、もしChrome Loggerのコードが公開環境でも残ったままですと、本当は人に見られたくないようなデバッグ出力が第三者に受け取られてしまうかもしれません。
そのため、確認時のみincludeして使用する、という運用が最適かと思われます。

ChromeLoggerを使う事で、画面に影響を与えずにデバッグ用の情報を出力できるようになりました。
var_dump()などで画面に出力できない部分(Ajaxを利用したAPIでのやりとりなど)のデバッグログ出力も行えるようになるので、そういった場面ではChromeLoggerで確認する事が多いです。

これである程度の動きは難なく追えるようになりましたが、毎回デバッグの出力文を書く必要は変わらずあります。
自分で制御している部分はある程度仕方ないのですが、フレームワークで制御されている部分ほど頻繁に確認するのがほとんどなので、その度に画面毎にデバッグ文を書いて・・・というのは手間な場合がほとんどです。

そこで、フレームワークにはデバッグツールが付いてきている場合があるのでそれを使ってみるというのも一つの手です。
使っている環境によって様々ですが、CakePHPではDebugKitを使用します。

DebugKit

DebugKitをご存じない方に向けてどんなものか簡単に説明しますと、CakePHP向けに提供されているデバッグツールです。
フレームワーク内で処理された送受信データやSQLクエリのログや実行時間が確認でき、更に、フレームワーク内部の処理時間やメモリの使用量も確認できます。
そのため、デバッグツールとしてだけではなく、簡易的なプロファイラーとしても利用しています。

導入して利用可能にすると下記のようなツールバーが表示されます。

23

各パネルをクリックすると詳細情報が表示され、それぞれ次の内容が確認できます。

パネル名 主な用途
History DebugKitが有効な状態で送信した今までのリクエストが確認できます。
Session 現在のセッションに格納されている情報を確認できます。
Request GETやPOSTで飛んできたリクエストやルーティング、Cookieの情報などリクエスト送受信回りのデータが確認できます。
Sql Log 発行したSQLのクエリログを確認できます。 ここからExplainできたり、時間がかかっているログには印が付いたりするので、SQL回りの問題の原因は比較的見つけやすいです。
Timer 各処理にかかった時間や消費したメモリの量を確認できます。
Log ログに書き出す処理($this->log())を実行した時に出力されたログの内容を確認できます。
Variables コントローラーからビューに設定($this->set())した内容や、$this->request->dataの中身、ページャーで利用したデータの中身が確認できます。
Environment PHPやCakePHPで使用できる環境変数を確認できます。
Include

プラグインをロードしてコンポーネントとして読み込ませる(DebugKit.Toolbar)だけなので使い始めも非常に楽です。
debug()と同じく、Debug Levelが1または2(Development Mode)の場合のみ表示されるため、本番環境でちゃんとLevelを切り替えていれば間違って表示される事もありません。

ちなみに、FuelPHPにもプロファイリングという同じようなものがあります。 見た目はこっちの方が豪華ですね・・・。

補助ツールを使う事により、頻繁に確認するデータについてはコードに変更を加えなくとも確認できるようになり、実行時間やSQLクエリログも確認できるようになりました。フレームワーク様々です。
しかし、あくまでも簡易的なものなので、もう少しロジックの流れを深く追ったりボトルネックを追いたいという場合は本格的なプロファイラーで計測する必要があります。

Xdebugにもプロファイリング機能は付いているのですが・・・今回はブラウザベースで視覚的に解析結果を追えるBlackfireを使ってみます。

Blackfire

Blackfireは、Symfonyの開発元のSensioLabsが開発した、PHP向けプロファイラーです。
ChromeのExtension(以下Companion)の他にもPHPのExtension(以下Probe)やサーバ側に計測用デーモン(以下Agent)を入れなければならなかったりと、導入までのハードルは高いのですが、その分精度が高かったり細かい所まで計測してくれるので、ボトルネックを簡単に見つける事ができます。

導入

サーバー側の準備はGetting Startedに詳しく書いてあるので、基本的にはそれに沿って進めれば良いかと思われます。

ちなみに、会員登録が必要(GitHubかGoogleがあればOK)です。
また、次の環境下でないと動作しないため注意が必要です。

  • Probe/Agentの動作はLinux/Macが必要
  • Probeが入れられるのはPHP 5.3～5.6まで
  • CompanionはChromeのみ
  • 結果表示はIE以外で動作

Debian系やRHEL系であればリポジトリを追加してそこからAgentやProbeを導入できますし、マニュアルでのインストールも可能です。Macの場合はHomebrewから。
環境により若干変わってきますが、基本的には以下のような流れです。

  • Agentを入れて
  • Server IDとServer Tokenを設定(Getting Startedのページに記載してあります)
  • CLI toolを入れて
  • Probeをインストール

このProbeがくせ者のようで、「PHPが –enable-debug がついてビルドされていると使用不可」「XdebugやXHProfと共存不可、Probe有効時にこの辺入っていた場合は自動で無効化」という条件付きのようです。
Xdebugとの共存は環境を変えるなり手動で切り替えれば良いのですが、それが大変という場合はどちらかを選ばなければなりません。

ここまで無事に導入できたら、CompanionをChromeに導入します。
Blackfireにログイン済みであれば、Companionにも自動でログインされます。

使ってみる

今回はWebページのプロファイリングを試しにやってみます。
他にも、blackfireコマンドを経由する事でCLIのスクリプトやAPI／Webサービスの呼び出しなんかもプロファイリングできます。

プロファイリングしたいサイトを開いてBackfire Companionのアイコンをクリックすると、こんなポップアップが表示されます。

14

確か最初はデモでいくつか入っていたはずなので、「Untitiled (Empty)」になっているスロットを選んで「Profile!」をクリックすると計測が始まります。

計測中はプログレスバーが表示され・・・

15

計測が完了すると簡単な計測結果が表示されます。
右から総実行時間、I/O、CPU、メモリ使用量、ネットワーク使用量の順です。

16

計測結果の横にある「View Profile」をクリックすると、プロファイリング結果のページが表示されます。

17

上の計測結果のバーは大体同じですが、カーソルを載せると詳細が表示されます。
タイトルの部分に載せると、リクエスト結果やサーバ側に導入されているBackfireコンポーネントのバージョンが確認できます。

18

メインの画面に視線を移すと、2ベインの構成になっています。右側が関数やメソッドのリストで、左側がコールグラフです。
コールグラフで赤い枠で覆われていたり背景が赤い部分は、そのアプリケーションのボトルネックとなっている部分です。
色が濃ければ濃いほどよりボトルネックとなっている部分ですので、そこを確認して解消するようにします。

19

グラフをクリックすると、関数リストの該当部分を表示してくれます。
関数毎のプロファイリング結果や、その関数が他の関数をどれだけ呼び出しているか、というのが確認でき・・・

20

関数名の横にある虫眼鏡マークをクリックすると、コールグラフ上で呼び出され／呼び出しの詳細な相関図が確認できます。

21

リストでは、実行時間(Excl.が排他時間、Incl.が統括時間)や呼ばれた順に並び替えが可能です。

22

ちなみに、プロファイル結果は共有する事も可能です。
試しに今回の結果を共有してみましたので、どんな感じで動作するか確認できます。

まとめ

普段デバッグやプロファイリングで使っているツールをいくつかご紹介しました。
デバッグ周りは基本的なものがほとんどでしたが、変わり種枠でご紹介したChrome Loggerは色んな所で使えるのではないかと思います。開発時はかなりお世話になる部分なので、おさえておいて損は無いはずです。

プロファイリングはかなり多種多様でした。BlackfireはSymfonyの開発元が作っているだけあって、解析や調査がかなりやりやすいです。
サーバの管理者権限が必要だったり、PHP拡張やデーモンも入れなければならなかったりとハードルは高めですが・・・Vagrantなどの仮想環境でも使えるので、手元の環境で試してみて、どんな感じか感覚を掴んでみて頂ければと思います。
使ってみれば分かる、はずです。

他にも、良いツールがあれば是非共有して頂ければな、と思います。
現場からは以上です。

  • このエントリーをはてなブックマークに追加
  • Evernoteに保存