How do I log query execution time?

Question

I'm trying to implement slow query logging into my database class, but I'm getting weird results. It's currently logging "mostly" all queries, and it says most queries takes around 0.8 seconds to run, and I do not understand because this is on my developer machine which is not under heavy load.

Hell, I even tried running the queries in phpMyAdmin, and they are very fast there.

Did I put it at the wrong place? Or have I missed something?

class database {
    protected $_mysqli;
    protected $_debug;

    public function __construct($host, $username, $password, $database, $debug) {
        $this->_mysqli = new mysqli($host, $username, $password, $database);
        $this->_debug = (bool) $debug;
        if (mysqli_connect_errno()) {
            if ($this->_debug) {
                echo mysqli_connect_error();
                debug_print_backtrace();
            }
            return false;
        }
        return true;
    }

    public function q($query) {
        $incomingq = $query;
        if ($query = $this->_mysqli->prepare($query)) {
            if (func_num_args() > 1) {
                $x = func_get_args();
                $args = array_merge(array(func_get_arg(1)),
                    array_slice($x, 2));
                $args_ref = array();
                foreach($args as $k => &$arg) {
                    $args_ref[$k] = &$arg;
                }
                call_user_func_array(array($query, 'bind_param'), $args_ref);
            }
            // Settings
            $SLOW_LOG_TIME = 0.8; // (sec)
            $SLOW_LOG_FILE = 'php_slow.txt';
            $SLOW_LOG_START = time(); // (sec)

            $query->execute();

            // Logging
            $SLOW_LOG_END = microtime(TRUE);
             $time = $SLOW_LOG_END - $SLOW_LOG_START;
            if ($time > $SLOW_LOG_TIME)
            {
                $log = date('Y-m-d H:i:s') . "\t" . round($time, 3) . "\t" . $_SERVER['SERVER_NAME'] . $_SERVER['REQUEST_URI'] . "\t" . str_replace(array("\t" , "\n"), "", $incomingq) . "\r\n";
                $fp = fopen($SLOW_LOG_FILE, 'a+');
                fwrite($fp, $log);
                fclose($fp);
            }

            if ($query->errno) {
                if ($this->_debug) {
                    echo mysqli_error($this->_mysqli);
                    debug_print_backtrace();
                }
                return false;
            }

            if ($query->affected_rows > -1) {
            // if ($query->sqlstate == "00000") {
                return $query->affected_rows;
            }
            $params = array();
            $meta = $query->result_metadata();
            while ($field = $meta->fetch_field()) {
                $params[] = &$row[$field->name];
            }
            call_user_func_array(array($query, 'bind_result'), $params);

            $result = array();
            while ($query->fetch()) {
                $r = array();
                foreach ($row as $key => $val) {
                    $r[$key] = $val;
                }
                $result[] = $r;
            }
            $query->close();
            return $result;
        }
        else {
            if ($this->_debug) {
                echo $this->_mysqli->error;
                debug_print_backtrace();
            }
            return false;
        }
    }

    public function handle() {
        return $this->_mysqli;
    }

    public function last_insert_id()
    {
        return $this->_mysqli->insert_id;
    }
}

Answer 1

You have using wrong unit measurement for this: $SLOW_LOG_START = time();, time() is in second.

It should be consistent with $SLOW_LOG_END = microtime(TRUE);.

While, microtime(TRUE) is in microsecond.

So, change $SLOW_LOG_START = microtime(TRUE);

Answer 2

You are getting the start time to the nearest second, and the end time to the nearest microsecond.

Use microtime for $SLOW_LOG_START, otherwise your measurements could potentially be just shy of a full second off.

That should fix your problem.