apcu_inc stucks on pthread_rwlock_wrlock

[gaohuia]

Hi I met this issue twice these days. We have two servers, the issue exists on both of them. New requests were just blocked and end with 504.

GDB:

(gdb) bt
#0  0x00007ff20217c2be in pthread_rwlock_wrlock () from /lib64/libpthread.so.0
#1  0x00007ff1e1d19b80 in apc_lock_wlock_impl (lock=<optimized out>) at /tmp/pear/temp/apcu/apc_lock.c:103
#2  apc_lock_wlock (lock=<optimized out>) at /tmp/pear/temp/apcu/apc_lock.c:324
#3  0x00007ff1e1d1d214 in apc_cache_store (cache=cache@entry=0x55e43df6b1a0, key=key@entry=0x7ff1f32705c0, val=val@entry=0x7ffd663118f0, ttl=ttl@entry=0, exclusive=exclusive@entry=1 '\001')
    at /tmp/pear/temp/apcu/apc_cache.c:507
#4  0x00007ff1e1d1dbab in apc_cache_atomic_update_long (cache=0x55e43df6b1a0, key=0x7ff1f32705c0, updater=updater@entry=0x7ff1e1d1a0f0 <php_inc_updater>, data=data@entry=0x7ffd66311960, 
    insert_if_not_found=1 '\001', ttl=0) at /tmp/pear/temp/apcu/apc_cache.c:938
#5  0x00007ff1e1d1b802 in php_apc_update (key=<optimized out>, updater=updater@entry=0x7ff1e1d1a0f0 <php_inc_updater>, data=data@entry=0x7ffd66311960, 
    insert_if_not_found=insert_if_not_found@entry=1 '\001', ttl=<optimized out>) at /tmp/pear/temp/apcu/php_apc.c:443
#6  0x00007ff1e1d1b884 in zif_apcu_inc (execute_data=<optimized out>, return_value=0x7ffd663119d0) at /tmp/pear/temp/apcu/php_apc.c:547
#7  0x00007ff1f2d47c5d in xdebug_execute_internal (current_execute_data=0x7ff1f322b7d0, return_value=0x7ffd663119d0) at /tmp/pear/temp/xdebug/src/base/base.c:466
#8  0x00007ff1f413825e in ?? () from /etc/httpd/modules/libphp-7.3.so
#9  0x00007ff1f43a728f in execute_ex () from /etc/httpd/modules/libphp-7.3.so
#10 0x00007ff1f2d4734f in xdebug_execute_ex (execute_data=0x7ff1f322b700) at /tmp/pear/temp/xdebug/src/base/base.c:380
#11 0x00007ff1f41381ed in ?? () from /etc/httpd/modules/libphp-7.3.so
#12 0x00007ff1f43a728f in execute_ex () from /etc/httpd/modules/libphp-7.3.so
#13 0x00007ff1f2d4734f in xdebug_execute_ex (execute_data=0x7ff1f322b5b0) at /tmp/pear/temp/xdebug/src/base/base.c:380
#14 0x00007ff1f413851c in ?? () from /etc/httpd/modules/libphp-7.3.so
#15 0x00007ff1f43a728f in execute_ex () from /etc/httpd/modules/libphp-7.3.so
#16 0x00007ff1f2d4734f in xdebug_execute_ex (execute_data=0x7ff1f322b380) at /tmp/pear/temp/xdebug/src/base/base.c:380
#17 0x00007ff1f413851c in ?? () from /etc/httpd/modules/libphp-7.3.so
#18 0x00007ff1f43a728f in execute_ex () from /etc/httpd/modules/libphp-7.3.so
#19 0x00007ff1f2d4734f in xdebug_execute_ex (execute_data=0x7ff1f322af60) at /tmp/pear/temp/xdebug/src/base/base.c:380
#20 0x00007ff1f413851c in ?? () from /etc/httpd/modules/libphp-7.3.so
#21 0x00007ff1f43a728f in execute_ex () from /etc/httpd/modules/libphp-7.3.so
#22 0x00007ff1f2d4734f in xdebug_execute_ex (execute_data=0x7ff1f322add0) at /tmp/pear/temp/xdebug/src/base/base.c:380
#23 0x00007ff1f413851c in ?? () from /etc/httpd/modules/libphp-7.3.so
#24 0x00007ff1f43a728f in execute_ex () from /etc/httpd/modules/libphp-7.3.so
#25 0x00007ff1f2d4734f in xdebug_execute_ex (execute_data=0x7ff1f322ace0) at /tmp/pear/temp/xdebug/src/base/base.c:380
#26 0x00007ff1f413851c in ?? () from /etc/httpd/modules/libphp-7.3.so
#27 0x00007ff1f43a728f in execute_ex () from /etc/httpd/modules/libphp-7.3.so
#28 0x00007ff1f2d4734f in xdebug_execute_ex (execute_data=0x7ff1f322a5b0) at /tmp/pear/temp/xdebug/src/base/base.c:380
#29 0x00007ff1f413851c in ?? () from /etc/httpd/modules/libphp-7.3.so
#30 0x00007ff1f43a728f in execute_ex () from /etc/httpd/modules/libphp-7.3.so
#31 0x00007ff1f2d4734f in xdebug_execute_ex (execute_data=0x7ff1f3229870) at /tmp/pear/temp/xdebug/src/base/base.c:380
#32 0x00007ff1f43a1479 in ?? () from /etc/httpd/modules/libphp-7.3.so
#33 0x00007ff1f43a728f in execute_ex () from /etc/httpd/modules/libphp-7.3.so
#34 0x00007ff1f2d4734f in xdebug_execute_ex (execute_data=0x7ff1f3223640) at /tmp/pear/temp/xdebug/src/base/base.c:380
#35 0x00007ff1f43a1479 in ?? () from /etc/httpd/modules/libphp-7.3.so
#36 0x00007ff1f43a728f in execute_ex () from /etc/httpd/modules/libphp-7.3.so
#37 0x00007ff1f2d4734f in xdebug_execute_ex (execute_data=0x7ff1f3223460) at /tmp/pear/temp/xdebug/src/base/base.c:380
#38 0x00007ff1f43a1479 in ?? () from /etc/httpd/modules/libphp-7.3.so
#39 0x00007ff1f43a728f in execute_ex () from /etc/httpd/modules/libphp-7.3.so
#40 0x00007ff1f2d4734f in xdebug_execute_ex (execute_data=0x7ff1f3222030) at /tmp/pear/temp/xdebug/src/base/base.c:380
#41 0x00007ff1f43af3f8 in zend_execute () from /etc/httpd/modules/libphp-7.3.so
#42 0x00007ff1f432a004 in zend_execute_scripts () from /etc/httpd/modules/libphp-7.3.so
---Type <return> to continue, or q <return> to quit---
#43 0x00007ff1f42ccc50 in php_execute_script () from /etc/httpd/modules/libphp-7.3.so
#44 0x00007ff1f43b155a in ?? () from /etc/httpd/modules/libphp-7.3.so
#45 0x000055e43b98f910 in ap_run_handler ()
#46 0x000055e43b98fe59 in ap_invoke_handler ()
#47 0x000055e43b9a534c in ap_internal_redirect ()
#48 0x00007ff1f9db8f6c in ?? () from /etc/httpd/modules/mod_rewrite.so
#49 0x000055e43b98f910 in ap_run_handler ()
#50 0x000055e43b98fe59 in ap_invoke_handler ()
#51 0x000055e43b9a602a in ap_process_async_request ()
#52 0x000055e43b9a62fe in ap_process_request ()
#53 0x000055e43b9a23c5 in ?? ()
#54 0x000055e43b9994a0 in ap_run_process_connection ()
#55 0x00007ff1f6ff79d9 in ?? () from /etc/httpd/modules/mod_mpm_prefork.so
#56 0x00007ff1f6ff7c20 in ?? () from /etc/httpd/modules/mod_mpm_prefork.so
#57 0x00007ff1f6ff8a26 in ?? () from /etc/httpd/modules/mod_mpm_prefork.so
#58 0x000055e43b9710ee in ap_run_mpm ()
#59 0x000055e43b969509 in main ()
(gdb) x/s 0x7ff1f32705c0+24
0x7ff1f32705d8:	"/rest/v2/test/123/simplememcachebuster"
(gdb) 

PHP Version: PHP 7.3.21

# uname -a
Linux pa-webapi 4.14.47-56.37.amzn1.x86_64 #1 SMP Wed Jun 6 18:49:01 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

apcu version 5.1.18

[nikic]

Usual question: Is it possible that an opcache restart occurred before the deadlock? (An "Attempting to kill locker" in opcache log at opcache.log_verbosity_level=2.)

[gaohuia]

I can now easily reproduce the issue. Just restart the httpd and send it a request ..

I set the opcache.log_verbosity_level=4 and only see the following logs while the deadlock occurs.

Fri Feb  5 03:06:00 2021 (14769): Debug Loading blacklist file:  '/etc/php-7.3.d/opcache-default.blacklist'

[gaohuia]

@nikic I finally figured out the minimal code to reproduce the issue.

<?php

header("Content-Type: text/plain");

function request_identifier()
{
  return apcu_entry("started_at", function(){return time();}, 999999) . apcu_inc('index');
}

$v = apcu_entry("HELLO", function(){
    return request_identifier() . ' hello';
}, 3600);

echo 'value: '. $v, "\n";

echo 'success';

Steps:

0. Save the code above into a php file, naming it "test.php"
1. Run a PHP server in the directory. (I could reproduce on both httpd and the php internal http server )

php -S 127.0.0.1:8003

2. Curl it with

curl 127.0.0.1:8003/test.php

3. Curl it again, with the same curl command.

Result: dead locked.

[nikic]

See the documentation for apcu_entry (https://www.php.net/apcu_entry):

Note: When control enters apcu_entry() the lock for the cache is acquired exclusively, it is released when control leaves apcu_entry(): In effect, this turns the body of generator into a critical section, disallowing two processes from executing the same code paths concurrently. In addition, it prohibits the concurrent execution of any other APCu functions, since they will acquire the same lock.

Warning: The only APCu function that can be called safely by generator is apcu_entry().

Calling any apcu function inside apcu_entry will indeed deadlock (at least when using rwlocks).

I think it's time to deprecate this function and replace it with one that doesn't guarantee a critical section.

[gaohuia]

I see. Thank you. Do you think it's a good idea/possible to report a fatal error in this scenario? The function that guarantee a critical section is sometimes useful in my mind.

The generator in our code is a function to fetch some data from the model layer which is a little deep, such that some other apcu function is involved unfortunately.

[nikic]

@gaohuia I've pushed 61f3c16, which adds checks for read lock failure. This should throw a warning and avoid a deadlock, at least if posix rwlocks are used. For your example, under --repeat 2:

Executing for the first time...

Warning: apcu_inc(): Failed to acquire read lock in /home/nikic/php/php-src/t225.php on line 6
value: 1612700173 hello
success
Finished execution, repeating...
value: 1612700173 hello
success

[nikic]

After 6e73f57, it should be safe to call other apcu_* functions inside apcu_entry().

[chrisddwrt]

Hi,

we are running into deadlocks on debian10 / litespeed with lsphp + plesk-php7.3 + acpu 5.1.19.

I can reproduce the locks with your short php-script.

is this case related to #410 and might your patch fix this issue too?

I use now master ( 6e73f57 ) and can't break the server anymore.

I will report if the shopware installation is now working without breaking.

[nikic]

https://github.com/krakjoe/apcu/releases/tag/v5.1.20 with a fix for this issue has been released. Please tell me if you still encounter problems.