Problem/Motivation

When debugging caching problems, it would be useful to have more information. Specifically, it would be good to log how long each action takes, and optionally how large of a value is being written to or read from the cache.

Beyond that, it would also be helpful to only log slow requests, and/or requests with larger value sizes.

Steps to reproduce

To enable all features, add some variation on the following options to settings.php:

$conf['memcache_debug_log'] = '/tmp/memcache.log';
$conf['memcache_debug_verbose'] = TRUE;
$conf['memcache_debug_size'] = TRUE;
$conf['memcache_debug_size_minimum'] = 5120;
$conf['memcache_debug_elapsed_minimum'] = 0.15;

Proposed resolution

Add the requested functionality.

Remaining tasks

Patch needs review, testing, and performance testing.

User interface changes

None.

API changes

The internal _dmemcache_write_debug() function gains a parameter for tracking the value size.

Data model changes

Issue fork memcache-3352885

Command icon Show commands

Start within a Git clone of the project using the version control instructions.

Or, if you do not have SSH keys set up on git.drupalcode.org:

About issue forks

Comments

Jeremy created an issue. See original summary.

Jeremy opened merge request !13

jeremy’s picture

jeremy commented

Implements new features per the issue description:
https://git.drupalcode.org/project/memcache/-/merge_requests/13/diffs

Includes new documentation:

You can also filter to only show requests that take longer than a specific number of milliseconds. For example, the following would only log memcache actions that take longer than 0.5 milliseconds:
$conf['memcache_debug_elapsed_minimum'] = 0.5;

To include '!size' (the estimated size in bytes of the object being written to or read from memcache) enable the following option:
$conf['memcache_debug_size'] = TRUE;

In order to calculate the size of objects, they are first serialized then strlen is used to determine total bytes. While this may not always be precise, it is a close enough estimation to be a useful metric in debug logging. Note that there is added CPU overhead when enabling this option, due to all the serialization required.

If enabled, you can also filter what is logged, so for example only objects over 1024 bytes in size:
$conf['memcache_debug_size_minimum'] = 1024;

jeremy’s picture

jeremy commented
Issue summary: View changes
jeremy’s picture

jeremy commented

I created some very large nodes, and then loaded them with this enabled to get the following logs:

1680863171|429.34|getMulti|cache_field|cache_field-cache-_multi181-field%253Anode%253A6|1048151|1
1680863171|430.37|getMulti|cache_field|cache_field-cache-_multi182-field%253Anode%253A6|1045479|1
1680863172|931.11|getMulti|cache_field|cache_field-field%3Anode%3A6|191789014|1
1680863200|0.27|get|cache_bootstrap|cache_bootstrap-system_list|6348|1

In my test configuration I configured the debug log to only include objects over 5120 bytes and that take longer than 0.25 milliseconds to process:

$conf['memcache_debug_size'] = TRUE;
$conf['memcache_debug_size_minimum'] = 5120;
$conf['memcache_debug_elapsed_minimum'] = 0.25;

The first two rows are part of a getMulti request for a large object was split into 182 pieces. You can see that each request is taking ~430 milliseconds, and that the objects have been split into 1,045,479 byte pieces The last line is a slow (0.27 millisecond) request for cache_bootstrap, which is 6,348 bytes in size.

japerry’s picture

japerry
Location KOMK
commented
Status: Active » 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.