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

Peter Mortensen · Accepted Answer · 2017-08-30 21:47:55Z

5

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

edited Aug 30, 2017 at 21:47

Peter Mortensen

31.4k22 gold badges110 silver badges134 bronze badges

answered Dec 12, 2011 at 13:00

ajreal

47.4k11 gold badges97 silver badges119 bronze badges

Sign up to request clarification or add additional context in comments.

1 Comment

John Over a year ago

Thanks ajreal! sometimes simple mistakes are the worst :)

Niet the Dark Absol · Accepted Answer · 2011-12-12 13:01:22Z

3

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.

answered Dec 12, 2011 at 13:01

Niet the Dark Absol

326k86 gold badges480 silver badges604 bronze badges

Comments

Gaurav Gupta · Accepted Answer · 2011-12-12 13:07:03Z

2

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.

answered Dec 12, 2011 at 13:07

Gaurav Gupta

5,4162 gold badges33 silver badges36 bronze badges

1 Comment

John Over a year ago

Thanks Gaurav, i will look into this at a later stage :)

Collectives™ on Stack Overflow

How do I log query execution time?

3 Answers 3

1 Comment

Comments

1 Comment

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

3 Answers 3

1 Comment

Comments

1 Comment

Your Answer

Sign up or log in

Post as a guest

Related