Merge "BagOStuff: Optionally log duplicate key lookups"
authorjenkins-bot <jenkins-bot@gerrit.wikimedia.org>
Fri, 22 Apr 2016 16:50:10 +0000 (16:50 +0000)
committerGerrit Code Review <gerrit@wikimedia.org>
Fri, 22 Apr 2016 16:50:10 +0000 (16:50 +0000)
includes/DefaultSettings.php
includes/libs/objectcache/BagOStuff.php
includes/libs/objectcache/MultiWriteBagOStuff.php
includes/objectcache/ObjectCache.php
tests/phpunit/includes/libs/objectcache/BagOStuffTest.php

index 08084f4..2a30352 100644 (file)
@@ -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 ],
 ];
 
 /**
index 1aed280..8e3c0a5 100644 (file)
@@ -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]
index 3e88cb1..fe61470 100644 (file)
@@ -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' &&
index 6d26419..bf152b6 100644 (file)
@@ -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'] ) ) {
index 96e200d..a8beb91 100644 (file)
@@ -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();
+       }
 }