PHP(WordPress)、関数の処理時間を知りたい

wordpressで一体この関数の実行にどのくらい時間がかかっているのか知りたいなと言うときはfunctions.phpに時間を測定する用の関数（クラス）を追記して、時間を測りたい場所で実行するようにしておくと便利です。

functionsの下準備

以下のような関数をfunctionsに追記します。デバックも有効にしておいてください。

//デバック用関数
if(!function_exists('_log')){
  function _log($message) {
    if (WP_DEBUG === true) {
      if (is_array($message) || is_object($message)) {
        error_log(print_r($message, true));
      } else {
        error_log($message);
      }
    }
  }
}


class Execution_Time {

  private $start_mt;
  private $stop_mt;

  private $name;

  static $totaltime = array();
  // インスタンス生成時に呼ばれる
  public function __construct($name) {
    $this->name = $name;
    // 計測開始時のタイムスタンプを整数と少数に分けて配列にブチ込む
    $this->start_mt = explode(' ', microtime());

    // ループで呼ばれるメソッドの合計処理時間を初期化
    if(!array_key_exists($this->name, self::$totaltime)){
      self::$totaltime[$this->name] = 0;
    }
  }

  // インスタンス破棄時に呼ばれる
  public function __destruct() {
      // 計測終了時のタイムスタンプを整数と少数に分けて配列にブチ込む
      $this->stop_mt = explode(' ', microtime());
      // 整数同士を計算
      $diff_sec = (float) $this->stop_mt[1] - (float) $this->start_mt[1];
      // 少数同士を計算
      $diff_usec = (float) $this->stop_mt[0] - (float) $this->start_mt[0];
      // 整形
      $execution_time = sprintf('%.6f', $diff_sec + $diff_usec);
      // 最後に0がついていたら削除
      $execution_time = preg_replace('/0*$/', '', $execution_time);
      // 計測時間を出力
      _log($this->name . "： " . $execution_time . 'sec');
      // ループで呼ばれるメソッドの合計処理時間を加算
      self::$totaltime[$this->name] += $execution_time;
  }
}


$et = null;
function start_measure($name) {
  global $et;
  // インスタンスを生成する
  $et = new Execution_Time($name);
}

function stop_measure() {
  global $et;
  // インスタンスを破棄する
  $et = null;
}

// ループで呼ばれるメソッドの合計処理時間を表示
function print_total_times(){
  foreach(Execution_Time::$totaltime as $key => $value){
    _log($key . "： " . $value . 'sec');
  }
  Execution_Time::$totaltime = array();
}

使い方

関数の処理時間を測定する

ある関数（今回はhoge()）の処理時間を測定したいときは、先程追記したstart_measureとstop_measureで関数を挟んでやります。 start_measureには、適当な文字列を渡してあげましょう

start_measure("hoge関数の実行時間");
hoge();
stop_measure();

するとdebug.logに実行時間が出力されます。

[xx-Jan-20xx xx:xx:xx UTC] hoge関数の実行時間： 1.394643sec

測りたい関数がループの中にいる時

例えばこんな状況で

for($i = 0; $i < 10; $i++){
    hoge();
    hogehoge();
    huga();
}

hoge関数の実行時間が知りたいときは、同様に

for($i = 0; $i < 10; $i++){
    start_measure("ループ内のhoge関数の実行時間");
    hoge();
    stop_measure();
    hogehoge();
    huga();
}

とすれば良いのですがこれだと十個も出力が出てしまします

[xx-Jan-20xx xx:xx:xx UTC] ループ内のhoge関数の実行時間： 1.394643sec
[xx-Jan-20xx xx:xx:xx UTC] ループ内のhoge関数の実行時間： 1.394643sec
・
・
・

これだと流石にうっとおしいので、 functions関数内に追記したExecution_Timeクラスのデストラクタに書いてあるログの出力を一旦コメントアウトして

// 計測時間を出力
//     _log($this->name . "： " . $execution_time . 'sec');

合計時間を出力するように定義したprint_total_times()関数をループの外で実行します

for($i = 0; $i < 10; $i++){
    start_measure("ループ内のhoge関数の実行時間");
    hoge();
    stop_measure();
    hogehoge();
    huga();
}
print_total_times() //New!!

するとhoge()を10回実行した処理時間の合計が出力されます

[xx-Jan-20xx xx:xx:xx UTC] ループ内のhoge関数の実行時間： 13.94643sec