クエリのログを取ってみる - Nucleusだとか

もうひとつ、チューニング系の話題。

hsurさんのsql_query()を細工して、クエリをトラッキングする話と、 しづきさんの関数の呼び出し元を取得する話を組み合わせて、 どこで発行されたクエリか、という情報もダンプしてみます。ついでに[発行コスト]¹の表示も。

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

/**
  * executes an SQL query
  */
function sql_query($query) {
    global $SQLCount;
    $SQLCount++;
    $res = mysql_query($query) or print("mySQL error with query $query: " . mysql_error() . '<p />');

    global $SQLQs; //_hack(begin)
    $chk = debug_backtrace();
    $res2 = mysql_query("SHOW SESSION STATUS LIKE 'Last_query_cost';"); //mysql v5 and higher
    $chk2 = mysql_fetch_assoc($res2);
    $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;
    $SQLQs .= $stat .'['. $chk2['Value'] .']: '
        . trim(preg_replace('/(\r|\n|\t| )+/i',' ',$query))."\n"; //_hack(end)

    return $res;
}

index.php の selector() の後に1行追加

if ($SQLQs) echo "<!--\n{$SQLQs}-->"; //sql dump

これで、HTMLソースの最後にこんな感じの出力が。 出力コストが多少かかるので、調べた後は sql_query() を元に戻すほうがいいです。

<!--
MEMBER->read[1.199000]: SELECT * FROM nucleus_member WHERE mname='yu'
ITEM->exists->getBlogIDFromItemID->quickQuery[0.000000]: SELECT iblog as result FROM nucleus_item WHERE inumber=283
ITEM->exists[0.000000]: select * FROM nucleus_item WHERE inumber=283 and itime<="2008-01-20 02:34:13" and idraft=0
selector[0.000000]: SELECT itime, iblog, icat FROM nucleus_item WHERE inumber=283
selector[335.360328]: SELECT inumber, ititle FROM nucleus_item WHERE itime<"2007-03-05 22:27:45" and idraft=0 and iblog=2 ORDER BY itime DESC LIMIT 1
selector[26.209000]: SELECT inumber, ititle FROM nucleus_item WHERE itime>"2007-03-05 22:27:45" and itime <= "2008-01-20 02:34:13" and idraft=0 and iblog=2 ORDER BY itime ASC LIMIT 1
MEMBER->isTeamMember[0.000000]: SELECT * FROM nucleus_team WHERE tblog=2 and tmember=1
（略）
-->