• Resolved ferraz13galo

    (@ferraz13galo)


    Environment. Redis Object Cache 2.8.0 (drop-in reports Version 2.8.0, md5 e27667c2e4d2aee614f3253e285f3e45) · PhpRedis 6.3.0 (Predis/Relay/Credis not loaded) · igbinary 3.2.16 · PHP 8.3.33 on PHP-FPM (pm = dynamic, max_children = 20, unix socket) · Redis 7.4.10 in a separate container, reached over TCP by service name, AUTH required · WP_REDIS_TIMEOUT = 1, WP_REDIS_READ_TIMEOUT = 1 · nginx with the default 60s fastcgi_read_timeout · single site · 78 active plugins (WooCommerce + Subscriptions) · Docker/EasyPanel on a KVM VPS.

    Throughout everything below, wp redis status reports Status: Connected / Drop-in: Valid / Ping: 1 / Errors: []. Redis itself is healthy: a pure PhpRedis GET/SET round-trip from the same container measures 4.5 ms.

    SYMPTOM

    Every FastCGI request that boots WordPress with the drop-in active spends 7 to 60 seconds after all PHP userland code has finished, in PHP’s automatic shutdown phase. The response is fully generated in under one second and then sits there, undelivered, while the process tears itself down.

    Releasing the cache object explicitly — a single unset($GLOBALS['wp_object_cache']) at the very end of the request, while the request is still alive — removes the delay entirely and costs about 12 ms. The exact same work, done microseconds later by PHP’s own teardown, costs 7 to 60 seconds.

    The drop-in has no __destruct(), no close() method and no register_shutdown_function() (grep against the installed 2.8.0 file: __destruct = 0, function close = 0, register_shutdown_function = 0). The connection is left for PHP to reap implicitly, and that is where the time goes.

    EVIDENCE 1 — the time is spent after PHP is done

    Comparing REQUEST_TIME_FLOAT measured inside the request against the client wall clock on the same host (curl over 127.0.0.1, no proxy in between):

    request   PHP finished at   client got response at   gap
      #3          +485 ms              +31,270 ms         30.8 s
      #5          +784 ms              +46,470 ms         45.7 s
      #8          +616 ms              +46,315 ms         45.7 s

    CPU stays at 0-1% during the gap. Sampling the worker state 419 times during the waits gave 409 samples sleeping and 10 running — it is blocking, not computing. Some requests stall at exactly 60.001157 s, which is nginx giving up at its default fastcgi_read_timeout, so the teardown can block indefinitely rather than for a bounded interval.

    EVIDENCE 2 — bisection isolates it to one object

    Five identical PHP files in the web root, each doing require of wp-load.php and then differing by a single line at the end. Four runs each, through FastCGI:

    x0  (nothing, control)                      7.098 / 60.014 / 60.001 / 16.466 s
    x1  unset($GLOBALS['wp_object_cache']);      0.585 /  0.543 /  0.542 /  0.606 s
    x2  unset($GLOBALS['wpdb']);                11.392 / 11.585 /  1.549 / 31.347 s
    x3  gc_collect_cycles();                    60.004 / 11.785 /  7.285 / 31.510 s
    x4  both unsets                              0.768 /  0.786 /  0.783 /  0.783 s

    Only the variants that release the object cache are fast. Forcing a GC cycle changes nothing, so this is not cycle collection, and wpdb alone does not explain it either.

    EVIDENCE 3 — what was ruled out, with numbers

    static file via nginx ................. 0.7 - 1.4 ms      fine
    bare PHP via FastCGI, no WordPress .... 0.9 - 4.5 ms      fine
    session_start() ....................... 1.5 - 5.4 ms      fine
    DNS (including NXDOMAIN) .............. 4 - 10 ms         fine
    OPcache hit rate ...................... 99.56%            fine
    disk: stat of 24,751 PHP files ........ 0.58 s            fine
    Redis round-trip, pure PhpRedis ....... 4.5 ms            fine
    MySQL round-trip, pure ................ 6 - 7 ms          fine
    WordPress + 78 plugins via WP-CLI ..... 3.5 - 8.5 s, never stalls
    WordPress + 78 plugins via FastCGI .... 1.6 s - 60.0 s    the stall

    Worker exhaustion was ruled out too: 10 parallel requests all finished internally in 617-1004 ms, the FPM listen queue was 0 and active processes 0 at the moment of the stalls, and pm = static with 20 pre-forked workers changed nothing. WooCommerce webhooks: 0 deliveries during 8 stalled requests. Output buffering: default handler only, 0 ms.

    The WP-CLI versus FastCGI contrast is the important one — same WordPress, same plugins, same Redis, same database. The stall appears only in the SAPI where delivering the response depends on the process reaching the end of its teardown.

    WORKAROUND NOW RUNNING IN PRODUCTION

    add_action( 'shutdown', function () {
        register_shutdown_function( function () {
            if ( isset( $GLOBALS['wp_object_cache'] ) ) {
                unset( $GLOBALS['wp_object_cache'] );
            }
        } );
    }, PHP_INT_MAX );

    Before and after on wp-login.php, five runs each: 46.504 s before, 0.591 / 0.588 / 0.575 / 0.836 / 0.913 s after. wp-admin 0.875 s, admin-ajax.php 0.61-1.93 s, front-end 0.115 s. No functional regressions; several hours later wp redis status still reports Connected / Valid / Ping 1 / Errors [].

    SUGGESTED FIX

    Close the connection deterministically while the request is still alive, instead of leaving it to PHP’s implicit teardown. Either a close() method on WP_Object_Cache calling redis->close(), invoked from a late shutdown hook, or an explicit release of the object at the end of the request. A __destruct() on its own would still run during the same implicit teardown and probably would not help. An opt-out constant would be a reasonable escape hatch for persistent-connection setups.

    WHAT I COULD NOT DETERMINE

    I could not get inside the blocking call: the container has no CAP_SYS_PTRACE, so strace and /proc/<pid>/syscall were unavailable. My working hypothesis is that when the PhpRedis Redis object is released during PHP’s request shutdown, the socket teardown against an authenticated, TCP, cross-container Redis blocks, and WP_REDIS_TIMEOUT / WP_REDIS_READ_TIMEOUT do not apply on that path. The observed clustering around 6.4 s and at multiples of 10 s is consistent with retransmission backoff, but I cannot prove it.

    Happy to run further instrumentation on this host if that would help narrow it down. Thanks for the plugin.

    The page I need help with: [log in to see the link]

Viewing 1 replies (of 1 total)
  • Plugin Author Till Krüss

    (@tillkruess)

    I assume when you use Predis this issue does not occur? This would be something to report to the PhpRedis repo directly. Please link the GitHub issue in here.

Viewing 1 replies (of 1 total)

You must be logged in to reply to this topic.