WordPress の表示が遅くなったので Debug Bar で調べてみた際のメモ

CATEGORY: WordPress | TAG: プラグイン

2014年10月12日

いつからから不明だが、気が付くといくつかのページの表示が恐ろしく時間がかかる（1分以上）ようになっていた。

結果的には「Debug Bar」と「Debug-Bar-Extender」というプラグインを使って切り分けたところ原因を特定できたけど、遠回りをしてしまった感もないではない。

取りあえずやってみたことをメモ。

注意事項：プラグインのインストールの前にはバックアップを取っておくように。

Chrome デベロッパー・ツールで確認

Chrome のデベロッパー・ツール（Windows の場合 F12キー）の Network パネルで確認するとなんとページの読み込みに50秒近くかかっていた。

以下は、問題解決後の Network パネルでの確認で、ページの読み込みが325ms（0.3秒）になっている。

何故それほどページの読み込みに時間がかかるのかが不明なので、プロバイダに問い合わせたところサーバー側には問題はないとの回答。

キャッシュのプラグインを使用してみてはとのこと。。。

なんだかそういう問題ではない気がするので調べてみると以下のページに次のようなことが書いてあった。

http://ja.forums.wordpress.org/topic/7713
（自分の現象とは異なるが、調べる目安にはなりそう）

プラグインを無効化してみて解消されるか
リビジョンも含めてpostsテーブルが肥大化していないか
管理画面の重さは均一か、あるいは特定の表示・動作の際のみ重いのか
ログファイルが見られるなら、なんらかのエラーログが出ていないか
Debug BarとDebug-Bar-Extenderで時間のかかっているクエリーがないか

プラグインに問題がないかの確認

P3 (Plugin Performance Profiler) というプラグインを使用してプラグインに問題があるかどうかを確認。

「Plugin Load Time」「Plugin Impact」ともに小さな値で問題なさそう。

プラグインというよりはテーマの読み込みに時間がかかっているみたい。

念のため、全てのプラグインを無効化してみたが現象は変わらず。そのため、プラグインが原因ではなさそうと判断。

posts テーブルの確認

postsテーブルが肥大化していないかを確認。

肥大化しているかどうかをどうやって判断するかがわからないので、取りあえず少し前にローカルに保存したものと現在のサーバー上のテーブルを phpMyAdmin で比較してみた。

サーバー上のものは投稿が207件、ローカルのものは180件
サーバー上の postsテーブルは1129行、ローカルのものは640行

すこし肥大化しているといえば言えるのか？（わからない）

Debug Bar で確認

プラグイン Debug Bar をインストールして有効化。

wp-config.php を少し変更。（切り分け終了後は元に戻す）

//以下は false を true に変更
define('WP_DEBUG', true);

//以下2行を追加
define('SAVEQUERIES', true);
define('WP_DEBUG_DISPLAY', false);

インストールして有効化すると、管理バーに「Debug」というボタンが表示されるので調べたいページをロードして、「Debug」ボタンをクリックすると、デバグを行った結果を表示してくれる。

試してみるとエラーが表示されていた。

WARNING: wp-includes/wp-db.php:1655 – Error while sending QUERY packet. PID=7200
require(‘wp-blog-header.php’), require_once(‘wp-includes/template-loader.php’), include(‘/themes/wdl2014/single.php’), previous_post_link, get_previous_post_link, get_adjacent_post_link, get_adjacent_post, wp_get_object_terms, wpdb->get_col, wpdb->query, wpdb->_do_query, mysql_query

NOTICE: wp-includes/wp-db.php:1655 – mysql_query() [function.mysql-query]: send of 268 bytes failed with errno=32 Broken pipe
require(‘wp-blog-header.php’), require_once(‘wp-includes/template-loader.php’), include(‘/themes/wdl2014/single.php’), previous_post_link, get_previous_post_link, get_adjacent_post_link, get_adjacent_post, wp_get_object_terms, wpdb->get_col, wpdb->query, wpdb->_do_query, mysql_query

「Error while sending QUERY packet.」や「send of 268 bytes failed with errno=32 Broken pipe」と書いてあるので検索してみるが、望むようなものは見つからず。

取りあえずテーブルが壊れていないかを phpMyAdmin で確認。

全てのテーブルを選択して「テーブルを分析する」を実行。

結果は特に問題はなさそう。

Debug-Bar-Extender のインストール

「Debug-Bar-Extender」の使い方は以下のサイトに詳しく書かれています。

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

「Debug Bar」だけでは詳しい情報がわからないので「Debug-Bar-Extender」をインストール。

但し、「Debug-Bar-Extender」のサイトを見てみると以下のような警告（このプラグインは2年以上アップデートされていない。。。）が表示されていた。

This plugin hasn’t been updated in over 2 years. It may no longer be maintained or supported and may have compatibility issues when used with more recent versions of WordPress.

それでも試しにと思いインストール後に有効化して、再度「Debug」ボタンをクリックしてみると問題なさそう。（自己責任で）

更に左側メニューの「Profiler」をクリック。

ページ上部に「45,226.57ms（ミリ秒）」と表示されているのがわかる。

Chrome のデベロッパー・ツールの Network パネルで確認した値「45.55s（秒）」とほぼ同じ。

Debug-Bar-Extender はデフォルトでは、自動的にフックを置いて、だいたいのプロファイリングを行ってくれるらしい。

但し、それでは問題がどこかを判断するのは難しいので、チェックポイントを設定して問題箇所を突き止める必要がある。

Profiler の画面では、Summary と Flow の2種類の結果が確認できる。

Flow は、処理の流れに沿ってプロファイリングをしてくれるが、これを利用するためには特定のコードを埋め込必要がある。

具体的には以下の3つのコードが利用可能（Profiler 画面の一番下に記載されている）。

Note: you can measure runtimes between checkpoints via Debug_Bar_Extender::instance()->start( $note=”” ), Debug_Bar_Extender::instance()->checkpoint( $note=”” ), Debug_Bar_Extender::instance()->end( $note=”” ) or using the simple shortcut function dbgx_checkpoint( $note=”” )

Debug_Bar_Extender::instance()->start()
プロファイルを開始する場所に置く。（ここから計測を開始）
Debug_Bar_Extender::instance()->checkpoint()
プロファイル中にチェックしたい個所に置く。
Debug_Bar_Extender::instance()->end()
プロファイルを終了する場所に置く。

引数にコメントをつけることにより、Profiler の画面にそのコメントが表示される。

以下は Single.php に「Debug_Bar_Extender」のコードを配置した例。疑わしい箇所の前後等にわかりやすい名前の引数を付けて配置。

<?php Debug_Bar_Extender::instance()->start("Profile Start"); ?>
<?php get_header(); ?>

<?php Debug_Bar_Extender::instance()->checkpoint("Begin loop"); ?>
<div id="contents">
<?php if(have_posts()): while(have_posts()): the_post(); ?>
<div class="single_content">
<?php the_content(); ?>

<?php Debug_Bar_Extender::instance()->checkpoint("Call GetPostImages"); ?>
<div id="post_image_info">
<?php 
$postImages = getPostImages($post);
if($postImages != null) {
　省略  
}
?>
</div>
<?php endwhile; endif; ?>

<?php Debug_Bar_Extender::instance()->checkpoint("Call Adsense"); ?>
<div class="adsense">
<script async src="//pagead2.googlesyndication.com/pagead/js/adsbygoogle.js"></script>
<!-- 20140620_rspv_bottom -->
<ins class="adsbygoogle"
     style="display:block"
     data-ad-client="ca-pub"
     data-ad-format="auto"></ins>
<script>
(adsbygoogle = window.adsbygoogle || []).push({});
</script>
</div>
</div><!-- end of #content -->

<?php Debug_Bar_Extender::instance()->checkpoint("Call Sidebar"); ?>
<?php get_sidebar(); ?>
</div>

<?php Debug_Bar_Extender::instance()->checkpoint("Call Footer"); ?>
<?php get_footer(); ?>
<?php Debug_Bar_Extender::instance()->end("Profile End"); ?>

再度「Debug」ボタンをクリックして左側メニューの「Profiler」をクリック後、スクロールして下のほうの「Flow」を確認するとコメントに入れた箇所が表示されているのがわかる。

どうも以下が問題の箇所らしいと判明。

どうも自分で作成した Light Box 風の表示の関数が原因のようだということが判明。

その関数の何が問題なのかはこれから調べる必要があるが、取りあえずこの関数を使用しないことにして表示が遅いのは改善された。（45,226.57ms から 104.47ms に劇的に？改善）

これで表示が遅い原因がわかったので、このためにインストール＆有効化したプラグインは全て停止して、wp-config.php も元に戻して終了。

Web Design Leaves