From 450bb6723da128eb5aa90151cbd8fda34dbb9118 Mon Sep 17 00:00:00 2001 From: Bryan Davis Date: Tue, 1 Mar 2016 19:25:55 -0700 Subject: [PATCH] BagOStuff: Optionally log duplicate key lookups Add new 'reportDupes' parameter to BagOStuff. This parameter enables scheduling of a callback after the current web request ends. This callback will emit warning log messages for all keys that were requested more than once. The default ObjectCache factory for MediaWiki enables this option by default. Not by default for plain BagOStuff instances, however. E.g. `new HashBagOStuff()`. It also set 'asyncHandler' for all classes now (not just MultiWriteBagOStuff). Bug: T128125 Co-Authored-By: Timo Tijhof Change-Id: I8a2b06cf54d2acf5950eed71756ecdf50e224be1 --- includes/DefaultSettings.php | 10 +-- includes/libs/objectcache/BagOStuff.php | 65 +++++++++++++++++++ .../libs/objectcache/MultiWriteBagOStuff.php | 7 -- includes/objectcache/ObjectCache.php | 12 ++-- .../libs/objectcache/BagOStuffTest.php | 25 +++++++ 5 files changed, 102 insertions(+), 17 deletions(-) diff --git a/includes/DefaultSettings.php b/includes/DefaultSettings.php index 08084f4256..2a30352124 100644 --- a/includes/DefaultSettings.php +++ b/includes/DefaultSettings.php @@ -2169,7 +2169,7 @@ $wgLanguageConverterCacheType = CACHE_ANYTHING; * given, giving a callable function which will generate a suitable cache object. */ $wgObjectCaches = [ - CACHE_NONE => [ 'class' => 'EmptyBagOStuff' ], + CACHE_NONE => [ 'class' => 'EmptyBagOStuff', 'reportDupes' => false ], CACHE_DB => [ 'class' => 'SqlBagOStuff', 'loggroup' => 'SQLBagOStuff' ], CACHE_ANYTHING => [ 'factory' => 'ObjectCache::newAnything' ], @@ -2189,12 +2189,12 @@ $wgObjectCaches = [ 'loggroup' => 'SQLBagOStuff' ], - 'apc' => [ 'class' => 'APCBagOStuff' ], - 'xcache' => [ 'class' => 'XCacheBagOStuff' ], - 'wincache' => [ 'class' => 'WinCacheBagOStuff' ], + 'apc' => [ 'class' => 'APCBagOStuff', 'reportDupes' => false ], + 'xcache' => [ 'class' => 'XCacheBagOStuff', 'reportDupes' => false ], + 'wincache' => [ 'class' => 'WinCacheBagOStuff', 'reportDupes' => false ], 'memcached-php' => [ 'class' => 'MemcachedPhpBagOStuff', 'loggroup' => 'memcached' ], 'memcached-pecl' => [ 'class' => 'MemcachedPeclBagOStuff', 'loggroup' => 'memcached' ], - 'hash' => [ 'class' => 'HashBagOStuff' ], + 'hash' => [ 'class' => 'HashBagOStuff', 'reportDupes' => false ], ]; /** diff --git a/includes/libs/objectcache/BagOStuff.php b/includes/libs/objectcache/BagOStuff.php index 1aed28036a..8e3c0a5f36 100644 --- a/includes/libs/objectcache/BagOStuff.php +++ b/includes/libs/objectcache/BagOStuff.php @@ -55,9 +55,21 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface { /** @var LoggerInterface */ protected $logger; + /** @var callback|null */ + protected $asyncHandler; + /** @var bool */ private $debugMode = false; + /** @var array */ + private $duplicateKeyLookups = []; + + /** @var bool */ + private $reportDupes = false; + + /** @var bool */ + private $dupeTrackScheduled = false; + /** Possible values for getLastError() */ const ERR_NONE = 0; // no error const ERR_NO_RESPONSE = 1; // no response @@ -71,6 +83,16 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface { const WRITE_SYNC = 1; // synchronously write to all locations for replicated stores const WRITE_CACHE_ONLY = 2; // Only change state of the in-memory cache + /** + * $params include: + * - logger: Psr\Log\LoggerInterface instance + * - keyspace: Default keyspace for $this->makeKey() + * - asyncHandler: Callable to use for scheduling tasks after the web request ends. + * In CLI mode, it should run the task immediately. + * - reportDupes: Whether to emit warning log messages for all keys that were + * requested more than once (requires an asyncHandler). + * @param array $params + */ public function __construct( array $params = [] ) { if ( isset( $params['logger'] ) ) { $this->setLogger( $params['logger'] ); @@ -81,6 +103,14 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface { if ( isset( $params['keyspace'] ) ) { $this->keyspace = $params['keyspace']; } + + $this->asyncHandler = isset( $params['asyncHandler'] ) + ? $params['asyncHandler'] + : null; + + if ( !empty( $params['reportDupes'] ) && is_callable( $this->asyncHandler ) ) { + $this->reportDupes = true; + } } /** @@ -144,9 +174,44 @@ abstract class BagOStuff implements IExpiringStore, LoggerAwareInterface { // B/C for ( $key, &$casToken = null, $flags = 0 ) $flags = is_int( $oldFlags ) ? $oldFlags : $flags; + $this->trackDuplicateKeys( $key ); + return $this->doGet( $key, $flags ); } + /** + * Track the number of times that a given key has been used. + * @param string $key + */ + private function trackDuplicateKeys( $key ) { + if ( !$this->reportDupes ) { + return; + } + + if ( !isset( $this->duplicateKeyLookups[$key] ) ) { + // Track that we have seen this key. This N-1 counting style allows + // easy filtering with array_filter() later. + $this->duplicateKeyLookups[$key] = 0; + } else { + $this->duplicateKeyLookups[$key] += 1; + + if ( $this->dupeTrackScheduled === false ) { + $this->dupeTrackScheduled = true; + // Schedule a callback that logs keys processed more than once by get(). + call_user_func( $this->asyncHandler, function () { + $dups = array_filter( $this->duplicateKeyLookups ); + foreach ( $dups as $key => $count ) { + $this->logger->warning( + 'Duplicate get(): "{key}" fetched {count} times', + // Count is N-1 of the actual lookup count + [ 'key' => $key, 'count' => $count + 1, ] + ); + } + } ); + } + } + } + /** * @param string $key * @param integer $flags Bitfield of BagOStuff::READ_* constants [optional] diff --git a/includes/libs/objectcache/MultiWriteBagOStuff.php b/includes/libs/objectcache/MultiWriteBagOStuff.php index 3e88cb19ed..fe61470284 100644 --- a/includes/libs/objectcache/MultiWriteBagOStuff.php +++ b/includes/libs/objectcache/MultiWriteBagOStuff.php @@ -33,8 +33,6 @@ class MultiWriteBagOStuff extends BagOStuff { protected $caches; /** @var bool Use async secondary writes */ protected $asyncWrites = false; - /** @var callback|null */ - protected $asyncHandler; /** Idiom for "write to all backends" */ const ALL = INF; @@ -58,8 +56,6 @@ class MultiWriteBagOStuff extends BagOStuff { * safe to use for modules when cached values: are immutable, * invalidation uses logical TTLs, invalidation uses etag/timestamp * validation against the DB, or merge() is used to handle races. - * - asyncHandler: callable that takes a callback and runs it after the - * current web request ends. In CLI mode, it should run it immediately. * @param array $params * @throws InvalidArgumentException */ @@ -88,9 +84,6 @@ class MultiWriteBagOStuff extends BagOStuff { } } - $this->asyncHandler = isset( $params['asyncHandler'] ) - ? $params['asyncHandler'] - : null; $this->asyncWrites = ( isset( $params['replication'] ) && $params['replication'] === 'async' && diff --git a/includes/objectcache/ObjectCache.php b/includes/objectcache/ObjectCache.php index 6d26419a6b..bf152b6ec6 100644 --- a/includes/objectcache/ObjectCache.php +++ b/includes/objectcache/ObjectCache.php @@ -174,11 +174,13 @@ class ObjectCache { } elseif ( isset( $params['class'] ) ) { $class = $params['class']; // Automatically set the 'async' update handler - if ( $class === 'MultiWriteBagOStuff' ) { - $params['asyncHandler'] = isset( $params['asyncHandler'] ) - ? $params['asyncHandler'] - : 'DeferredUpdates::addCallableUpdate'; - } + $params['asyncHandler'] = isset( $params['asyncHandler'] ) + ? $params['asyncHandler'] + : 'DeferredUpdates::addCallableUpdate'; + // Enable reportDupes by default + $params['reportDupes'] = isset( $params['reportDupes'] ) + ? $params['reportDupes'] + : true; // Do b/c logic for MemcachedBagOStuff if ( is_subclass_of( $class, 'MemcachedBagOStuff' ) ) { if ( !isset( $params['servers'] ) ) { diff --git a/tests/phpunit/includes/libs/objectcache/BagOStuffTest.php b/tests/phpunit/includes/libs/objectcache/BagOStuffTest.php index 96e200dc9d..a8beb91518 100644 --- a/tests/phpunit/includes/libs/objectcache/BagOStuffTest.php +++ b/tests/phpunit/includes/libs/objectcache/BagOStuffTest.php @@ -252,4 +252,29 @@ class BagOStuffTest extends MediaWikiTestCase { $this->assertType( 'ScopedCallback', $value1, 'First reentrant call returned lock' ); $this->assertType( 'ScopedCallback', $value1, 'Second reentrant call returned lock' ); } + + /** + * @covers BagOStuff::__construct + * @covers BagOStuff::trackDuplicateKeys + */ + public function testReportDupes() { + $logger = $this->getMock( 'Psr\Log\NullLogger' ); + $logger->expects( $this->once() ) + ->method( 'warning' ) + ->with( 'Duplicate get(): "{key}" fetched {count} times', [ + 'key' => 'foo', + 'count' => 2, + ] ); + + $cache = new HashBagOStuff( [ + 'reportDupes' => true, + 'asyncHandler' => 'DeferredUpdates::addCallableUpdate', + 'logger' => $logger, + ] ); + $cache->get( 'foo' ); + $cache->get( 'bar' ); + $cache->get( 'foo' ); + + DeferredUpdates::doUpdates(); + } } -- 2.20.1