Db logging

src/Db.php

@@ -28,8 +28,10 @@ namespace TorrentPier;
 use \PDO;
 use \PDOException;
 use \PDOStatement;
+use Psr\Log\LoggerInterface;
 use TorrentPier\Db\Exception;
 use TorrentPier\Db\IntegrityViolationException;
+use TorrentPier\Db\LogProcessor;
 
 class Db extends PDO
 {
@@ -39,13 +41,17 @@ class Db extends PDO
     ];
 
     public $type;
-    public $stat;
+    /** @var LoggerInterface */
-    public $sqlTimeTotal = 0;
+    public $logger;
-    public $numQueries = 0;
+    /** @var LogProcessor */
+    public $logProcessor;
+    public $isLogPrepare;
+    public $isLogExplain;
 
     public function __construct(array $config)
     {
-        $this->stat = $config['stat'] ?? true;
+        $this->isLogPrepare = $config['isLogPrepare'] ?? false;
+        $this->isLogExplain = $config['isLogExplain'] ?? true;
         $type = $this->type = $config['type'] ?? 'mysql';
         $options = $config['options'] ?? [];
         $hostname = $config['hostname'] ?? '127.0.0.1';
@@ -126,7 +132,7 @@ class Db extends PDO
                             $options = [])
     {
         try {
-            if ($this->stat) {
+            if (isset($this->logger) && $this->isLogPrepare) {
                 $t = microtime(true);
             }
             return parent::prepare($statement, $options);
@@ -134,7 +140,7 @@ class Db extends PDO
             throw new Exception($e);
         } finally {
             if (isset($t)) {
-                $this->sqlTimeTotal += microtime(true) - $t;
+                $this->logger->debug($statement, ['time' => microtime(true) - $t, 'prepare' => true]);
             }
         }
     }
@@ -148,13 +154,10 @@ class Db extends PDO
     public function query($statement, ...$args)
     {
         try {
-            if ($this->stat) {
-                $t = microtime(true);
-            }
             if (func_num_args() > 1) {
                 $input = func_get_arg(1);
                 if (is_array($input)) {
-                    $stmt = parent::prepare($statement);
+                    $stmt = $this->prepare($statement);
                     if (func_num_args() > 2) {
                         $stmt->setFetchMode(...array_slice(func_get_args(), 2));
                     }
@@ -162,6 +165,9 @@ class Db extends PDO
                     return $stmt;
                 }
             }
+            if (isset($this->logger) && strncasecmp($statement, 'EXPLAIN', 7)) {
+                $t = microtime(true);
+            }
             return parent::query($statement, ...$args);
         } catch (PDOException $e) {
             if ($e->getCode() == '23000') {
@@ -170,16 +176,30 @@ class Db extends PDO
             throw new Exception($e);
         } finally {
             if (isset($t)) {
-                $this->sqlTimeTotal += microtime(true) - $t;
+                $context = ['time' => microtime(true) - $t];
-                $this->numQueries++;
+                if ($this->isLogExplain && preg_match('#^s*SELECTs#i', $statement)) {
+                    $context['explain'] = $this->explain($statement);
+                }
+                $this->logger->debug($statement, $context);
             }
         }
     }
 
+    public function explain($statement, $input = null)
+    {
+        try {
+            $stmt = parent::prepare("EXPLAIN $statement");
+            $stmt->execute($input);
+            return $stmt->fetchAll();
+        } catch (PDOException $e) {
+            throw new Exception($e);
+        }
+    }
+
     public function exec($statement)
     {
         try {
-            if ($this->stat) {
+            if (isset($this->logger) && strncasecmp($statement, 'EXPLAIN', 7)) {
                 $t = microtime(true);
             }
             return parent::exec($statement);
@@ -190,8 +210,7 @@ class Db extends PDO
             throw new Exception($e);
         } finally {
             if (isset($t)) {
-                $this->sqlTimeTotal += microtime(true) - $t;
+                $this->logger->debug($statement, ['time' => microtime(true) - $t]);
-                $this->numQueries++;
             }
         }
     }

src/Db/LogProcessor.php

@@ -0,0 +1,55 @@
+<?php
+/**
+ * MIT License
+ *
+ * Copyright (c) 2005-2017 TorrentPier
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy
+ * of this software and associated documentation files (the "Software"), to deal
+ * in the Software without restriction, including without limitation the rights
+ * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+ * copies of the Software, and to permit persons to whom the Software is
+ * furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included in all
+ * copies or substantial portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+ * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+ * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+ * SOFTWARE.
+ */
+
+namespace TorrentPier\Db;
+
+class LogProcessor
+{
+    public $timeQueries = 0;
+    public $timePrepares = 0;
+    public $numQueries = 0;
+    public $numPrepares = 0;
+
+    public function __invoke(array $record)
+    {
+        $isPrepare = isset($record['context']['prepare']);
+        if ($isPrepare) {
+            $record['message'] = "Prepare {$record['message']}";
+            $this->numPrepares++;
+        } else {
+            $this->numQueries++;
+        }
+        if (isset($record['context']['time'])) {
+            $t = $record['context']['time'];
+            $record['message'] = '[' . sprintf('%.5f', $t) . '] ' . $record['message'];
+            if ($isPrepare) {
+                $this->timePrepares += $t;
+            } else {
+                $this->timeQueries += $t;
+            }
+        }
+        return $record;
+    }
+}

src/Db/Statement.php

@@ -38,13 +38,14 @@ class Statement extends PDOStatement
         $this->db = $db;
     }
 
-    public function execute($input_parameters = null)
+    public function execute(/** @noinspection PhpSignatureMismatchDuringInheritanceInspection */
+        $input = null)
     {
         try {
-            if ($this->db->stat) {
+            if (isset($this->db->logger) && strncasecmp($this->queryString, 'EXPLAIN', 7)) {
                 $t = microtime(true);
             }
-            return parent::execute($input_parameters);
+            return parent::execute($input);
         } catch (PDOException $e) {
             if ($e->getCode() == '23000') {
                 throw new IntegrityViolationException($e);
@@ -52,8 +53,11 @@ class Statement extends PDOStatement
             throw new Exception($e);
         } finally {
             if (isset($t)) {
-                $this->db->sqlTimeTotal += microtime(true) - $t;
+                $context = ['time' => microtime(true) - $t, 'input' => $input];
-                $this->db->numQueries++;
+                if ($this->db->isLogExplain && preg_match('#^\\s*SELECT\\s#i', $this->queryString)) {
+                    $context['explain'] = $this->db->explain($this->queryString, $input);
+                }
+                $this->db->logger->debug($this->queryString, $context);
             }
         }
     }

src/ServiceProviders/DbServiceProvider.php

@@ -25,9 +25,12 @@
 
 namespace TorrentPier\ServiceProviders;
 
+use Monolog\Logger;
+use Monolog\Handler\BrowserConsoleHandler;
 use Pimple\Container;
 use Pimple\ServiceProviderInterface;
 use TorrentPier\Db;
+use TorrentPier\Db\LogProcessor;
 
 /**
  * Class DbServiceProvider
@@ -41,7 +44,16 @@ class DbServiceProvider implements ServiceProviderInterface
     public function register(Container $container)
     {
         $container['db'] = function (Container $container) {
-            return new Db($container['config']->get('services.db'));
+            $db = new Db($container['config']->get('services.db'));
+
+            // TODO: enable only for admins with magic cookie?
+            if ($container['config']->get('debug')) {
+                $db->logProcessor = new LogProcessor();
+                $db->logger = (new Logger('db'))->pushHandler(
+                    (new BrowserConsoleHandler(Logger::DEBUG))->pushProcessor($db->logProcessor)
+                );
+            }
+            return $db;
         };
     }
 }