MDL-43882 performance: New metric, time spent by the database

This patch adds a new performance metric to the performance
info shown by MDL_PERF* vars, the time spent by the database,
it was one of the wonderful @poltawski ideas. To be more specific
the value displayed is the sum of the time elapsed between query_start()
and query_end().

lib/dml/moodle_database.php

@@ -91,6 +91,8 @@ abstract class moodle_database {
     protected $reads = 0;
     /** @var int The database writes (performance counter).*/
     protected $writes = 0;
+    /** @var float Time queries took to finish, seconds with microseconds.*/
+    protected $queriestime = 0;
 
     /** @var int Debug level. */
     protected $debug  = 0;
@@ -441,7 +443,10 @@ abstract class moodle_database {
         $logerrors = !empty($this->dboptions['logerrors']);
         $iserror   = ($error !== false);
 
-        $time = microtime(true) - $this->last_time;
+        $time = $this->query_time();
+
+        // Will be shown or not depending on MDL_PERF values rather than in dboptions['log*].
+        $this->queriestime = $this->queriestime + $time;
 
         if ($logall or ($logslow and ($logslow < ($time+0.00001))) or ($iserror and $logerrors)) {
             $this->loggingquery = true;
@@ -471,6 +476,14 @@ abstract class moodle_database {
         }
     }
 
+    /**
+     * Returns the time elapsed since the query started.
+     * @return float Seconds with microseconds
+     */
+    protected function query_time() {
+        return microtime(true) - $this->last_time;
+    }
+
     /**
      * Returns database server info array
      * @return array Array containing 'description' and 'version' at least.
@@ -525,7 +538,7 @@ abstract class moodle_database {
         if (!$this->get_debug()) {
             return;
         }
-        $time = microtime(true) - $this->last_time;
+        $time = $this->query_time();
         $message = "Query took: {$time} seconds.\n";
         if (CLI_SCRIPT) {
             echo $message;
@@ -2349,4 +2362,12 @@ abstract class moodle_database {
     public function perf_get_queries() {
         return $this->writes + $this->reads;
     }
+
+    /**
+     * Time waiting for the database engine to finish running all queries.
+     * @return float Number of seconds with microseconds
+     */
+    public function perf_get_queries_time() {
+        return $this->queriestime;
+    }
 }

lib/moodlelib.php

@@ -10700,6 +10700,10 @@ function get_performance_info() {
     $info['html'] .= '<span class="dbqueries">DB reads/writes: '.$info['dbqueries'].'</span> ';
     $info['txt'] .= 'db reads/writes: '.$info['dbqueries'].' ';
 
+    $info['dbtime'] = round($DB->perf_get_queries_time(), 5);
+    $info['html'] .= '<span class="dbtime">DB queries time: '.$info['dbtime'].' secs</span> ';
+    $info['txt'] .= 'db queries time: ' . $info['dbtime'] . 's ';
+
     if (function_exists('posix_times')) {
         $ptimes = posix_times();
         if (is_array($ptimes)) {