diff --git a/src/Db.php b/src/Db.php index 8f35d3cb7..3c69bbcb3 100644 --- a/src/Db.php +++ b/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; - public $sqlTimeTotal = 0; - public $numQueries = 0; + /** @var LoggerInterface */ + public $logger; + /** @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; - $this->numQueries++; + $context = ['time' => microtime(true) - $t]; + 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->numQueries++; + $this->logger->debug($statement, ['time' => microtime(true) - $t]); } } } diff --git a/src/Db/LogProcessor.php b/src/Db/LogProcessor.php new file mode 100644 index 000000000..eec84cf8a --- /dev/null +++ b/src/Db/LogProcessor.php @@ -0,0 +1,55 @@ +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; + } +} diff --git a/src/Db/Statement.php b/src/Db/Statement.php index a02c9733a..368745030 100644 --- a/src/Db/Statement.php +++ b/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; - $this->db->numQueries++; + $context = ['time' => microtime(true) - $t, 'input' => $input]; + 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); } } } diff --git a/src/ServiceProviders/DbServiceProvider.php b/src/ServiceProviders/DbServiceProvider.php index 309f81b58..3b4f82802 100644 --- a/src/ServiceProviders/DbServiceProvider.php +++ b/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; }; } }