include action time and value size in debug logs

Created on 7 April 2023, about 1 year ago

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

✨ Feature request
Status

Active

Version

1.0

Component

Code

Created by

🇮🇹Italy Jeremy Tuscany

Live updates comments and jobs are added and updated live.
Sign in to follow issues

Comments & Activities

  • Issue created by @Jeremy
  • @jeremy opened merge request.
  • 🇮🇹Italy Jeremy Tuscany

    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 seconds. For example, the following would only log memcache actions that take
    +longer than 0.5 seconds:
    + $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;

  • 🇮🇹Italy Jeremy Tuscany
  • 🇮🇹Italy Jeremy Tuscany

    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.

Production build 0.69.0 2024