From bf6357342d438f879e41c6889193b5ba3c1497f6 Mon Sep 17 00:00:00 2001 From: Pete Gautier Date: Fri, 13 Oct 2023 10:04:06 -0700 Subject: [PATCH] chore: looking into clear cache performance --- .github/workflows/on-pull-request.yml | 4 +- README.md | 5 +- composer.json | 2 +- src/Client/MomentoClientFactory.php | 2 +- src/MomentoCacheBackend.php | 185 +++++++++++--------------- src/MomentoCacheBackendFactory.php | 9 +- 6 files changed, 95 insertions(+), 112 deletions(-) diff --git a/.github/workflows/on-pull-request.yml b/.github/workflows/on-pull-request.yml index 927d98e..0ea5856 100644 --- 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 index d6306cb..fa692e1 100644 --- 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'] = ''; $settings['momento_cache']['cache_name_prefix'] = ''; +$settings['momento_cache']['logfile'] = ''; ``` Replace `` 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 `` 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 `` 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 @@ -47,7 +50,7 @@ $settings['bootstrap_container_definition'] = [ ], 'cache.container' => [ 'class' => 'Drupal\momento_cache\MomentoCacheBackend', - 'arguments' => ['container', '@momento_cache.backend.cache.container', '@cache_tags_provider.container', 'momento_cache.timestamp.invalidator.bin'] + 'arguments' => ['container', '@momento_cache.backend.cache.container', '@cache_tags_provider.container'] ] ] ]; diff --git a/composer.json b/composer.json index 2a978d7..c0873ab 100644 --- 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 index 7de7707..991314b 100644 --- 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 index 00b53de..6ba6be0 100644 --- 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,59 +38,20 @@ 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; } 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); } - private function valid($item) { - // TODO: see https://www.drupal.org/project/memcache/issues/3302086 for discussion of why I'm using - // $_SERVER instead of Drupal::time() and potential suggestions on how to inject the latter for use here. - try { - $requestTime = \Drupal::time()->getRequestTime(); - } catch (ContainerNotInitializedException $e) { - $requestTime = $_SERVER['REQUEST_TIME']; - } - $isValid = TRUE; - if ($item->expire != CacheBackendInterface::CACHE_PERMANENT && $item->expire < $requestTime) { - $item->valid = FALSE; - return FALSE; - } - - if (!$this->checksumProvider->isValid($item->checksum, $item->tags)) { - $isValid = FALSE; - } - $item->valid = $isValid; - return $isValid; - } - 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 +65,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 +91,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 +107,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 +129,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 +209,49 @@ public function garbageCollection() // freed up and reused. So nothing needs to be deleted/cleaned up here. } + private function valid($item) { + // TODO: see https://www.drupal.org/project/memcache/issues/3302086 for discussion of why I'm using + // $_SERVER instead of Drupal::time() and potential suggestions on how to inject the latter for use here. + try { + $requestTime = \Drupal::time()->getRequestTime(); + } catch (ContainerNotInitializedException $e) { + $requestTime = $_SERVER['REQUEST_TIME']; + } + $isValid = TRUE; + if ($item->expire != CacheBackendInterface::CACHE_PERMANENT && $item->expire < $requestTime) { + $item->valid = FALSE; + return FALSE; + } + + if (!$this->checksumProvider->isValid($item->checksum, $item->tags)) { + $isValid = FALSE; + } + $item->valid = $isValid; + return $isValid; + } + + private function log(string $message) { + if (!$this->logFile) { + return; + } + 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 index b1a09ad..d76e1da 100644 --- 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() {