chore: looking into clear cache performance

momentohq · Oct 13, 2023 · a1588fe · a1588fe
1 parent 4cc5769
commit a1588fe
Show file tree

Hide file tree

Showing 6 changed files with 73 additions and 90 deletions.
diff --git a/.github/workflows/on-pull-request.yml b/.github/workflows/on-pull-request.yml
@@ -165,5 +165,5 @@ jobs:
         run: |
           vendor/bin/phpunit --bootstrap $DRUPAL_ROOT/core/tests/bootstrap.php \
             -c $MODULE_FOLDER/phpunit.xml $MODULE_FOLDER
-        env:
-          MOMENTO_CACHE_NAME_PREFIX: drupal-test-${{ matrix.php-version }}
+#        env:
+#          MOMENTO_CACHE_NAME_PREFIX: drupal-test-${{ matrix.php-version }}
diff --git a/README.md b/README.md
@@ -16,12 +16,15 @@ Add the following to your `settings.php` file:
 $settings['cache']['default'] = 'cache.backend.momento_cache';
 $settings['momento_cache']['api_token'] = '<YOUR_MOMENTO_TOKEN>';
 $settings['momento_cache']['cache_name_prefix'] = '<YOUR_CACHE_NAME_PREFIX>';
+$settings['momento_cache']['logfile'] = '<YOUR_LOG_FILE_PATH>';
 ```
 
 Replace `<YOUR_MOMENTO_TOKEN>` with the token you generated in the console. You may also use an environment variable named `MOMENTO_API_TOKEN` to pass your API token to the Momento cache backend. The module will check for the token in the settings file first and will fall back to the environment variable if a token is not found in the settings.
 
 Replace `<YOUR_CACHE_NAME_PREFIX>` with a string to be prepended to the names of the underlying caches. The prefix will prevent cache name collisions when multiple Drupal installs are backed by the same Momento account. If you don't provide a prefix in settings, the prefix "drupal-" is used.
 
+Replace `<YOUR_LOG_FILE_PATH>` with the path of a file writable by your Drupal server. This logfile is used for logging and timing requests as they are handled by the module. If undefined or empty, no logging is performed.
+
 Finally, add the following to `settings.php`:
 
 ```php

diff --git a/composer.json b/composer.json
@@ -8,6 +8,6 @@
         }
     },
     "require": {
-        "momentohq/client-sdk-php": "v1.4.0"
+        "momentohq/client-sdk-php": "dev-add-flush-cache"
     }
 }
diff --git a/src/Client/MomentoClientFactory.php b/src/Client/MomentoClientFactory.php
@@ -31,13 +31,13 @@ public function get() {
         if (!$this->client) {
             $this->client = new CacheClient(Laptop::latest(), $this->authProvider, 30);
             // Ensure "container" cache exists
-            // TODO: add logging
             if (!$this->containerCacheCreated) {
                 $createResponse = $this->client->createCache($this->cachePrefix . 'container');
                 if ($createResponse->asSuccess()) {
                     $this->containerCacheCreated = true;
                 } elseif ($createResponse->asError()) {
                     try {
+                        // TODO: unify logging interface and direct this message to the logfile.
                         $this->getLogger('momento_cache')->error(
                             "Error getting Momento client: " . $createResponse->asError()->message()
                         );

diff --git a/src/MomentoCacheBackend.php b/src/MomentoCacheBackend.php
@@ -5,7 +5,6 @@
 use Drupal\Core\Cache\CacheBackendInterface;
 use Drupal\Core\Cache\CacheTagsChecksumInterface;
 use Drupal\Core\DependencyInjection\ContainerNotInitializedException;
-use Drupal\Core\Logger\LoggerChannelTrait;
 use Drupal\Core\Site\Settings;
 use Drupal\Component\Assertion\Inspector;
 use Drupal\Component\Serialization\SerializationInterface;
@@ -14,23 +13,21 @@
 class MomentoCacheBackend implements CacheBackendInterface
 {
 
-    use LoggerChannelTrait;
-
-    private $checksumProvider;
-
     private $backendName = "momento-cache";
     private $bin;
     private $binTag;
     private $client;
+    private $checksumProvider;
     private $MAX_TTL;
     private $cacheName;
-    private $tagsCacheName;
+    private $logFile;
 
     public function __construct(
         $bin,
         $client,
         CacheTagsChecksumInterface $checksum_provider
     ) {
+        $start = hrtime(true);
         $this->MAX_TTL = intdiv(PHP_INT_MAX, 1000);
         $this->client = $client;
         $this->bin = $bin;
@@ -41,27 +38,15 @@ public function __construct(
         $cacheNamePrefix =
             array_key_exists('cache_name_prefix', $settings) ? $settings['cache_name_prefix'] : "drupal-";
         $this->cacheName = $cacheNamePrefix . $this->bin;
-    }
-
-    private function tryLogDebug($logName, $logMessage) {
-        try {
-            $this->getLogger($logName)->debug($logMessage);
-        } catch (ContainerNotInitializedException $e) {
-            // the call to getLogger() fails until the container is initialized
-        }
-    }
-
-    private function tryLogError($logName, $logMessage) {
-        try {
-            $this->getLogger($logName)->error($logMessage);
-        } catch (ContainerNotInitializedException $e) {
-            // the call to getLogger() fails until the container is initialized
-        }
+        $this->logFile =
+            array_key_exists('logfile', $settings) ? $settings['logfile'] : null;
+        error_log(
+            "Constructed MomentoCacheBackend for $bin [" . (hrtime(true) - $start) / 1e+6 . "]\n", 3, $this->logFile
+        );
     }
 
     public function get($cid, $allow_invalid = FALSE)
     {
-        $this->tryLogDebug('momento_cache', "GET with bin $this->bin, cid " . $cid);
         $cids = [$cid];
         $recs = $this->getMultiple($cids, $allow_invalid);
         return reset($recs);
@@ -90,10 +75,7 @@ private function valid($item) {
 
     public function getMultiple(&$cids, $allow_invalid = FALSE)
     {
-        $this->tryLogDebug(
-            'momento_cache',
-            "GET_MULTIPLE for bin $this->bin, cids: " . implode(', ', $cids)
-        );
+        $start = $this->startStopwatch();
         $fetched = [];
         foreach (array_chunk($cids, 100) as $cidChunk) {
             $futures = [];
@@ -107,24 +89,22 @@ public function getMultiple(&$cids, $allow_invalid = FALSE)
                     $result = unserialize($getResponse->asHit()->valueString());
                     if ($allow_invalid || $this->valid($result)) {
                         $fetched[$cid] = $result;
-                        $this->tryLogDebug(
-                            'momento_cache', "Successful GET for cid $cid in bin $this->bin"
-                        );
                     }
                 } elseif ($getResponse->asError()) {
-                    $this->tryLogError(
-                        'momento_cache',
+                    $this->log(
                         "GET error for cid $cid in bin $this->bin: " . $getResponse->asError()->message()
                     );
                 }
             }
         }
         $cids = array_diff($cids, array_keys($fetched));
+        $this->stopStopwatch($start, "GET_MULTIPLE got " . count($fetched) . " items");
         return $fetched;
     }
 
     public function set($cid, $data, $expire = CacheBackendInterface::CACHE_PERMANENT, array $tags = [])
     {
+        $start = $this->startStopwatch();
         assert(Inspector::assertAllStrings($tags));
 
         // Add tag for invalidateAll()
@@ -135,7 +115,6 @@ public function set($cid, $data, $expire = CacheBackendInterface::CACHE_PERMANEN
         $ttl = $this->MAX_TTL;
         $item = new \stdClass();
         $item->cid = $cid;
-//        $item->tags = implode(' ', $tags);
         $item->tags = $tags;
         $item->data = $data;
         $item->created = round(microtime(TRUE), 3);
@@ -152,21 +131,16 @@ public function set($cid, $data, $expire = CacheBackendInterface::CACHE_PERMANEN
         }
         $item->expire = $expire;
 
-        $this->getLogger('momento_cache')->debug("SET cid $cid in bin $this->bin with ttl $ttl");
         $setResponse = $this->client->set($this->cacheName, $cid, serialize($item), $ttl);
         if ($setResponse->asError()) {
-            $this->getLogger('momento_cache')->error("SET response error for bin $this->bin: " . $setResponse->asError()->message());
+            $this->log("SET response error for bin $this->bin: " . $setResponse->asError()->message());
         } else {
-            $this->getLogger('momento_cache')->debug(
-                "SET $this->bin:$cid with tags: " . implode(', ', $item->tags)
-            );
+            $this->stopStopwatch($start, "SET cid $cid in bin $this->bin with ttl $ttl");
         }
     }
 
     public function setMultiple(array $items)
     {
-        $this->getLogger('momento_cache')->debug("SET_MULTIPLE in bin $this->bin for " . count($items) . " items");
-
         foreach ($items as $cid => $item) {
             $this->set(
                 $cid,
@@ -179,100 +153,78 @@ public function setMultiple(array $items)
 
     public function delete($cid)
     {
-        $this->getLogger('momento_cache')->debug("DELETE cid $cid from bin $this->bin");
+        $start = $this->startStopwatch();
         $deleteResponse = $this->client->delete($this->cacheName, $cid);
         if ($deleteResponse->asError()) {
-            $this->getLogger('momento_cache')->error(
-                "DELETE response error for $cid in bin $this->bin: " . $deleteResponse->asError()->message()
-            );
+            $this->log("DELETE response error for $cid in bin $this->bin: " . $deleteResponse->asError()->message());
         } else {
-            $this->getLogger('momento_cache')->debug("DELETED $cid from bin $this->bin");
+            $this->stopStopwatch($start, "DELETE cid $cid from bin $this->bin");
         }
     }
 
     public function deleteMultiple(array $cids)
     {
-        $this->getLogger('momento_cache')->debug(
-            "DELETE_MULTIPLE in bin $this->bin for cids: " . implode(', ', $cids)
-        );
+        $start = $this->startStopwatch();
         foreach ($cids as $cid) {
             $this->delete($cid);
         }
+        $this->stopStopwatch($start, "DELETE_MULTIPLE in bin $this->bin for " . count($cids) . " items");
     }
 
     public function deleteAll()
     {
-        $this->getLogger('momento_cache')->debug("DELETE_ALL in bin $this->bin");
-        // TODO: we don't have flushCache in the PHP SDK yet
-        $deleteResponse = $this->client->deleteCache($this->cacheName);
-        if ($deleteResponse->asError()) {
-            $this->getLogger('momento_cache')->error(
-                "DELETE_CACHE response error for $this->cacheName: " . $deleteResponse->asError()->message()
-            );
-            return;
-        }
-        $createResponse = $this->client->createCache($this->cacheName);
-        if ($createResponse->asError()) {
-            $this->getLogger('momento_cache')->error(
-                "CREATE_CACHE response error for $this->cacheName: " . $createResponse->asError()->message()
+        $start = $this->startStopwatch();
+        $flushResponse = $this->client->flushCache($this->cacheName);
+        if ($flushResponse->asError()) {
+            $this->log(
+                "FLUSH_CACHE response error for $this->cacheName: " . $flushResponse->asError()->message()
             );
+        } else {
+            $this->stopStopwatch($start, "FLUSH_CACHE for $this->bin");
         }
     }
 
     public function invalidate($cid)
     {
-        $this->getLogger('momento_cache')->debug("INVALIDATE cid $cid for bin $this->bin");
+        $start = $this->startStopwatch();
         $this->invalidateMultiple([$cid]);
+        $this->stopStopwatch($start, "INVALIDATE $cid for bin $this->bin");
     }
 
     public function invalidateMultiple(array $cids)
     {
-        $this->getLogger('momento_cache')->debug("INVALIDATE_MULTIPLE for bin $this->bin");
+        $start = $this->startStopwatch();
         $requestTime = \Drupal::time()->getRequestTime();
         foreach ($cids as $cid) {
             if ($item = $this->get($cid)) {
                 $this->set($item->cid, $item->data, $requestTime - 1, $item->tags);
             }
         }
+        $this->stopStopwatch($start, "INVALIDATE_MULTIPLE for " . count($cids) . " items in $this->bin");
     }
 
     public function invalidateAll()
     {
-        $invalidateTime = round(microtime(TRUE), 3);
-        $this->getLogger('momento_cache')->debug("INVALIDATE_ALL for bin $this->bin");
+        $start = $this->startStopwatch();
         $this->invalidateTags([$this->binTag]);
-//        $setResponse = $this->client->set($this->tagsCacheName, $this->binTag, $invalidateTime, $this->MAX_TTL);
-//        if ($setResponse->asError()) {
-//            $this->getLogger('momento_cache')->error(
-//                "INVALIDATE_ALL response error for $this->tagsCacheName: " . $setResponse->asError()->message()
-//            );
-//        }
+        $this->stopStopwatch($start, "INVALIDATE_ALL for $this->bin");
     }
 
     public function invalidateTags(array $tags)
     {
+        $start = $this->startStopwatch();
         $this->checksumProvider->invalidateTags($tags);
-//        $tags = array_unique($tags);
-//        $invalidateTime = round(microtime(TRUE), 3);
-//        foreach ($tags as $tag) {
-//            $setResponse = $this->client->set($this->tagsCacheName, $tag, $invalidateTime, $this->MAX_TTL);
-//            if ($setResponse->asError()) {
-//                $this->getLogger('momento_cache')->error(
-//                    "INVALIDATE_TAGS response error $tag: " . $setResponse->asError()->message()
-//                );
-//            }
-//        }
+        $this->stopStopwatch($start, "INVALIDATE_TAGS for " . count($tags));
     }
 
     public function removeBin()
     {
-        $this->getLogger('momento_cache')->debug("REMOVE_BIN $this->bin");
+        $start = $this->startStopwatch();
         $deleteResponse = $this->client->deleteCache($this->cacheName);
         if ($deleteResponse->asError()) {
-            $this->getLogger('momento_cache')->error(
-                "DELETE_CACHE response error for bin $this->cacheName: " . $deleteResponse->asError()->message()
-            );
+            $this->log("DELETE_CACHE response error for bin $this->cacheName: " . $deleteResponse->asError()->message());
         }
+        $this->stopStopwatch($start, "REMOVE_BIN for $this->bin");
     }
 
     public function garbageCollection()
@@ -281,4 +233,25 @@ public function garbageCollection()
         // freed up and reused. So nothing needs to be deleted/cleaned up here.
     }
 
+    private function log(string $message) {
+        if ($message[-1] != "\n") {
+            $message .= "\n";
+        }
+        error_log($message, 3, $this->logFile);
+    }
+
+    private function startStopwatch() {
+        return hrtime(true);
+    }
+
+    private function stopStopwatch($startTime, $message=null) {
+        if (!$this->logFile) {
+            return;
+        }
+        $totalTimeMs = (hrtime(true) - $startTime) / 1e+6;
+        if ($message) {
+            $this->log("$message [$totalTimeMs ms]\n");
+        }
+    }
+
 }
diff --git a/src/MomentoCacheBackendFactory.php b/src/MomentoCacheBackendFactory.php
@@ -24,6 +24,7 @@ class MomentoCacheBackendFactory implements CacheFactoryInterface {
     private $cacheNamePrefix;
     private $tagsCacheId = '_momentoTags';
     private $tagsCacheName;
+    private $backends = [];
 
 
     public function __construct(
@@ -40,6 +41,10 @@ public function __construct(
 
     public function get($bin)
     {
+        if (array_key_exists($bin, $this->backends)) {
+            return $this->backends[$bin];
+        }
+
         if (
             ! $this->caches
             || ($this->cacheListTimespamp && time() - $this->cacheListTimespamp > $this->cacheListGoodForSeconds)
@@ -51,11 +56,13 @@ public function get($bin)
         if (!in_array($cacheName, $this->caches)) {
             $this->createCache($cacheName);
         }
-        return new MomentoCacheBackend(
+        $backend = new MomentoCacheBackend(
             $bin,
             $this->client,
             $this->checksumProvider
         );
+        $this->backends[$bin] = $backend;
+        return $backend;
     }
 
     private function populateCacheList() {