前回の続き。 SQLサーバが計算する発行コストに加えて実際の実行時間も出して、最後にトータル値も出してみた。

追記：$CONF['SQLTrace']でオン・オフするように変更

nucleus/libs/globalfunctions.php sql_query()のハック

/**
  * executes an SQL query
  */
function sql_query($query) {
    global $SQLCount;
    $SQLCount++;

    if ($GLOBALS['CONF']['SQLTrace']) { //_hack
        global $SQLQs, $SQLCs, $SQLTs;

        $chk = debug_backtrace();
        $c = 1;
        $stat = $chk[$c]['function'];
        while(! $chk[$c]['class']) { if (++$c > 9) break; if ($chk[$c]['function']) $stat = $chk[$c]['function'] .'->'. $stat; }
        if ($chk[$c]['class']) $stat = $chk[$c]['class'] .'->'. $stat;

        $bench1 = microtime();
        $res = mysql_query($query) or print("mySQL error with query $query: " . mysql_error() . '<p />');
        $bench2 = microtime();
        list($msec1, $sec1) = explode(' ', $bench1);
        list($msec2, $sec2) = explode(' ', $bench2);
        $time = ((float) $sec2 + (float) $msec2) - ((float) $sec1 + (float) $msec1);

        $res2 = mysql_query("SHOW SESSION STATUS LIKE 'Last_query_cost';"); //mysql v5 and higher
        $chk2 = mysql_fetch_assoc($res2);

        $stat .= ' ['. number_format($chk2['Value'], 2) .'/'. number_format($time, 4).'sec.' .'] ';
        $SQLQs .= $stat . trim(preg_replace('/(\r|\n|\t| )+/i',' ',$query))."\n";
        $SQLCs += (float) $chk2['Value'];
        $SQLTs += $time;
    }
    else {
        $res = mysql_query($query) or print("mySQL error with query $query: " . mysql_error() . '<p />');
    }

    return $res;
}

index.php（呼び出しファイル）の例。$CONF['SQLTrace']でトレースの有無を切り替えるようにしてみた。

$CONF = array();
$CONF['Self'] = 'index.php';
$CONF['SQLTrace'] = 1;

include('./config.php');

selector();
if ($CONF['SQLTrace']) echo "<!--\n{$SQLQs}\n[TOTAL] Count:{$SQLCount} Cost:{$SQLCs} Time:{$SQLTs}\n-->"; //sql dump

出力は以下のような感じ。

<!--
MEMBER->read [1.20/0.0014sec.] SELECT * FROM nucleus_member WHERE mname='yu'
MEMBER->isTeamMember [0.00/0.0012sec.] SELECT * FROM nucleus_team WHERE tblog=1 and tmember=7
ACTIONS->parse_otherblog->getBlogIDFromName->quickQuery [1.20/0.0011sec.] SELECT bnumber as result FROM nucleus_blog WHERE bshortname="blog"
BLOG->showUsingQuery [1,695.36/0.0030sec.] SELECT i.inumber as itemid, i.ititle as title, i.ibody as body, m.mname as author, m.mrealname as authorname, i.itime, i.imore as more, m.mnumber as authorid, m.memail as authormail, m.murl as authorurl, c.cname as category, i.icat as catid, i.iclosed as closed FROM nucleus_item as i, nucleus_member as m, nucleus_category as c WHERE i.iblog=3 and i.iauthor=m.mnumber and i.icat=c.catid and i.idraft=0 and i.itime<="2008-01-20 13:30:34" ORDER BY i.itime DESC LIMIT 0,1
NP_Markdown->_getSelectItem [0.00/0.0017sec.] SELECT * FROM nucleus_plug_markdown WHERE itemid='958'
COMMENTS->amountComments [1.20/0.0013sec.] SELECT COUNT(*) FROM nucleus_comment as c WHERE c.citem=958
（・・・中略・・・）

[TOTAL] Count:21 Cost:6816.299829 Time:0.0325856208801
-->

ちなみに class->function の部分の表示は、発行元がクラスのメソッドじゃない場合はクラス情報が出てくるまでさかのぼろうとします（class->function->function 等）。なので正しくないんだけど、表現としてはこっちのほうが直感的でわかりやすいのでこうしてます。