Merge pull request #742 from cakephp/cache-log

Improve Cache Panel

Author: markstory

.stickler.yml

@@ -1,6 +1,6 @@
 linters:
   phpcs:
-    standard: CakePHP
+    standard: CakePHP4
     fixer: true
 
 ignore:

src/Cache/Engine/DebugEngine.php

@@ -17,7 +17,7 @@
 
 use Cake\Cache\CacheEngine;
 use Cake\Cache\CacheRegistry;
-use DebugKit\DebugTimer;
+use Psr\Log\LoggerInterface;
 
 /**
  * A spying proxy for cache engines.
@@ -40,27 +40,40 @@ class DebugEngine extends CacheEngine
      */
     protected $_engine;
 
+    /**
+     * @var \Psr\Log\LoggerInterface
+     */
+    protected $logger;
+
+    /**
+     * @var string
+     */
+    protected $name;
+
     /**
      * Hit/miss metrics.
      *
      * @var mixed
      */
-    protected $_metrics = [
+    protected $metrics = [
         'set' => 0,
         'delete' => 0,
-        'get' => 0,
-        'hit' => 0,
-        'miss' => 0,
+        'get hit' => 0,
+        'get miss' => 0,
     ];
 
     /**
      * Constructor
      *
      * @param mixed $config Config data or the proxied adapter.
+     * @param string $name The name of the proxied cache engine.
+     * @param \Psr\Log\LoggerInterface $logger Logger for collecting cache operation logs.
      */
-    public function __construct($config)
+    public function __construct($config, string $name, LoggerInterface $logger)
     {
         $this->_config = $config;
+        $this->logger = $logger;
+        $this->name = $name;
     }
 
     /**
@@ -100,7 +113,7 @@ public function engine()
      */
     public function metrics()
     {
-        return $this->_metrics;
+        return $this->metrics;
     }
 
     /**
@@ -109,20 +122,37 @@ public function metrics()
      * @param string $metric The metric to increment.
      * @return void
      */
-    protected function _track($metric)
+    protected function track($metric)
     {
-        $this->_metrics[$metric]++;
+        $this->metrics[$metric]++;
+    }
+
+    /**
+     * Log a cache operation
+     *
+     * @param string $operation The operation performed.
+     * @param float $duration The duration of the operation.
+     * @param string|null $key The cache key.
+     * @return void
+     */
+    protected function log(string $operation, float $duration, ?string $key = null): void
+    {
+        $key = $key ? " `{$key}`" : '';
+        $duration = number_format($duration, 5);
+        $this->logger->log('info', ":{$this->name}: {$operation}{$key} - {$duration}ms");
     }
 
     /**
      * {@inheritDoc}
      */
     public function set($key, $value, $ttl = null): bool
     {
-        $this->_track('set');
-        DebugTimer::start('Cache.set ' . $key);
+        $start = microtime(true);
         $result = $this->_engine->set($key, $value, $ttl);
-        DebugTimer::stop('Cache.set ' . $key);
+        $duration = microtime(true) - $start;
+
+        $this->track('set');
+        $this->log('set', $duration, $key);
 
         return $result;
     }
@@ -132,10 +162,12 @@ public function set($key, $value, $ttl = null): bool
      */
     public function setMultiple($data, $ttl = null): bool
     {
-        $this->_track('set');
-        DebugTimer::start('Cache.setMultiple');
+        $start = microtime(true);
         $result = $this->_engine->setMultiple($data);
-        DebugTimer::stop('Cache.setMultiple');
+        $duration = microtime(true) - $start;
+
+        $this->track('set');
+        $this->log('setMultiple', $duration);
 
         return $result;
     }
@@ -145,15 +177,16 @@ public function setMultiple($data, $ttl = null): bool
      */
     public function get($key, $default = null)
     {
-        $this->_track('get');
-        DebugTimer::start('Cache.get ' . $key);
+        $start = microtime(true);
         $result = $this->_engine->get($key, $default);
-        DebugTimer::stop('Cache.get ' . $key);
+        $duration = microtime(true) - $start;
         $metric = 'hit';
-        if ($result === false) {
+        if ($result === null) {
             $metric = 'miss';
         }
-        $this->_track($metric);
+
+        $this->track("get {$metric}");
+        $this->log('get', $duration, $key);
 
         return $result;
     }
@@ -163,10 +196,12 @@ public function get($key, $default = null)
      */
     public function getMultiple($keys, $default = null): iterable
     {
-        $this->_track('get');
-        DebugTimer::start('Cache.getMultiple');
+        $start = microtime(true);
         $result = $this->_engine->getMultiple($keys);
-        DebugTimer::stop('Cache.getMultiple');
+        $duration = microtime(true) - $start;
+
+        $this->track('get hit');
+        $this->log('getMultiple', $duration);
 
         return $result;
     }
@@ -176,10 +211,12 @@ public function getMultiple($keys, $default = null): iterable
      */
     public function increment(string $key, int $offset = 1)
     {
-        $this->_track('set');
-        DebugTimer::start('Cache.increment ' . $key);
+        $start = microtime(true);
         $result = $this->_engine->increment($key, $offset);
-        DebugTimer::stop('Cache.increment ' . $key);
+        $duration = microtime(true) - $start;
+
+        $this->track('set');
+        $this->log('increment', $duration, $key);
 
         return $result;
     }
@@ -189,10 +226,12 @@ public function increment(string $key, int $offset = 1)
      */
     public function decrement(string $key, int $offset = 1)
     {
-        $this->_track('set');
-        DebugTimer::start('Cache.decrement ' . $key);
+        $start = microtime(true);
         $result = $this->_engine->decrement($key, $offset);
-        DebugTimer::stop('Cache.decrement ' . $key);
+        $duration = microtime(true) - $start;
+
+        $this->track('set');
+        $this->log('decrement', $duration, $key);
 
         return $result;
     }
@@ -202,10 +241,12 @@ public function decrement(string $key, int $offset = 1)
      */
     public function delete($key): bool
     {
-        $this->_track('delete');
-        DebugTimer::start('Cache.delete ' . $key);
+        $start = microtime(true);
         $result = $this->_engine->delete($key);
-        DebugTimer::stop('Cache.delete ' . $key);
+        $duration = microtime(true) - $start;
+
+        $this->track('delete');
+        $this->log('delete', $duration, $key);
 
         return $result;
     }
@@ -215,10 +256,12 @@ public function delete($key): bool
      */
     public function deleteMultiple($data): bool
     {
-        $this->_track('delete');
-        DebugTimer::start('Cache.deleteMultiple');
+        $start = microtime(true);
         $result = $this->_engine->deleteMultiple($data);
-        DebugTimer::stop('Cache.deleteMultiple');
+        $duration = microtime(true) - $start;
+
+        $this->track('delete');
+        $this->log('deleteMultiple', $duration);
 
         return $result;
     }
@@ -228,10 +271,12 @@ public function deleteMultiple($data): bool
      */
     public function clear(): bool
     {
-        $this->_track('delete');
-        DebugTimer::start('Cache.clear');
+        $start = microtime(true);
         $result = $this->_engine->clear();
-        DebugTimer::stop('Cache.clear');
+        $duration = microtime(true) - $start;
+
+        $this->track('delete');
+        $this->log('clear', $duration);
 
         return $result;
     }
@@ -275,10 +320,12 @@ public function setConfig($key, $value = null, $merge = true)
      */
     public function clearGroup(string $group): bool
     {
-        $this->_track('delete');
-        DebugTimer::start('Cache.clearGroup ' . $group);
+        $start = microtime(true);
         $result = $this->_engine->clearGroup($group);
-        DebugTimer::stop('Cache.clearGroup ' . $group);
+        $duration = microtime(true) - $start;
+
+        $this->track('delete');
+        $this->log('clearGroup', $duration, $group);
 
         return $result;
     }

src/Panel/CachePanel.php

@@ -16,6 +16,7 @@
 namespace DebugKit\Panel;
 
 use Cake\Cache\Cache;
+use Cake\Log\Engine\ArrayLog;
 use DebugKit\Cache\Engine\DebugEngine;
 use DebugKit\DebugPanel;
 
@@ -25,11 +26,22 @@
 class CachePanel extends DebugPanel
 {
     /**
-     * The cache spy instances used.
-     *
+     * @var \Cake\Log\Engine\ArrayLog
+     */
+    protected $logger;
+
+    /**
      * @var \DebugKit\Cache\Engine\DebugEngine[]
      */
-    protected $_instances = [];
+    protected $instances = [];
+
+    /**
+     * Constructor
+     */
+    public function __construct()
+    {
+        $this->logger = new ArrayLog();
+    }
 
     /**
      * Initialize - install cache spies.
@@ -44,11 +56,11 @@ public function initialize()
                 $instance = $config['className'];
             } elseif (isset($config['className'])) {
                 Cache::drop($name);
-                $instance = new DebugEngine($config);
+                $instance = new DebugEngine($config, $name, $this->logger);
                 Cache::setConfig($name, $instance);
             }
             if (isset($instance)) {
-                $this->_instances[$name] = $instance;
+                $this->instances[$name] = $instance;
             }
         }
     }
@@ -61,12 +73,15 @@ public function initialize()
     public function data()
     {
         $metrics = [];
-        foreach ($this->_instances as $name => $instance) {
+        foreach ($this->instances as $name => $instance) {
             $metrics[$name] = $instance->metrics();
         }
+        $logs = $this->logger->read();
+        $this->logger->clear();
 
         return [
             'metrics' => $metrics,
+            'logs' => $logs,
         ];
     }
 }