From 9c3206ee73264a3cc94f9670f24aa8217d92741b Mon Sep 17 00:00:00 2001 From: Tobias Matthaiou Date: Tue, 1 Oct 2019 12:17:23 +0200 Subject: [PATCH] New Featuer: "Measures the sql execution time" --- spec/OxidSQLLoggerSpec.php | 89 ++++++++++++++++++++ spec/SQLQuerySpec.php | 65 +++++++++++++++ src/OxidSQLLogger.php | 26 +++++- src/SQLQuery.php | 167 +++++++++++++++++++++++++++++++++++++ 4 files changed, 346 insertions(+), 1 deletion(-) create mode 100644 spec/OxidSQLLoggerSpec.php create mode 100644 spec/SQLQuerySpec.php create mode 100644 src/SQLQuery.php diff --git a/spec/OxidSQLLoggerSpec.php b/spec/OxidSQLLoggerSpec.php new file mode 100644 index 0000000..1e8834d --- /dev/null +++ b/spec/OxidSQLLoggerSpec.php @@ -0,0 +1,89 @@ +testLogger = new Monolog\Handler\TestHandler(); + Monolog\Registry::addLogger( + new Monolog\Logger('sql', [$this->testLogger]), + 'sql', + true + ); + } + + public function it_is_initializable() + { + $this->shouldHaveType(OxidSQLLogger::class); + } + + /** + * @throws FailureException + */ + public function it_should_log_the_sql_normally() + { + $this->startQuery('SELECT 1', ['param1'], ['master']); + for ($i = 0; $i <= 1000; $i++) @get_declared_classes(); + $this->stopQuery(); + + $this->assertExpectLog(); + $this->assertMatchMessage('/\[\d+ms\] SELECT 1/'); + + $this->assertContext('params', isSameAs(['param1'])); + $this->assertContext('types', isSameAs(['master'])); + $this->assertContext('time', isOfType('float')); + + } + + /** + * @throws FailureException + */ + public function it_should_log_without_time_specification() + { + $this->startQuery('SELECT 1'); + $this->startQuery('SELECT 2'); + + $this->assertExpectLog(); + $this->assertMatchMessage('/\[Statement canceled\] SELECT 1/'); + $this->assertContext('time', isSameAs('Statement canceled')); + + } + + private function assertExpectLog() + { + if (!$this->testLogger->hasRecords(Monolog\Logger::DEBUG)) { + throw new FailureException("No log entry was made"); + } + } + + private function assertMatchMessage($regex) + { + if (!$this->testLogger->hasRecordThatMatches($regex, Monolog\Logger::DEBUG)) { + $message = $this->testLogger->getRecords()[0]['message']; + throw new FailureException("Expect message '{$regex}' got '{$message}'"); + }; + } + + private function assertContext($param, $actual) + { + $record = $this->testLogger->getRecords()[0]; + + \bovigo\assert\assert($record['context'], hasKey($param), "Context '{$param}' not found"); + \bovigo\assert\assert($record['context'][$param], $actual, "Context '{$param} is not same"); + } +} diff --git a/spec/SQLQuerySpec.php b/spec/SQLQuerySpec.php new file mode 100644 index 0000000..5ef7009 --- /dev/null +++ b/spec/SQLQuerySpec.php @@ -0,0 +1,65 @@ +shouldHaveType(SQLQuery::class); + } + + public function it_hat_sql_setter_getter() + { + $this->setSQL('SELECT NOW()')->shouldHaveType(SQLQuery::class); + $this->getSQL()->shouldBe('SELECT NOW()'); + } + + public function it_hat_params_setter_getter() + { + $this->setParams(['param1', 'param2'])->shouldHaveType(SQLQuery::class); + $this->getParams()->shouldBe(['param1', 'param2']); + } + + public function it_hat_type_setter_getter() + { + $this->setTypes(['type1'])->shouldHaveType(SQLQuery::class); + $this->getTypes()->shouldBe(['type1']); + } + + public function it_should_indicate_an_aborted_time() + { + $this->setSql('SELECT 1'); + $this->setCanceled()->shouldHaveType(SQLQuery::class); + $this->getElapsedTime()->shouldBe('Statement canceled'); + } + + public function it_should_display_with_a_readable_time() + { + $this->setSql('SELECT 1'); + sleep(1); + $this->getReadableElapsedTime()->shouldMatch('/^1\.\d\d\ds/'); + } + + public function it_should_display_with_a_readable_time_in_ms() + { + $this->setSql('SELECT 1'); + for ($i = 0; $i <= 1000; $i++) @get_declared_classes(); + $this->getReadableElapsedTime()->shouldMatch('/^\d{1,3}ms/'); + } + + public function it_should_display_a_time_in_float() + { + $this->setSql('SELECT 1'); + for ($i = 0; $i <= 1000; $i++) @get_declared_classes(); + $this->getElapsedTime()->shouldBeFloat(); + } +} diff --git a/src/OxidSQLLogger.php b/src/OxidSQLLogger.php index 7fbe8be..0068728 100644 --- a/src/OxidSQLLogger.php +++ b/src/OxidSQLLogger.php @@ -16,6 +16,11 @@ use Monolog; */ class OxidSQLLogger implements SQLLogger { + /** + * @var SQLQuery + */ + private $SQLQuery = null; + /** * @inheritDoc */ @@ -31,7 +36,14 @@ class OxidSQLLogger implements SQLLogger */ public function startQuery($sql, array $params = null, array $types = null) { - Monolog\Registry::sql()->addDebug($sql, ['params' => $params, 'types' => $types]); + if ($this->SQLQuery) { + $this->SQLQuery->setCanceled(); + $this->stopQuery(); + } + + $this->SQLQuery = (new SQLQuery()) ->setSql($sql) + ->setParams($params) + ->setTypes($types); } /** @@ -39,5 +51,17 @@ class OxidSQLLogger implements SQLLogger */ public function stopQuery() { + if ($this->SQLQuery) { + Monolog\Registry::sql()->addDebug( + '['.$this->SQLQuery->getReadableElapsedTime().'] ' . $this->SQLQuery->getSql(), + [ + 'params' => $this->SQLQuery->getParams(), + 'time' => $this->SQLQuery->getElapsedTime(), + 'types' => $this->SQLQuery->getTypes(), + ] + ); + } + + $this->SQLQuery = null; } } diff --git a/src/SQLQuery.php b/src/SQLQuery.php new file mode 100644 index 0000000..9295655 --- /dev/null +++ b/src/SQLQuery.php @@ -0,0 +1,167 @@ + + * Date: 2019-08-20 + * Time: 21:56 + */ + +namespace tm\oxid\sql\logger; + +/** + * Class SQLQuery + * @package tm\oxid\sql\logger + */ +class SQLQuery +{ + /** + * @var float|null + */ + private $start_time = null; + + /** + * @var float|null + */ + private $stop_time = null; + + /** + * @var string + */ + private $sql = ''; + + /** + * @var null + */ + private $params = null; + + /** + * @var null + */ + private $types = null; + + /** + * @inheritDoc + */ + public function __construct() + { + $this->start_time = microtime(true); + } + + /** + * @return string + */ + public function getSql() + { + return $this->sql; + } + + /** + * @param string $sql + * @return SQLQuery + */ + public function setSql($sql) + { + $this->sql = $sql; + return $this; + } + + /** + * @return null + */ + public function getParams() + { + return $this->params; + } + + /** + * @param null $params + * @return SQLQuery + */ + public function setParams($params) + { + $this->params = $params; + return $this; + } + + /** + * @return null + */ + public function getTypes() + { + return $this->types; + } + + /** + * @param null $types + * @return SQLQuery + */ + public function setTypes($types) + { + $this->types = $types; + return $this; + } + + /** + * Statement was cancelled prematurely, an error was thrown. + * + * @return $this + */ + public function setCanceled() + { + $this->start_time = null; + return $this; + } + + /** + * Returns elapsed time + * @return float|string + */ + public function getElapsedTime() + { + if ($this->start_time === null) { + return 'Statement canceled'; + } + + if ($this->stop_time === null) { + $end_time = microtime(true); + $this->stop_time = $end_time - $this->start_time; + } + + return (float)$this->stop_time; + } + + /** + * Returns a human readable elapsed time + * + * @return string + */ + public function getReadableElapsedTime() + { + return $this->readableElapsedTime($this->getElapsedTime()); + } + + /** + * Returns a human readable elapsed time + * + * @param float $microtime + * @param string $format The format to display (printf format) + * @return string + */ + private function readableElapsedTime($microtime, $format = '%.3f%s', $round = 3) + { + if (is_string($microtime)) { + return $microtime; + } + + if ($microtime >= 1) { + $unit = 's'; + $time = round($microtime, $round); + } else { + $unit = 'ms'; + $time = round($microtime*1000); + + $format = preg_replace('/(%.[\d]+f)/', '%d', $format); + } + + return sprintf($format, $time, $unit); + } +}