WordPressチューニング、その前に使うDebug Bar

WordPressは非常にポピュラーなソフトウェアです。非常に多くのサイトで使われており、この「さくらのナレッジ」もWordPressをベースに作られています。

WordPressはPHPのコードとApache等のWebサーバ、mySQL等のDBサーバで構成されています。インストールは比較的簡単ですぐに始められるのですが、WordPress自体が大きなプログラムであるのに加え、多数のプラグインやテーマが流通しているため、どんどん機能を追加するうちにサイトが重くなっていき、見るに堪えないページができあがってしまうこともしばしばです。そのためか、WordPressのチューニング方法を取り上げた記事はとても多く、どれも人気があります。ただ、それらの記事で紹介されている手法が、本当に自分のサイトを速くしてくれるのだろうかと、疑問に思ったことはないでしょうか。チューニングの基本はまず測定です。そこでWordPressサイトの「性能」を、どうやって計測するのか、それを用いてどのようにチューニングするかを取り上げたいと思います。

サイトのスピードを測ってみる
Debug-Bar-ExtenderでWordPress内部の動作をチェックする
チェックポイントを設定して遅いコードを突き止める
遅いコードを追い詰める
おわりに

サイトのスピードを測ってみる

サイトのスピード、つまりリンクやブックマークをクリックしてから、画面表示が完了するまでに、何秒かかるかを測るにはどうすればよいでしょうか。ストップウォッチを片手に測るのもいいのですが、目の前に優秀な計算機があるのですから、これを使わない手はありません。代表的なブラウザにはデベロッパー・ツールやデバッグ・ツールといった機能があって、これを使うと簡単にサイトのロード時間を計測することができます。ChromeやFirefoxの場合は標準でデベロッパー・ツールがありCTRL+SHIFT+Iを押すと使えます。さらにFirefoxにはFirebugという有名なプラグインがあります。ブラウザによって使えるツールと表示形式はそれぞれ異なるのですが、ここではChromeを例にご紹介したいと思います。

Chromeを起動してCTRL+CHIFT+Iを押すと、デベロッパー・ツール画面が開きます。ツール画面に「Network」というタブがあるのでクリックし、ブラウザから計測したいサイトを表示します。するとページを構成する項目ごとのロード時間と、最後にページロードにかかった時間をグラフ化して表示してくれます。

Chromeを使った時間計測の例

画面の例は、実は「さくらのナレッジ」のミラーサイトで、4月1日時点のコードを対象に時間を計測したものです。トップページのロードに5.11秒もかかっていることが分かります。実は「さくらのナレッジ」の目標ロード時間は2秒以下だったので、大きくオーバーしてしまっています。

いったい何がそんなに遅いのでしょうか。このグラフ表示はページを構成するすべての要素ごとに、タイムラインと所要時間を表示してくれます。右側のスクロールバーを使ってどの項目が遅いのかを探してみます。すると、いちばん最初のインデックス・ページのロードが非常に遅いことが分かります。

遅いページを探す

インデックス・ページは最初に読み込まれますが、これのロードになぜか3.33秒もかかっています。インデックス・ページ読み込み終了後、その他の項目は全体で1.78秒で読み込みが終わるので、問題はインデックス・ページのどこかにありそうです。

Debug-Bar-ExtenderでWordPress内部の動作をチェックする

インデックス・ページのロードが遅い原因は、一般的には以下の要因が考えられます。

サーバの性能不足。WordPressはPHPプログラムなので性能が不足すると遅くなる
DBの性能不足。ページを構成するためにDBアクセスが欠かせず、これが遅いとページ生成も遅れる
ネットワークの問題。アプリサーバ（Webサーバ）とDBが別になっているとき、この間のネットワークが原因で遅くなる
プラグインの問題
プログラム（WordPressを改変したり、デザインを変更した結果、動作に問題が生じたり遅くなったりする）

しかしこれらのうち何が原因であるのかは、ブラウザでいくら計測しようとしても分かりません。そこで、WordPressのプラグインの力を借りて問題点を炙り出してみましょう。Debug BarとDebug-Bar-Extenderを使います。

インストール方法は、まずDebug Barを入れて、それからDebug-Bar-Extenderを入れてください。まあ、WordPressをご利用の方ならやり方はよくご存知ですよね。

インストールが完了すると、管理バーにDebugというボタンが現れます。

Debug Bar 有効時の管理バー

プラグインが有効になったら、計測したいページをロードして、このDebugボタンを押します。するとDebug BarおよびExtenderが、さまざまなベンチマークを行った結果を表示してくれます。

Debug Bar - Queries結果

Debug Bar画面には多くのメニューがありますが、今回はQueries（Debug Bar標準の機能）とProfiler（Debug-Bar-Extenderによる拡張機能）をご紹介します。なお、右上に「Please Enable WP_DEBUG」とありますが、今回はこれをONにせずとも機能を利用できるので今回は見なかったことにしてください。

Debug Bar画面のQueriesを選択すると、DBサーバに送ったクエリの数と経過時間を知ることができます。この画面を確認すれば、対象のサイトがどれぐらいDBに負荷をかけているか、DBの応答がどれほどのものかを計測することができます。この例では、あまり大きな負荷はかかっておらず、DBは良好な応答時間で動作しているとみなせそうです。つまりインデックス・ページが遅い理由はDBにはなさそうだ、ということです。

次にProfilerの方を見てみましょう。

Debug Bar - Profiler結果

ページの最初に大きく「3,385.60ms」と表示されていますが、msは1/1000秒に相当しますので、3.385秒かかっているという意味になります。最初にブラウザの機能で計測した数値に近いですね。どうやらこのどこかに、表示が遅くなる原因が隠れているようです。

Debug-Bar-Extenderは、特に設定がない状況では、WordPressのさまざまな個所に自動的にフックを置いて、だいたいのプロファイリングを行ってくれます。Summary画面では、それらのデフォルトのフック位置でそれぞれどれぐらいの経過時間が観測されたかを表示します。それぞれのフックは数字の見出しと大雑把な位置情報と共に表示されますが、残念ながらこの画面では具体的にどこが遅いのかを突き止めることができません。まず、全体にわたって遅いのか、一部だけ遅くなっているのかを掴むために、スクロールバーをたどって全体を眺めてみます。すると10行目にこんな行が見つかりました。

Profile画面の詳細

他の行では数ミリ秒から数百ミリ秒で処理されているにもかかわらず、この部分だけ3秒もかかっていることが分かります。10行目を詳しく見ると、「get_header_action」とありますが、実は必ずしもget_header_actionの処理中に遅くなっているというわけではありません。もっと詳しくコードを調べていかなければいけません。

チェックポイントを設定して遅いコードを突き止める

Profile画面を一番下までスクロールすると、こんな記述に出くわします。

Profile画面 - Flowの注意書き

Profile画面では、SummaryとFlowの2種類の結果を確認できます。Flowは、処理の流れに沿ってプロファイリングをしてくれる便利なモードなのですが、これを利用するためには注意書きにあるようにコードを埋め込まなければいけません。具体的には以下の3つのコードが利用できます。

Extender::instance()->start()
プロファイルを開始する場所に置きます。この地点から計時を始めます
Extender::instance()->checkpoint()
プロファイル中にチェックしたい個所に置きます。この前に通ったstartあるいはcheckpointからの経過時間が記録され、Profile画面で確認できるようになります
Extender::instance()->end()
プロファイルを終了する場所に置きます。checkpointと同様経過時間も記録されます

それぞれのコードの引数にはコメントを付けることができ、このコメントもProfile画面に表示されます。さまざまなcheckpointごとに分かりやすいコメントを付けてプログラムに配置すれば、処理フローに従って何秒ずつかかったかを目で見ることができるわけです。

さて、それではプログラムのどこに、どのようにしてチェックポイントを配置すればよいでしょうか。みなさんが実践するうえでは、サイトでお使いのテーマやプラグインによって入れる場所が変わってくると思いますが、最初に手をつけるべきはインデックスを生成する部分でしょう。

どんなテーマにも、インデックスを生成するためのindex.phpが存在すると思います。その構造はだいたい以下のようになっています。

get_header();

	LOOP

get_sidebar();
get_footer();

これらのコードの特徴は、ヘッダ、サイドバー、フッタの3つのパートを処理するよう順にコールされている個所があるということです。これらのうち、どこで問題が発生しているかを突き止めるために、Extenderのチェックポイントを次のように配置します。

Debug_Bar_Extender::instance()->start("Profile Start");
get_header();
Debug_Bar_Extender::instance()->checkpoint("Begin loop");

	LOOP

Debug_Bar_Extender::instance()->checkpoint("Call Sidebar");
get_sidebar();
Debug_Bar_Extender::instance()->checkpoint("Call Footer");
get_footer();
Debug_Bar_Extender::instance()->end("Profile End");

ブロックの間に、チェックポイントを挟んでいくようなイメージです。もしお使いのテーマが異なる構造になっていても、処理の間にチェックポイントを入れ、適切なコメントを付ければよいはずです。

チェックポイントを入れて、ページをロードしてみると、Profile画面のFlowの部分が以下のように変わります。

Profile画面 - Flow計測結果

プログラムに入れた「Profile Start」から、Flowの計測が始まっていることが分かります。この後、Summaryで見たデフォルトのフックのほか、自分で入れたチェックポイントとコメントが同様に出力されていきます。チェックポイントを探して、スクロールしていくと、次のような個所に出くわしました。

Profile画面 - 時間がかかっている個所を探す

まず53行目の2.7秒かかっている個所に注目します。これはコメントから、get_footer()を実行する直前のチェックポイントと分かります。注意するべきなのは、2.7秒かかっている処理はこのチェックポイントより前で発生しているということです。これより前の、自分で入れたチェックポイントは48行目ですが、コメントからget_sidebar()を実行する直前のものと分かります。要するにget_sidebar()の処理の中で、2.7秒かかっている処理が存在するということになります。

遅いコードを追い詰める

当サイトのデザインを見てみると、サイドバーと呼ばれている部分には以下の3つの要素があります。

カテゴリー
筆者
人気記事ランキング

この3つのうち、1と2は割とどのサイトでも見かける普通のウィジェットですが、3つ目の人気記事ランキングがちょっと怪しく思えます。そこでこのウィジェットのコードをさらに詳しく調べます。ウィジェットのコードは、プラグインディレクトリにファイルがあるのでそれをエディタで開き、「function widget」を含む行を探します。だいたい、次のような構造になっているはずです。

    function widget($args, $instance) {
        extract($args);
        :
        :
    }
    :
    :

見つかったら、以下のようにチェックポイントを入れます。

    function widget($args, $instance) {
        Debug_Bar_Extender::instance()->start("widget start");
        extract($args);
        :
        :
        Debug_Bar_Extender::instance()->end("widget end");
    }
    :
    :

このようにしてページをリロードし、ProfilerのFlowの結果を確認してみます。

ウィジェットを特定できた

ご覧のとおり、どのプラグイン（ウィジェット）が問題なのか、かなり絞り込めました。

さて、このままの勢いでコードをどんどん追いかけていきたいのですが、すでに紙面を大量に使ってしまっているので、結果だけお伝えいたします。widget()のコードの中では、さらにいくつも関数を呼び出しているため、適宜チェックポイントを追加してどのコード、どの関数が問題であるのかを逐次追いかけていき、最後にランキングの各ページがソーシャルからどれぐらいの評価を得ているのかを問い合わせている部分に行き当たりました。プラグインのコードをサクナレ用にカスタマイズする過程で、TwitterのRT数やはてなのブックマーク数を取得するコードが直接埋め込まれていたのです。

人気記事ランキング -
ソーシャル関連データを問い合わせる部分で遅かった
（ミラーサイトなので数値はデタラメです）

このうち、特にFacebookに「いいね」数を問い合わせる場所が400ms（0.4秒）かかっていることが分かりました。本来、ソーシャルボタンの処理は非同期で処理するべきなのですが、APIサイトの応答時間だけページ生成処理が待たされてしまうようになっていたため、上位5人の記事を表示するために0.4秒×5＝2秒、ここで遅延が発生していたのです。

原因が判明すれば、効果的な対策を打つことができます。現在サクナレをご覧のみなさんなら、ランキングから数字を表す部分がなくなっていることにお気づきでしょう。「あんまりクドクド数字を出すことないんじゃないの？」という意見に賛同票が集まり、シンプルに原因だったコードを削除して解決してしまったのです。

おわりに

今回はDebug BarとDebug-Bar-Extenderを使ったサイトのパフォーマンス計測について説明しました。サイトのチューニングに取り組み始めた時は「データベースの再構築をすることになったら面倒でイヤだなあ」と思っていたのですが、原因はまったく別のところにあることが分かり、無駄な手間をかけずに済んでよかったと胸をなで下ろす結果になりました。Debug Barはサイトの開発、デバッグ、チューニングに絶大な効果を発揮しますので、ぜひ使ってみてください。