思わぬところに眠っていたボトルネック

CakePHPで書かれたシステムが妙に重いと思ったら、想像もしないところにボトルネックがあったのを発見してしまった、ということがありました。

もともとの状況

ローカル環境で開発を始めたのですが、データベースへのアクセスもほぼないであろう、固定的なテンプレートを取得するのにすら¹1秒以上かかっていることに気づいて、いくらビルトインサーバと言ってもさすがに「これはおかしい」と調べてみることにしました。

Xdebugを仕掛ける

こういうときは慌てず騒がず、まずは「推測より計測」ということで、PHPにXdebugを入れてプロファイリングしてみることにしました。xdebug.profiler_enable_trigger = 1と設定しておくことで、XDEBUG_PROFILEという名前のGET/POSTパラメーター、あるいはCookieをセットすることで、必要なときだけプロファイリングを行うことができます。

そんな感じでプロファイリングデータを取得して、調査を行ってみたところ、1つのライブラリ内で70%以上の時間を消費していることに気づきました。

DeviceDetectorとは

piwik/DeviceDetectorは、ユーザーエージェントを解析して、ブラウザ種類やバージョン、ユーザーの環境を判定するためのツールです、そして、消費時間がかかっていたのは、判定に使うための情報がキャッシュされず、毎回YAMLを解析していたためでした。

さすがにそれはまずいと、CakePHPのキャッシュへとつなぐ部分を作成してDeviceDetectorに渡したのですが、それでも毎回YAMLの解析が続いていました。

呼び出すメソッドの問題

さらに調べ続けてみると、DeviceDetector::getInfoFromUserAgentを呼んでいることに気づきました。コード自体を確認してみると、

DeviceDetector.php

    /**
     * Parses a useragent and returns the detected data
     *
     * ATTENTION: Use that method only for testing or very small applications
     * To get fast results from DeviceDetector you need to make your own implementation,
     * that should use one of the caching mechanisms. See README.md for more information.
     *
     * @internal
     * @deprecated
     *
     * @param string $ua UserAgent to parse
     *
     * @return array
     */
    public static function getInfoFromUserAgent($ua)

    /* 後略 */

というようになっていました。そもそもこの関数自体がキャッシュ非対応だったということで、正しくインスタンスを作成してそちらから呼ぶようにしたところ、処理時間の過半を占めていたYAML解析は綺麗サッパリ消え去って、一気に速度が改善しました。

後日談

あとからRedisを入れたので、CakePHP自体のキャッシュもRedisへ振り替えたところ、それだけでレスポンスタイムが100ミリ秒ほどさらに改善しました。そして、デバイスによって挙動を変える必要自体がないAPI系のコントローラーでは、DeviceDetectorの呼び出し自体を行わないようにして、関連する処理時間をゼロとしています。

ブラウザ表示の時間でなく、「リクエスト→CakePHPがHTMLのレスポンスを返す」までが1秒超えという状態でした。 ↩