CODEWITHSUNDEEP
phpmysql
John
John

Reputation: 387

How do I log query execution time?

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;
    }
}

Upvotes: 2

Views: 1024

Answers (3)

ajreal
ajreal

Reputation: 47331

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);

Upvotes: 5

Gaurav Gupta
Gaurav Gupta

Reputation: 5416

I'm sure you know it already but MySQL has it's own slow query logger to log any queries that took more than a specified time. This way, you need need build this yourself.

Upvotes: 2

Niet the Dark Absol
Niet the Dark Absol

Reputation: 324790

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.

Upvotes: 3

Related Questions