はじめに
実装機能の処理時間を調査しているときに、実装箇所とは別のところで大幅に時間がかかっている問題に遭遇しました。
その時の原因と、おまけで計測処理について自分用に記録します。
ざっくり言語・フレームワーク
言語:PHP
フレームワーク:FuelPHP
原因
結論:コードプロファイラがオンになっていたため
より細かく処理時間をログ出力して、原因を調査してみたところ最後のレスポンスを返すところまでは問題ありませんでした。
お手上げ状態の時にたまたま、コードプロファイラの存在を思い出し、オフにしてみたら解決しました。
プロファイラでは、プログラム実行時の様々な情報が確認できその中で実行されたSQLも確認できる。今回、かなり多くループ処理でSQL文（4~5万）が実行されていたた。そのすべての情報をプロファイラで出力されていたためプロファイラの処理に時間がかかったと考えられる。
（コード）プロファイラとは？
プロファイラとは、コンピュータプログラムが実行される様子を監視・記録し、プログラム中の各箇所の動作順や実行時間などを集計・解析するプログラム。ソフトウェアの開発環境や実行環境の機能の一部として提供され、プログラムの性能測定・解析を行うことができる。
引用元：プロファイラ（profiler）とは - IT用語辞典 e-Words
FuelPHPに同梱のアプリケーションプロファイラは、PHPQuickProfilerをベースにしています。
以下の画像がプロファイラの画像です。
プロファイラでは以下のような情報がわかる。
- Console. デフォルトのタブ。エラー、ログ、メモリ使用量や実行タイミングに関する情報を提供します。
- Load time. リクエストのロード時間。タブ内で詳細を表示します。
- Database. 実行されたクエリ数や実行時間および、もしサポートされていればクエリの解析。
- Memory. リクエストの処理に要したメモリ使用量。
- Files. 読み込まれた PHP ファイルのフルパス名と、それらの容量。
- Config. 処理の終了時点における、設定値の内容。
- Session. 処理の終了時点における、セッション値の内容。
- GET. $_GET 配列の内容。
- POST. $_POST 配列の内容。
使用するには設定ファイルで、以下のように設定すればよい。
'profiling' => true,
まとめ
今回は、コードプロファイラによって処理時間が大幅に増えたときのことをまとめた。
プロファイラの使用中に処理時間が増えた場合は、まず今回の件を思い出したい。