Problem/Motivation

The module currently relies upon the time() function to track when various caches are cleared. The time() function tracks events to the nearest second. The problem is that there can be thousands of operations within an individual second, so a second becomes an extremely imprecise value to work from. The current system leads to issues like #2444221: cache_lifetime should not affect cache_clear_all(), whereby it's impossible to discern between cache_set() being called before or after a cache_clear_all().

Proposed resolution

Change all time-based logic to use microtime() instead of time().

Remaining tasks

Write a patch, test it.

User interface changes

None.

API changes

None.

Data model changes

Additional variables are kept to track the microtime of various events in addition to the timestamp.

Comments

damienmckenna’s picture

Issue summary: View changes
damienmckenna’s picture

Status: Active » Needs review
StatusFileSize
new9.78 KB

Food for thought. This adds some reliance upon $cache->created_microtime. It could probably use a little tidying up too.

damienmckenna’s picture

StatusFileSize
new10.22 KB

Wrapped some of the logic (if() statements) to make the lines easier to follow.

damienmckenna’s picture

StatusFileSize
new12.31 KB

Improvements to make the same logic improvements from the cache_flush logic also available on the other scenarios, and added comments explaining the logic.

damienmckenna’s picture

Some sample code that can be added to a PHP script and then loaded via the webpage to confirm the before & after behavior:

define('DRUPAL_ROOT', getcwd());
include_once DRUPAL_ROOT . '/includes/bootstrap.inc';
drupal_bootstrap(DRUPAL_BOOTSTRAP_FULL);

print("<hr />\n");

$cid = "sidthesloth";
$data = "potato";
$bin = 'cache';

cache_set($cid, $data, $bin, CACHE_TEMPORARY);
print("1. Stored some data in the cache.<br />\n");

$t = cache_get($cid, $bin);
print("2. Cache contains the following:<br />\n");
print("<pre>\n");
print_r($t);
print("</pre>\n");

cache_clear_all("*", $bin, TRUE);
print("3. Caches cleared.<br />\n");

$t = cache_get($cid, $bin);
print("4. The cache object now contains:<br />\n");
print("<pre>\n");
print_r($t);
print("</pre>\n");
print("(That should be a blank value.)<br />\n");

print("<hr />\n");

$cid = "sidthesloth1";
$data = "potato1";
cache_set($cid, $data, $bin, CACHE_TEMPORARY);
print("5. New data stored in the cache.<br />\n");

$t = cache_get($cid, $bin);
print("6. The cache now contains:<br />\n");
print("<pre>\n");
print_r($t);
print("</pre>\n");

print("The cache should return data.<br />\n");

print("<hr />\n");
damienmckenna’s picture

When the code above is ran against the current -dev release, the following is the results:

1. Stored some data in the cache.

2. Cache contains the following:
stdClass Object
(
    [cid] => sidthesloth
    [data] => potato
    [created] => 1438291623
    [created_microtime] => 1438291623.349
    [flushes] => 0
    [expire] => 1440883622
    [temporary] => 1
)

3. Caches cleared.

4. The cache object now contains:

(That should be a blank value.)

5. New data stored in the cache.

6. The cache now contains:

The cache should return data.

After the patch is applied the output looks like this:

1. Stored some data in the cache.

2. Cache contains the following:
stdClass Object
(
    [cid] => sidthesloth
    [data] => potato
    [created] => 1438291677
    [created_microtime] => 0.90800500
    [flushes] => 0
    [expire] => 1440883674
    [temporary] => 1
)

3. Caches cleared.

4. The cache object now contains:

(That should be a blank value.)

5. New data stored in the cache.

6. The cache now contains:
stdClass Object
(
    [cid] => sidthesloth1
    [data] => potato1
    [created] => 1438291677
    [created_microtime] => 0.93335500
    [flushes] => 0
    [expire] => 1440883674
    [temporary] => 1
)

The cache should return data.
damienmckenna’s picture

FYI you'll need to clear all sessions after applying the patch because the $_SESSION['cache_flush'] data structure changes.

damienmckenna’s picture

StatusFileSize
new12.82 KB

Working on the tests - they're not all passing yet, so there's some work to be done.

damienmckenna’s picture

StatusFileSize
new14.36 KB

One step closer. I noticed that the MemCacheRealWorldCase tests were failing because the 'language' table wasn't found, so I added 'locale' to the list of enabled modules.

damienmckenna’s picture

StatusFileSize
new15.24 KB

Down to three fails in MemCacheClearCase and one in MemcacheLockFunctionalTest, while MemCacheGetMultipleUnitTest and MemCacheRealWorldCase pass all tests.

FYI the failure in MemcacheLockFunctionalTest is the old "Bootstrap failed in lockInit(), lock_acquire() is not available." problem.

damienmckenna’s picture

Here's what "drush test-run MemCacheClearCase" has to say for itself:

Starting test MemCacheClearCase.
Cache clear test 75 passes, 3 fails, 0 exceptions, and 9 debug messages
Test MemCacheClearCase->testClearCacheLifetime() failed: Cache item was cleared successfully. in memcache.test on line 504
Test MemCacheClearCase->testClearCacheLifetime() failed: Cache item is not returned once minimum cache lifetime has expired. in memcache.test on line 522
Test MemCacheClearCase->testClearWildcardOnSeparatePages() failed: Cache was properly flushed. in memcache.test on line 701
damienmckenna’s picture

Issue summary: View changes
damienmckenna’s picture

StatusFileSize
new32.85 KB

Some minor code formatting cleanup for the tests. Still just have the four failures.

damienmckenna’s picture

StatusFileSize
new33.01 KB

I left in some debug print() statements in one of the tests, sorry about that.

damienmckenna’s picture

StatusFileSize
new30.99 KB

Reverted the unnecessary changes to the memcache6.test file.

pieterdc’s picture

Issue #2335727: Setting $cache->created with msec precision borks page caching. changed the created timestamp to a second-precision version to align with the Drupal core database cache backend class, but:
- it uses to REQUEST_TIME (like it did pre-2011) which holds the start time of the request instead of the current time (like it did from 2011 to 2014)
- didn't adjust the time checks in MemCacheDrupal::valid() accordingly

That causes for example a cache entry set after a cache clear to be considered invalid if retrieved in the same request. That's a false cache miss.

Luckily this issue helps with that.

It's a pity there are so many test failures on the 7.x-1.x branch because that makes it hard to verify if any patch breaks existing functionality. Being worked on in #1863996: Fix all tests. But running CacheClearTest on my local, with the patch, I went down from 3 to 2 failures.

If we leave out the code cleanup (that adheres coding standards and improves readability) we're left with a patch that's easier to review.
If we then leave out the pieces from the general test fixing issue patch, the changes of this issue are even more obvious: see patch attached.

pieterdc’s picture

Status: Needs review » Needs work

We ran a whole bunch of integration tests on our Drupal distribution and discovered failures were introduced by applying the patch from comment #15.
Mostly module installations that assign permissions to roles in a hook_enable() implementation. Clearing some caches did the trick to get the newly created permissions known even before the module installation was completed.
But with the aforementioned patch, we sometimes get stale (cache) data making the permissions unknown again.

So, the patch needs more work.

damienmckenna’s picture

@PieterDC: are you talking about the problem with permissions exported via Features, e.g. #1549608: Cannot import exported Panelizer permissions using Features/defaultconfig if handler cache is stale?

pieterdc’s picture

Damien, our permissions are not exported through Features, but yeah, we face the same PDOException. I created an internal low priority follow-up ticket to have a look at it. Thanks for the hint!

jeremy’s picture

@PieterDC, did you ever track down the regressions? I'm interested in seeing this patch committed, if you can provide any more detail on how to duplicate the regressions that would be helpful.

pieterdc’s picture

@Jeremy, I never got to tracking down the regressions.

damienmckenna’s picture

Status: Needs work » Needs review
StatusFileSize
new10.09 KB

Just to get a baseline of where we are, this is a reroll of the raw changes, it doesn't include the tests.

damienmckenna’s picture

Was automated testing disabled for the 7.x-1.x branch?

jeremy’s picture

Status: Needs review » Needs work

patch doesn't apply

mrinalini9’s picture

Status: Needs work » Needs review
StatusFileSize
new10.01 KB

Rerolled patch #22 for 7.x-1.x branch as it failed to apply, please review.

jeremy’s picture

Thanks! I'll test this out once 7.x-1.7 is released (ideally to be part of 7.x-1.8).

badrange’s picture

Hi @jeremy - looks like the patch didn't make it to 1.8, is there a chance for it to be released in 1.9? If this fix would improve caching it would save lots of cpu cycles and electricity..

moshe weitzman’s picture

Looks to me like this is done in latest version.

japerry’s picture

Status: Needs review » Closed (outdated)

Closing as Drupal 7 is no longer supported.

Now that this issue is closed, review the contribution record.

As a contributor, attribute any organization that helped you, or if you volunteered your own time.

Maintainers, credit people who helped resolve this issue.