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 <krinklemail@gmail.com>
Change-Id: I8a2b06cf54d2acf5950eed71756ecdf50e224be1

diff --git a/includes/DefaultSettings.php b/includes/DefaultSettings.php
index 08084f4..2a30352 100644 (file)
--- 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 1aed280..8e3c0a5 100644 (file)
--- 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 3e88cb1..fe61470 100644 (file)
--- 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 6d26419..bf152b6 100644 (file)
--- 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 96e200d..a8beb91 100644 (file)
--- 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();
+       }
 }