8000 feature #30844 [Cache] add logs on early-recomputation and locking (n… · symfony/symfony@78afdd1 · GitHub
[go: up one dir, main page]
Skip to content

Commit 78afdd1

Browse files
fabpotfabpot
committed
feature #30844 [Cache] add logs on early-recomputation and locking (nicolas-grekas)
This PR was merged into the 4.3-dev branch. Discussion ---------- [Cache] add logs on early-recomputation and locking | Q | A | ------------- | --- | Branch? | master | Bug fix? | no | New feature? | yes | BC breaks? | no | Deprecations? | no | Tests pass? | yes | Fixed tickets | - | License | MIT | Doc PR | - Commits ------- 847a9bb [Cache] add logs on early-recomputation and locking
2 parents 4835136 + 847a9bb commit 78afdd1

File tree

3 files changed

+17
-6
lines changed

3 files changed

+17
-6
lines changed

‎src/Symfony/Component/Cache/LockRegistry.php

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111

1212
namespace Symfony\Component\Cache;
1313

14+
use Psr\Log\LoggerInterface;
1415
use Symfony\Contracts\Cache\CacheInterface;
1516
use Symfony\Contracts\Cache\ItemInterface;
1617

@@ -75,7 +76,7 @@ public static function setFiles(array $files): array
7576
return $previousFiles;
7677
}
7778

78-
public static function compute(callable $callback, ItemInterface $item, bool &$save, CacheInterface $pool, \Closure $setMetadata = null)
79+
public static function compute(callable $callback, ItemInterface $item, bool &$save, CacheInterface $pool, \Closure $setMetadata = null, LoggerInterface $logger = null)
7980
{
8081
$key = self::$files ? crc32($item->getKey()) % \count(self::$files) : -1;
8182

@@ -87,6 +88,7 @@ public static function compute(callable $callback, ItemInterface $item, bool &$s
8788
try {
8889
// race to get the lock in non-blocking mode
8990
if (flock($lock, LOCK_EX | LOCK_NB)) {
91+
$logger && $logger->info('Lock acquired, now computing item "{key}"', ['key' => $item->getKey()]);
9092
self::$lockedFiles[$key] = true;
9193

9294
$value = $callback($item, $save);
@@ -103,6 +105,7 @@ public static function compute(callable $callback, ItemInterface $item, bool &$s
103105
return $value;
104106
}
105107
// if we failed the race, retry locking in blocking mode to wait for the winner
108+
$logger && $logger->info('Item "{key}" is locked, waiting for it to be released', ['key' => $item->getKey()]);
106109
flock($lock, LOCK_SH);
107110
} finally {
108111
flock($lock, LOCK_UN);
@@ -114,13 +117,15 @@ public static function compute(callable $callback, ItemInterface $item, bool &$s
114117

115118
try {
116119
$value = $pool->get($item->getKey(), $signalingCallback, 0);
120+
$logger && $logger->info('Item "{key}" retrieved after lock was released', ['key' => $item->getKey()]);
117121
$save = false;
118122

119123
return $value;
120124
} catch (\Exception $e) {
121125
if ($signalingException !== $e) {
122126
throw $e;
123127
}
128+
$logger && $logger->info('Item "{key}" not found while lock was released, now retrying', ['key' => $item->getKey()]);
124129
}
125130
}
126131
}

‎src/Symfony/Component/Cache/Traits/ContractsTrait.php

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111

1212
namespace Symfony\Component\Cache\Traits;
1313

14+
use Psr\Log\LoggerInterface;
1415
use Symfony\Component\Cache\Adapter\AdapterInterface;
1516
use Symfony\Component\Cache\CacheItem;
1617
use Symfony\Component\Cache\Exception\InvalidArgumentException;
@@ -40,7 +41,7 @@ trait ContractsTrait
4041
public function setCallbackWrapper(?callable $callbackWrapper): callable
4142
{
4243
$previousWrapper = $this->callbackWrapper;
43-
$this->callbackWrapper = $callbackWrapper ?? function (callable $callback, ItemInterface $item, bool &$save, CacheInterface $pool, \Closure $setMetadata) {
44+
$this->callbackWrapper = $callbackWrapper ?? function (callable $callback, ItemInterface $item, bool &$save, CacheInterface $pool, \Closure $setMetadata, ?LoggerInterface $logger) {
4445
return $callback($item, $save);
4546
};
4647

@@ -82,13 +83,13 @@ function (CacheItem $item, float $startTime, ?array &$metadata) {
8283
try {
8384
$value = $callbackWrapper($callback, $item, $save, $pool, function (CacheItem $item) use ($setMetadata, $startTime, &$metadata) {
8485
$setMetadata($item, $startTime, $metadata);
85-
});
86+
}, $this->logger ?? null);
8687
$setMetadata($item, $startTime, $metadata);
8788

8889
return $value;
8990
} finally {
9091
$this->callbackWrapper = $callbackWrapper;
9192
}
92-
}, $beta, $metadata);
93+
}, $beta, $metadata, $this->logger ?? null);
9394
}
9495
}

‎src/Symfony/Contracts/Cache/CacheTrait.php

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@
1313

1414
use Psr\Cache\CacheItemPoolInterface;
1515
use Psr\Cache\InvalidArgumentException;
16+
use Psr\Log\LoggerInterface;
1617

1718
/**
1819
* An implementation of CacheInterface for PSR-6 CacheItemPoolInterface classes.
@@ -37,7 +38,7 @@ public function delete(string $key): bool
3738
return $this->deleteItem($key);
3839
}
3940

40-
private function doGet(CacheItemPoolInterface $pool, string $key, callable $callback, ?float $beta, array &$metadata = null)
41+
private function doGet(CacheItemPoolInterface $pool, string $key, callable $callback, ?float $beta, array &$metadata = null, LoggerInterface $logger = null)
4142
{
4243
if (0 > $beta = $beta ?? 1.0) {
4344
throw new class(sprintf('Argument "$beta" provided to "%s::get()" must be a positive number, %f given.', \get_class($this), $beta)) extends \InvalidArgumentException implements InvalidArgumentException {
@@ -52,9 +53,13 @@ private function doGet(CacheItemPoolInterface $pool, string $key, callable $call
5253
$expiry = $metadata[ItemInterface::METADATA_EXPIRY] ?? false;
5354
$ctime = $metadata[ItemInterface::METADATA_CTIME] ?? false;
5455

55-
if ($recompute = $ctime && $expiry && $expiry <= microtime(true) - $ctime / 1000 * $beta * log(random_int(1, PHP_INT_MAX) / PHP_INT_MAX)) {
56+
if ($recompute = $ctime && $expiry && $expiry <= ($now = microtime(true)) - $ctime / 1000 * $beta * log(random_int(1, PHP_INT_MAX) / PHP_INT_MAX)) {
5657
// force applying defaultLifetime to expiry
5758
$item->expiresAt(null);
59+
$this->logger && $this->logger->info('Item "{key}" elected for early recomputation {delta}s before its expiration', [
60+
'key' => $key,
61+
'delta' => sprintf('%.1f', $expiry - $now),
62+
]);
5863
}
5964
}
6065

0 commit comments

Comments
 (0)
0