Fix slow callbacks in getWithSetCallback() using lockTSE
authorAaron Schulz <aschulz@wikimedia.org>
Fri, 23 Oct 2015 02:36:59 +0000 (19:36 -0700)
committerKrinkle <krinklemail@gmail.com>
Wed, 28 Oct 2015 23:31:37 +0000 (23:31 +0000)
* Keys that take a long time to generate would run into
  the MAX_SNAPSHOT_LAG check and have set() no-op. This
  would be fine except that leaves no key there to figure
  out the time since expiry and therefore whether to use
  the mutex, so it didn't. This now saves the keys but with
  a FLG_STALE bit set, making the next caller that sees it
  perform a regeneration (unless it can't get the mutex).
* Bumped LOCK_TTL so that keys can stay locked much longer.
* This is easy to test via sleep(5) in tagUsageStatistics()
  and two Special:Tags browser tabs.

Bug: T91535
Change-Id: I549e70ace3d2e7da40d3c4346ebacc36024cd522

includes/libs/objectcache/WANObjectCache.php
tests/phpunit/includes/libs/objectcache/WANObjectCacheTest.php

index 5338e3a..6ef2bce 100644 (file)
@@ -89,7 +89,7 @@ class WANObjectCache implements IExpiringStore, LoggerAwareInterface {
        /** Seconds to keep dependency purge keys around */
        const CHECK_KEY_TTL = self::TTL_YEAR;
        /** Seconds to keep lock keys around */
-       const LOCK_TTL = 5;
+       const LOCK_TTL = 10;
        /** Default remaining TTL at which to consider pre-emptive regeneration */
        const LOW_TTL = 30;
        /** Default time-since-expiry on a miss that makes a key "hot" */
@@ -104,6 +104,9 @@ class WANObjectCache implements IExpiringStore, LoggerAwareInterface {
        /** Max TTL to store keys when a data sourced is lagged */
        const TTL_LAGGED = 30;
 
+       /** Tiny negative float to use when CTL comes up >= 0 due to clock skew */
+       const TINY_NEGATIVE = -0.000001;
+
        /** Cache format version number */
        const VERSION = 1;
 
@@ -111,6 +114,10 @@ class WANObjectCache implements IExpiringStore, LoggerAwareInterface {
        const FLD_VALUE = 1;
        const FLD_TTL = 2;
        const FLD_TIME = 3;
+       const FLD_FLAGS = 4;
+
+       /** @var integer Treat this value as expired-on-arrival */
+       const FLG_STALE = 1;
 
        const ERR_NONE = 0; // no error
        const ERR_NO_RESPONSE = 1; // no response
@@ -159,11 +166,11 @@ class WANObjectCache implements IExpiringStore, LoggerAwareInterface {
        /**
         * Fetch the value of a key from cache
         *
-        * If passed in, $curTTL is set to the remaining TTL (current time left):
-        *   - a) INF; if the key exists, has no TTL, and is not expired by $checkKeys
-        *   - b) float (>=0); if the key exists, has a TTL, and is not expired by $checkKeys
-        *   - c) float (<0); if the key is tombstoned or existing but expired by $checkKeys
-        *   - d) null; if the key does not exist and is not tombstoned
+        * If supplied, $curTTL is set to the remaining TTL (current time left):
+        *   - a) INF; if $key exists, has no TTL, and is not expired by $checkKeys
+        *   - b) float (>=0); if $key exists, has a TTL, and is not expired by $checkKeys
+        *   - c) float (<0); if $key is tombstoned, stale, or existing but expired by $checkKeys
+        *   - d) null; if $key does not exist and is not tombstoned
         *
         * If a key is tombstoned, $curTTL will reflect the time since delete().
         *
@@ -314,10 +321,9 @@ class WANObjectCache implements IExpiringStore, LoggerAwareInterface {
         *               Generally, other threads should not see values from the future and
         *               they certainly should not see ones that ended up getting rolled back.
         *               Default: false
-        *   - lockTSE : if excessive possible snapshot lag is detected,
-        *               then stash the value into a temporary location
-        *               with this TTL. This is only useful if the reads
-        *               use getWithSetCallback() with "lockTSE" set.
+        *   - lockTSE : if excessive replication/snapshot lag is detected, then store the value
+        *               with this TTL and flag it as stale. This is only useful if the reads for
+        *               this key use getWithSetCallback() with "lockTSE" set.
         *               Default: WANObjectCache::TSE_NONE
         * @return bool Success
         */
@@ -325,29 +331,31 @@ class WANObjectCache implements IExpiringStore, LoggerAwareInterface {
                $lockTSE = isset( $opts['lockTSE'] ) ? $opts['lockTSE'] : self::TSE_NONE;
                $age = isset( $opts['since'] ) ? max( 0, microtime( true ) - $opts['since'] ) : 0;
                $lag = isset( $opts['lag'] ) ? $opts['lag'] : 0;
-               // Disallow set() if the source data is uncommitted as it might get rolled back
+
+               // Do not cache potentially uncommitted data as it might get rolled back
                if ( !empty( $opts['pending'] ) ) {
                        $this->logger->info( "Rejected set() for $key due to pending writes." );
 
                        return true; // no-op the write for being unsafe
                }
+
+               $wrapExtra = array(); // additional wrapped value fields
                // Check if there's a risk of writing stale data after the purge tombstone expired
                if ( ( $lag + $age ) > self::MAX_READ_LAG ) {
+                       // Case A: read lag with "lockTSE"; save but record value as stale
                        if ( $lockTSE >= 0 ) {
-                               // Focus on avoiding stampedes; stash the value with a low TTL
-                               $tempTTL = max( 1, (int)$lockTSE ); // set() expects seconds
-                               $this->cache->set( self::STASH_KEY_PREFIX . $key, $value, $tempTTL );
-                       }
-                       // Case A: any long-running transaction; ignore this set()
-                       if ( $age > self::MAX_READ_LAG ) {
+                               $ttl = max( 1, (int)$lockTSE ); // set() expects seconds
+                               $wrapExtra[self::FLD_FLAGS] = self::FLG_STALE; // mark as stale
+                       // Case B: any long-running transaction; ignore this set()
+                       } elseif ( $age > self::MAX_READ_LAG ) {
                                $this->logger->warning( "Rejected set() for $key due to snapshot lag." );
 
                                return true; // no-op the write for being unsafe
-                       // Case B: replication lag is high; lower TTL instead of ignoring all set()s
+                       // Case C: high replication lag; lower TTL instead of ignoring all set()s
                        } elseif ( $lag > self::MAX_READ_LAG ) {
                                $ttl = $ttl ? min( $ttl, self::TTL_LAGGED ) : self::TTL_LAGGED;
                                $this->logger->warning( "Lowered set() TTL for $key due to replication lag." );
-                       // Case C: medium length request during medium lag; ignore this set()
+                       // Case D: medium length request with medium replication lag; ignore this set()
                        } else {
                                $this->logger->warning( "Rejected set() for $key due to high read lag." );
 
@@ -355,7 +363,8 @@ class WANObjectCache implements IExpiringStore, LoggerAwareInterface {
                        }
                }
 
-               $wrapped = $this->wrap( $value, $ttl );
+               // Wrap that value with time/TTL/version metadata
+               $wrapped = $this->wrap( $value, $ttl ) + $wrapExtra;
 
                $func = function ( $cache, $key, $cWrapped ) use ( $wrapped ) {
                        return ( is_string( $cWrapped ) )
@@ -922,7 +931,7 @@ class WANObjectCache implements IExpiringStore, LoggerAwareInterface {
         *
         * @param mixed $value
         * @param integer $ttl [0=forever]
-        * @return string
+        * @return array
         */
        protected function wrap( $value, $ttl ) {
                return array(
@@ -945,7 +954,7 @@ class WANObjectCache implements IExpiringStore, LoggerAwareInterface {
                $purgeTimestamp = self::parsePurgeValue( $wrapped );
                if ( is_float( $purgeTimestamp ) ) {
                        // Purged values should always have a negative current $ttl
-                       $curTTL = min( -0.000001, $purgeTimestamp - $now );
+                       $curTTL = min( $purgeTimestamp - $now, self::TINY_NEGATIVE );
                        return array( false, $curTTL );
                }
 
@@ -956,7 +965,12 @@ class WANObjectCache implements IExpiringStore, LoggerAwareInterface {
                        return array( false, null );
                }
 
-               if ( $wrapped[self::FLD_TTL] > 0 ) {
+               $flags = isset( $wrapped[self::FLD_FLAGS] ) ? $wrapped[self::FLD_FLAGS] : 0;
+               if ( ( $flags & self::FLG_STALE ) == self::FLG_STALE ) {
+                       // Treat as expired, with the cache time as the expiration
+                       $age = $now - $wrapped[self::FLD_TIME];
+                       $curTTL = min( -$age, self::TINY_NEGATIVE );
+               } elseif ( $wrapped[self::FLD_TTL] > 0 ) {
                        // Get the approximate time left on the key
                        $age = $now - $wrapped[self::FLD_TIME];
                        $curTTL = max( $wrapped[self::FLD_TTL] - $age, 0.0 );
index 54393a7..a1fdd91 100644 (file)
@@ -175,7 +175,6 @@ class WANObjectCacheTest extends MediaWikiTestCase {
                        return $value;
                };
 
-               $cache->delete( $key );
                $ret = $cache->getWithSetCallback( $key, 30, $func, array( 'lockTSE' => 5 ) );
                $this->assertEquals( $value, $ret );
                $this->assertEquals( 1, $calls, 'Value was populated' );
@@ -187,6 +186,36 @@ class WANObjectCacheTest extends MediaWikiTestCase {
                $this->assertEquals( 1, $calls, 'Callback was not used' );
        }
 
+       /**
+        * @covers WANObjectCache::getWithSetCallback()
+        */
+       public function testLockTSESlow() {
+               $cache = $this->cache;
+               $key = wfRandomString();
+               $value = wfRandomString();
+
+               $calls = 0;
+               $func = function( $oldValue, &$ttl, &$setOpts ) use ( &$calls, $value ) {
+                       ++$calls;
+                       $setOpts['since'] = microtime( true ) - 10;
+                       return $value;
+               };
+
+               // Value should be marked as stale due to snapshot lag
+               $curTTL = null;
+               $ret = $cache->getWithSetCallback( $key, 30, $func, array( 'lockTSE' => 5 ) );
+               $this->assertEquals( $value, $ret );
+               $this->assertEquals( $value, $cache->get( $key, $curTTL ), 'Value was populated' );
+               $this->assertLessThan( 0, $curTTL, 'Value has negative curTTL' );
+               $this->assertEquals( 1, $calls, 'Value was generated' );
+
+               // Acquire a lock to verify that getWithSetCallback uses lockTSE properly
+               $this->internalCache->lock( $key, 0 );
+               $ret = $cache->getWithSetCallback( $key, 30, $func, array( 'lockTSE' => 5 ) );
+               $this->assertEquals( $value, $ret );
+               $this->assertEquals( 1, $calls, 'Callback was not used' );
+       }
+
        /**
         * @covers WANObjectCache::getMulti()
         */