[PHP] PHPの動作が遅い原因を調査したら function 多重呼び出しが悪さをしていた件

こんにちは。たきもとです。
今回はデバッグ中に出会った動作速度低下の原因について紹介します。
 
 
作ったツールの動作が遅い！
と思うことがしばしばあると思います。
そこでGoogle先生に

PHP 遅い　原因

なんて訊いてみたりして。
きっと先生は　知らんがな！　と仰るかのような検索結果を沢山提示して下さるでしょう。
結果的には私が的外れなコーディングをしていたのですが。
私のような若輩者は自分の書いたコードがイケてないなんて思わないんです。
何しろ初心者すぎるので。
 
 
今回の件ですが、もしかしたら専門用語があるのかもしれません。
私はその用語を知らないのでここでは
-function多重呼び出し
と呼びますね。

内容ですが、
-function 内でさらに function を呼び出したら思った以上に処理に時間が掛かった
という件です。

function とは

2回以上似たような記述を書きたくない！ と思った時に使う関数

こう思っていれば概ね合っています。

ちょっと値が違うだけで似たような記述を数回書いてしまう。
誰もが一度は通る道だと思うのですが。

これをもっと簡単に記述するために自分で作る関数が
-function
です。
 
 

基本的な使い方

-関数名: お好きな名前で。勿論アルファベット。
-引数: “処理” 内で使いたい値があればココに。
-処理: 何でもok. 自分がしたい処理。
-return: ここで指定した値をfunctionの結果として返す。
-変数: 結果として返したい値の名前。
 
 
試しに使ってみるとこうなります。

<?php

//変数定義
$value = 100;


//関数定義
function multiplication($hikisu){
    echo '引数を2倍します'."<br>";
    $result = $hikisu * 2;
    echo '計算を終了しました'."<br>";

    return $result;
}


//実行
$kekka = multiplication($value);
echo 'function($value)を実行した結果は'.$kekka.'です';

 
 
実行結果

引数を2倍します
計算を終了しました
function($value)を実行した結果は200です

 
 
multiplicationという関数名を付けて実行しています。
結果を表示するために一旦 kekka という変数に値を格納し、それをechoで表示しています。
 
 

デバッグのためにデバッグ用の関数を用意

私はデバッグ用にいくつか関数を作って利用しています。
今回は実行時間を知りたいので、こんな関数を定義しておきます。
これは後で使いますので。

function debug_time($txt_title, $var_start){
        echo '<pre>';
        echo '//--- debug ---//'."<br>";
        echo '// '.$txt_title."<br>";

        $end_time=microtime(true);

        $cal_time = $end_time - $var_start;

        echo "開始時間： ".date('Y-m-d H:i:s',(int)$var_start)."<br>";
        echo "終了時間： ".date('Y-m-d H:i:s',(int)$end_time)."<br>";
        echo "処理時間：".sprintf('%0.1f',$cal_time).'[s]'."<br>";
        echo '</pre>';
    }

関数名: debug_time
引数: txt_title, var_start
処理: 解説は次の通り。
return, 変数: 今回は指定していません。
 
 
ここでの処理ですが、やっていることは
-開始時間
-終了時間
の差分をとっているだけです。
時間の取得は microtime で行っています。

date はタイムスタンプを取得しているだけです。
(int)$var_start という具合に型変換をしているのは,date関数内の引数に文字列を使えないからです。

echo がたくさんあるのは、結果を表示するときに見やすくするため。

txt_title を指定したのは,どの処理の結果なのかをテキストで表示したいから。

sprintf は結果の桁数を指定するため。
 
 

現象

まずは現象を。

今回は話を単純にするために
-割り算
-足し算
を例にします。

sleepを 2秒 抱えた関数を2つ実行するだけなので
合計処理時間 = 4秒
が期待する動作です。

でも、結果は6秒でした。

実行コードと結果はこちら。
 
 

<?php

//定数定義
define('WAIT_2SEC', 2);//wait時間
$smplA        = 10;


//実行
$timeStart = microtime(true);

$calResultA = divider(WAIT_2SEC, $smplA);// 10/2 = 5
$calResultB = adder  (WAIT_2SEC, $calResultA);// 5/2 + 100 = 102.5

//debug
echo '$calResultA='.$calResultA."<br>";
echo '$calResultB='.$calResultB."<br>";

//debug
debug_time('calRsult A,B の結果を得るまでにかかった時間', $timeStart);



/**
* function定義
*
* divider   | $waitTimeだけsleep. 引数を2で割る
* adder     | $waitTimeだけsleep. dividerの呼出し後,引数に100を足す
* debug_time| 実行時間を表示するための関数
**/
function divider($waitTime, $constA){
    sleep($waitTime);

    $result_1 = $constA /2;

    return $result_1;
}


function adder($waitTime, $constB){
    sleep($waitTime);

    //dividerの呼び出し
    $cnst_add = divider($waitTime, $constB);

    //実行
    $result  = 100 + $cnst_add;

    return $result;
}


function debug_time($txt_title, $var_start){
        echo '<pre>';
        echo '//--- debug ---//'."<br>";
        echo '// '.$txt_title."<br>";

        $end_time=microtime(true);

        $cal_time = $end_time - $var_start;

        echo "開始時間： ".date('Y-m-d H:i:s',(int)$var_start)."<br>";
        echo "終了時間： ".date('Y-m-d H:i:s',(int)$end_time)."<br>";
        echo "処理時間：".sprintf('%0.1f',$cal_time).'[s]'."<br>";
        echo '</pre>';
}

実行結果

$calResultA=5
$calResultB=102.5
//--- debug ---//
// calRsult A,B の結果を得るまでにかかった時間
開始時間： 2016-03-13 01:00:05
終了時間： 2016-03-13 01:00:11
処理時間：6.0[s]

原因は function多重呼び出し

上のコードの 43, 44 行目が原因です。
↓ここでは抜粋したので行番号がずれていますが。

function adder($waitTime, $constB){
    sleep($waitTime);

    //dividerの呼び出し
    $cnst_add = divider($waitTime, $constB);

    //実行
    $result  = 100 + $cnst_add;

    return $result;
}

function adder 内で divider が呼び出されています。
ここで、 divider内のsleepが発動してしまった、というオチです。

これを考慮すると実行時間は
divier 2回分: 2sec x2 = 4sec
adder 1回分: 2sec x1 = 2sec
合計: 6sec

となります。
 
 

改善策

今回はどうすれば良かったかについて。
期待した処理時間は 4秒 でした。
一番簡単な修正方法はadder内を次の様に書き直します。

function adder($waitTime, $constB){
    sleep($waitTime);

    //dividerの呼び出し
    // $cnst_add = divider($waitTime, $constB);

    $cnst_add = $constB / 2;//素直に計算するように書き直す

    //実行
    $result  = 100 + $cnst_add;

    return $result;
}

実行結果

$calResultA=5
$calResultB=102.5
//--- debug ---//
// calRsult A,B の結果を得るまでにかかった時間
開始時間： 2016-03-13 01:10:45
終了時間： 2016-03-13 01:10:49
処理時間：4.0[s]

この結果は期待するものと一致します。
 
 

まとめ

これは最近やってしまった事例。
スクレイピングツール作成時にclass内メソッドを呼び出した時に発覚した。
実際は呼び出し条件がやや異なるのですが、本質的な原因は今回のように余分な呼び出しを行っていたことです。
 
 
-冗長なコーディングをしてませんか？

という視点を持つのは大切だなぁと実感した失敗でした。
 
 
PHPを走らせてあまりにも結果が遅い場合は気になる動作時間を調べてみましょう。
もしかしたら私のようにfunctionの多重呼び出しをしているかもしれないですよ。

今回は以上です。