bug?

[lichunqiang]

具体现象是：php-fpm打印出所有请求相应时间都很慢，导致服务器无法正常相应，只能通过重启php-fpm来解决。

系统环境：

xhprof

xhprof => 1.0.0
CPU num => 32

apcu

APCu Support => Disabled
Version => 5.1.8
APCu Debugging => Disabled
MMAP Support => Enabled
MMAP File Mask =>
Serialization Support => Disabled
Build Date => Oct 17 2017 19:49:16

php: PHP 7.1.10

gdb打印的调用栈：

#0  0x00000036a620ac50 in pthread_rwlock_wrlock () from /lib64/libpthread.so.0
#1  0x00007ffb746ae1d9 in apc_lock_wlock (lock=<value optimized out>) at /usr/local/src/apcu-5.1.8/apc_lock.c:245
#2  0x00007ffb746b231c in apc_cache_insert (cache=0x1e6d030, key=0x7fffa9b42b70, value=0x7ffb72377e78, ctxt=0x7fffa9b42b10, t=1523733237, exclusive=1 '\001') at /usr/local/src/apcu-5.1.8/apc_cache.c:948
#3  0x00007ffb746b27ec in apc_cache_store (cache=0x1e6d030, strkey=0x7ffb7ab563f0, val=0x7ffb7aa14c00, ttl=0, exclusive=1 '\001') at /usr/local/src/apcu-5.1.8/apc_cache.c:552
#4  0x00007ffb746af430 in apc_store_helper (execute_data=<value optimized out>, return_value=0x7fffa9b42cb0, exclusive=1 '\001') at /usr/local/src/apcu-5.1.8/php_apc.c:495
#5  0x00007ffb72c25ba1 in hp_execute_internal (execute_data=0x7ffb7aa14ba0, return_value=0x7fffa9b42cb0) at /usr/local/src/xhprof-master/extension/xhprof.c:1776
#6  0x00000000008d5dff in ZEND_DO_FCALL_SPEC_RETVAL_UNUSED_HANDLER (execute_data=0x7ffb7aa14b00) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:972
#7  0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#8  0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14b00) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#9  0x00000000008d567c in ZEND_DO_FCALL_SPEC_RETVAL_USED_HANDLER (execute_data=0x7ffb7aa14a70) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:1076
#10 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#11 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14a70) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#12 0x000000000083ec1f in zend_call_function (fci=0x7fffa9b42f20, fci_cache=0x7fffa9b42f60) at /usr/local/src/php-7.1.10/Zend/zend_execute_API.c:855
#13 0x00000000008719aa in zend_call_method (object=0x7ffb7aa62758, obj_ce=<value optimized out>, fn_proxy=<value optimized out>, function_name=0x7ffb7aa02928 "composer\\autoload\\classloader::loadclass\004", function_name_len=44,
    retval_ptr=0x0, param_count=1, arg1=0x7ffb7aa14a60, arg2=0x0) at /usr/local/src/php-7.1.10/Zend/zend_interfaces.c:99
#14 0x00000000006ecfb4 in zif_spl_autoload_call (execute_data=<value optimized out>, return_value=<value optimized out>) at /usr/local/src/php-7.1.10/ext/spl/php_spl.c:420
#15 0x00007ffb72c25ba1 in hp_execute_internal (execute_data=0x7ffb7aa14a10, return_value=0x7fffa9b43250) at /usr/local/src/xhprof-master/extension/xhprof.c:1776
#16 0x000000000083f20b in zend_call_function (fci=0x7fffa9b431e0, fci_cache=0x7fffa9b43220) at /usr/local/src/php-7.1.10/Zend/zend_execute_API.c:871
#17 0x000000000083f599 in zend_lookup_class_ex (name=<value optimized out>, key=0x7ffb69315ce0, use_autoload=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_execute_API.c:1028
#18 0x000000000083f896 in zend_fetch_class_by_name (class_name=0x7ffb69316288, key=<value optimized out>, fetch_type=512) at /usr/local/src/php-7.1.10/Zend/zend_execute_API.c:1463
#19 0x00000000008ead0a in ZEND_INIT_STATIC_METHOD_CALL_SPEC_CONST_CONST_HANDLER (execute_data=0x7ffb7aa14920) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:5479
#20 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#21 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14920) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#22 0x00000000008f5695 in ZEND_INCLUDE_OR_EVAL_SPEC_CONST_HANDLER (execute_data=0x7ffb7aa148d0) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:3479
#23 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#24 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa148d0) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#25 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa147d0) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#26 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#27 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa147d0) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#28 0x00000000008d567c in ZEND_DO_FCALL_SPEC_RETVAL_USED_HANDLER (execute_data=0x7ffb7aa14750) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:1076
#29 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#30 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14750) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#31 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa146e0) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#32 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#33 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa146e0) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#34 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa14670) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#35 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#36 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14670) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#37 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa14600) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#38 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#39 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14600) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#40 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa14590) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#41 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#42 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14590) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#43 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa14520) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#44 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#45 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14520) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#46 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa144b0) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#47 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#48 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa144b0) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#49 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa14440) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#50 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#51 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14440) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#52 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa143d0) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#53 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#54 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa143d0) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#55 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa14360) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#56 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#57 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14360) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#58 0x00000000008f5695 in ZEND_INCLUDE_OR_EVAL_SPEC_CONST_HANDLER (execute_data=0x7ffb7aa14300) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:3479
#59 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#60 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14300) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#61 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa14360) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#62 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#63 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14360) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#64 0x00000000008f5695 in ZEND_INCLUDE_OR_EVAL_SPEC_CONST_HANDLER (execute_data=0x7ffb7aa14300) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:3479
#65 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#66 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14300) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#67 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa14210) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#68 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#69 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14210) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#70 0x00000000008d5c87 in ZEND_DO_FCALL_SPEC_RETVAL_UNUSED_HANDLER (execute_data=0x7ffb7aa14160) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:949
#71 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#72 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14160) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#73 0x00000000008d5c87 in ZEND_DO_FCALL_SPEC_RETVAL_UNUSED_HANDLER (execute_data=0x7ffb7aa140a0) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:949
#74 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#75 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa140a0) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#76 0x00000000008f527c in ZEND_INCLUDE_OR_EVAL_SPEC_TMPVAR_HANDLER (execute_data=0x7ffb7aa14030) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:51699
#77 0x00000000008b1e38 in execute_ex (ex=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:432
#78 0x00007ffb72c273a1 in hp_execute_ex (execute_data=0x7ffb7aa14030) at /usr/local/src/xhprof-master/extension/xhprof.c:1749
#79 0x0000000000904bc5 in zend_execute (op_array=<value optimized out>, return_value=<value optimized out>) at /usr/local/src/php-7.1.10/Zend/zend_vm_execute.h:474
#80 0x000000000084e734 in zend_execute_scripts (type=8, retval=0x0, file_count=3) at /usr/local/src/php-7.1.10/Zend/zend.c:1480
#81 0x00000000007daf00 in php_execute_script (primary_file=0x7fffa9b46710) at /usr/local/src/php-7.1.10/main/main.c:2552
#82 0x000000000091255e in main (argc=<value optimized out>, argv=<value optimized out>) at /usr/local/src/php-7.1.10/sapi/fpm/fpm/fpm_main.c:1966

[longxinH]

@lichunqiang 是开启了apcu才会出现这种情况吗？

[lichunqiang]

@longxinH 嗯，是的.

目前从日志看来，php慢日志最后几个都是在apcu_store, 之后再无慢日志写入。

只有php-fpm.log 刷屏的执行超时而退出

[longxinH]

@lichunqiang 不好意思，最近公司任务比较忙，周末抽时间看看

[longxinH]

@lichunqiang 我这边无法重现出来，你能提供一个能重现的例子吗？ 我的配置如下

php.ini
extension = apcu.so
apc.enabled= on
apc.shm_size= 64M
apc.enable_cli = on

test.php
xhprof_enable();
$bar = 'BAR';
apcu_store('foo', $bar);
apcu_fetch('foo');
xhprof_disable();

[lichunqiang]

尝试过重现，但是失败了，无法重现.

应该是和代码有关系，因为业务代码中大量使用了apcu做共享内存使用。

xhprof_enable(XHPROF_FLAGS_CPU | XHPROF_FLAGS_MEMORY);
... 各个组件都有使用到apcu
xhprof_disable();

单单抽出部分代码确实无法重现。。。

从日志初步分析: slow log: 最后的日志停在 apcu_store (最后N个记录都是)，是不是xhprof在收集信息的时候遇到了这个阻塞（？猜测的状态）方法执行导致的呢

[longxinH]

@lichunqiang 从你提供的gdb看，貌似是执行了pthread_rwlock_wrlock之后就卡住了，猜测是进程锁导致了

#0  0x00000036a620ac50 in pthread_rwlock_wrlock () from /lib64/libpthread.so.0
#1  0x00007ffb746ae1d9 in apc_lock_wlock (lock=<value optimized out>) at /usr/local/src/apcu-5.1.8/apc_lock.c:245

[longxinH]

@lichunqiang 我这边重现不出来，也无法断点调试

[lichunqiang]

@longxinH 嗯，目前看来无法通过几行代码就能复现。我们线上环境的机器也不是每次都复现这种情况，只是偶尔出现这个问题。

已经和运维商量了，下次在出现这种情况，先不要做php重启操作，先将机器摘掉，保存现场。这样就有环境进行复现了。

有进展会及时同步，另外有什么其他建议需要注意的么

[longxinH]

@lichunqiang 谢谢你的帮助。如果可以的话最好能生成core_dump，这样能更好的定位