CakePHPで高速Webアプリ開発
第11回 CakePHPの「DEBUG値」を極める!
今回はCakePHPのデバッグに重要な「DEBUG値」を極めます。CakePHPバージョンは1.1系を対象としています。
DEBUG値とは
DEBUG値は,app/config/core.php内で定義するDEBUG定数の値です。
app/config/core.php
/**
* Set debug level here:
* - 0: production
* - 1: development
* - 2: full debug with sql
* - 3: full debug with sql and dump of the current object
*
* In production, the "flash messages" redirect after a time interval.
* With the other debug levels you get to click the "flash message" to continue.
*
*/
define('DEBUG', 1);
DEBUG定数に設定する値は,0,1,2,3の4種類があります。0から順に解説していきます。
DEBUG値「0」は本番用。エラー出力なし
DEBUG値に「0」を設定すると,CakePHPのエラー画面でコードヒントなどが表示されなくなります。さらにCakePHPコア内で「error_reporting(0);」が実行され,PHPによるすべてのエラーは出力されなくなります(参考:PHP: error_reporting - Manual)。
PHPでは,WarningやFatal Errorを出力するとエラーが発生したファイルのパス名などが画面に出力されます。仮にアプリケーションにセキュリティホールがあったときに,ファイルのパス名などが出力されてしまうと,具体的な攻撃を行うための重要な情報を提供してしまうことになります。CakePHPに限らず,余計な情報は表示させないようにしましょう。
なお,CakePHPでは app/tmp/cache/models以下に,DBのスキーマと連動したモデルのキャッシュファイルが作成されています。このキャッシュファイルはDEBUG値を1以上にしない限り更新されませんので,DBの仕様変更などを行った際には手動で削除するかDEBUG値を1以上にして再作成してください。
本番環境では通常,この設定で運用します。
DEBUG値「1」は通常の開発用。エラー出力あり
DEBUG値に「1」を設定すると,CakePHPコア内では「error_reporting(E_ALL);」と「ini_set('display_errors', 1);」(ini_setが使用可能な場合のみ)が実行され,PHP5においてはE_STRICT以外の全てのエラーが出力されます。
また,HTMLのコメントとして,CakePHPアプリケーションの実行時間(アプリケーションが呼び出されてから結果出力まで)のミリ秒時間が末尾に出力されます。
以下のように末尾に実行時間が出力される
<!-- 0.079s -->
この実行時間出力は,DEBUG値が1以上のときは常に行われます。しかしJSONやバイナリデータなどを出力した場合,このHTMLコメントによってJSONテキストをそのまま処理できなかったり,バイナリデータにゴミが付加されてしまうことになります。
幸いなことに,この時間出力はアプリケーション部分の「app/webroot/index.php」で行われています。必要なときだけ出力すれば良い情報ですので,JSONやバイナリを出力するアプリケーションの場合は「app/webroot/index.php」内の以下のコードをコメントアウトしてしまってもよいでしょう。
app/webroot/index.php
if (Configure::read() > 0) {
echo "<!-- " . round(getMicrotime() - $TIME_START, 4) . "s -->";
}
デフォルトのDEBUG値はこの「1」が設定されています。
DEBUG値「2」はDBへのクエリーのデバッグ情報が出力される
DEBUG値「2」は,DEBUG値「1」をベースに,末尾にDBへのクエリのデバッグ情報が出力されます。たとえば,本連載で作成したToDoアプリケーションでDEBUG値を「2」にすると,以下のような情報が画面末尾に出力されます。
3 queries took 1 ms
| Nr | Query | Error | Affected | Num. rows | Took (ms) |
|---|---|---|---|---|---|
| 1 | DESCRIBE `tasks` | 5 | 5 | 1 | |
| 2 | SELECT `Task`.`id`, `Task`.`content`, `Task`.`status`, `Task`.`created`, `Task`.`modified` FROM `tasks` AS `Task` WHERE `Task`.`status` = 'yet' ORDER BY `Task`.`created` ASC | 3 | 3 | 0 | |
| 3 | SELECT `Task`.`id`, `Task`.`content`, `Task`.`status`, `Task`.`created`, `Task`.`modified` FROM `tasks` AS `Task` WHERE `Task`.`status` = 'done' ORDER BY `Task`.`modified` DESC | 1 | 1 | 0 |
この情報の各カラムの意味は以下のとおりです。
- 「* queries took * ms」実行したクエリの数と,合計時間です。
- 「Nr」実行したクエリーの連番です。
- 「Query」実行したSQL文です。
- 「Error」クエリがエラーだった場合,エラー情報が入ります。
- 「Affected」UPDATEやDELETEの際は,影響した行数が入ります。 SELECTの場合は結果の行数です。
- 「Nom. rows」結果の行数です。
- 「Took (ms)」DB上でのクエリの実行時間と考えて差し支えありませんが,CakePHPコア内の処理時間の一部も含まれるため,DB上での実行時間だけとは限りません。APCなどのPHPアクセラレータを導入した際にこの値が短縮されることがあります。
このようにクエリの合計時間とクエリ1つ1つについての情報が列挙されるので,かなり充実した内容となっています。CakePHPがどんなクエリを発行しているかということと,それぞれのクエリーの実行時間がわかるため,ボトルネック調査のときなどにかなり重宝するでしょう。
個人的にはこの出力はCakePHPの目玉機能の1つではないかと思います。


