先日、いつものようにプラグイン更新が通知されていたので、NextGEN Gallery(1.9.10⇒2.0.27)を含めいくつか更新したのですが、その後サイトが遅くなる事象が発生。結論から先に言うとNextGENが犯人だったのですが、当初はなにが悪いのかさっぱりわからず、結局調査するハメに。

■事象

ここ1週間、遅くとも表示に3秒以内で返っていたサイトが急に倍の6秒以上かかるようになった。

■調査

1. まずはレスポンス（応答）で待たされているので、レンタルサーバの負荷ではないかと収容先に問い合わせましたが問題ないと。むしろ「CPU使用時間が長い」と指摘される始末。これには思い当たる節があるので納得。決して「CPU使用率が高い」わけではないです。「CPU使用時間が長い」原因は管理画面でDNS逆引きをしている箇所があり、ここで時間がかかっているんですね。サイトが遅い原因はここではないです。

2. 次にターミナルでログインし、自分のプロセスをtopしながら、サイトにアクセスすると「php-cgi-mysqlx.x」プロセスが数秒かかっているのが目視でわかりました。ということはデータベース。データベースの負荷が高いか、自サイトのSQLに時間がかかっているかになりますね。こうなると普通は自サイトを疑いますよね。

3. ってことでSQLをデバッグすることにしました。お約束？の以下の２つを追加。
   1. wp-config.php

      define ('SAVEQUERIES', true);
      

   2. footer.php

      <?php
      if (current_user_can('administrator')){
          global $wpdb;
          echo "<hr><br><pre>";
          print_r($wpdb->queries);
          echo "</pre>";
      }
      ?>
      

   おー、出ますねー。凄い量。トップの１ページだけで300以上もSQLが発行されてます。ありえんWP。まあSQLを診るとゴミみたいなSQLが山ほど発行されてます。SQLをチマチマ発行するより、一度のSQLである程度レコードをまとめて取得してphp側でゴニョゴニョするほうがほよっぽど速いですから。SQLをオブジェクトと同じ感覚でプログラミングしてるようにしか見えないですね。
   [cc lang=”dos”] Array
   (
   [0] => Array
   (
   [0] => SELECT option_value FROM options WHERE option_name = ‘rewrite_rules’ LIMIT 1
   [1] => 0.0101861953735
   [2] => require(‘wp-blog-header.php’), wp, WP->main, WP->parse_request, WP_Rewrite->wp_rewrite_rules, get_option
   )

   [1] => Array
   (
   [0] => SELECT SQL_CALC_FOUND_ROWS posts.ID FROM posts WHERE 1=1 AND posts.post_type = ‘post’ AND (posts.post_status = ‘publish’ OR posts.post_status = ‘private’) ORDER BY posts.post_date DESC LIMIT 0, 5
   [1] => 0.00300097465515
   [2] => require(‘wp-blog-header.php’), wp, WP->main, WP->query_posts, WP_Query->query, WP_Query->get_posts
   )
   ……………….
   [332] => Array
   ……………….
   [/cc]

   ３回ほどアクセスしSQLデータを収集。このArrayの「[1] => 」のSQL実行時間(duration)をgrepしExcelに張り付け、グラフ化。
   

   すると以下の特定のテーブルのSQLが処理に時間がかかっているのがわかりました。これ、まさしくNextGenのテーブルですよね。
   [cc lang=”dos”] SELECT image_slug FROM ngg_pictures WHERE image_slug = ‘xxxxxxxxx’ AND NOT pid = 0 LIMIT 1
   [/cc]

   ってことで、やっとここでNextGENのプラグインをアップデートしたのを思い出しました。1.9.10⇒2.0.27だったのですが、なんで今頃アップデート通知されたん！？。
   １回目と２、３回目でSQL実行数が違うのはget_option()などのキャッシュが効いたものと思われます。