New Featuer: "Measures the sql execution time"

spec/OxidSQLLoggerSpec.php

@@ -0,0 +1,89 @@
+<?php
+
+namespace spec\tm\oxid\sql\logger;
+
+use PhpSpec\Exception\Example\FailureException;
+use tm\oxid\sql\logger\OxidSQLLogger;
+use PhpSpec\ObjectBehavior;
+use Monolog;
+use function bovigo\assert\predicate\hasKey;
+use function bovigo\assert\predicate\isOfType;
+use function bovigo\assert\predicate\isSameAs;
+
+class OxidSQLLoggerSpec extends ObjectBehavior
+{
+    /**
+     * @var Monolog\Handler\TestHandler
+     */
+    private $testLogger = null;
+
+    public function let()
+    {
+        $this->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");
+    }
+}

spec/SQLQuerySpec.php

@@ -0,0 +1,65 @@
+<?php
+
+namespace spec\tm\oxid\sql\logger;
+
+use tm\oxid\sql\logger\SQLQuery;
+use PhpSpec\ObjectBehavior;
+use Prophecy\Argument;
+
+/**
+ * Class SQLQuerySpec
+ * @package spec\tm\oxid\sql\logger
+ */
+class SQLQuerySpec extends ObjectBehavior
+{
+    public function it_is_initializable()
+    {
+        $this->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();
+    }
+}

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

src/SQLQuery.php

@@ -0,0 +1,167 @@
+<?php
+/**
+ * Autor: Tobias Matthaiou <developer@tobimat.eu>
+ * 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);
+    }
+}