Open chris-lee-lb opened 2 years ago
And here are some debug & trace logs
====== flag : SWOOLE_HOOK_FILE ======
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=160, size=152
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:32:26 @718.0] TRACE Table::get_memory_size(:113): _memory_size=35248, _row_num=307, _row_memory_size=104
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=160, size=152
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:32:26 @718.0] TRACE Table::get_memory_size(:113): _memory_size=12415936, _row_num=1228, _row_memory_size=10100
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=160, size=152
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:32:26 @718.0] TRACE Table::get_memory_size(:113): _memory_size=1363936, _row_num=1228, _row_memory_size=1100
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:32:26 @718.0] TRACE ServerObject::on_before_start(:1017): Create Server: host=0.0.0.0, port=80, mode=2, type=1
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=280, size=272
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:32:26 @718.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:32:26 @718.0] TRACE ReactorEpoll::add(:107): add events[fd=23#0, type=9, events=512]
[2021-12-21 11:32:26 @718.0] TRACE ReactorEpoll::add(:107): add events[fd=8#0, type=1, events=512]
[2021-12-21 11:32:26 #718.2] TRACE Timer::add(:144): id=1, exec_msec=1000, msec=1000, round=0, exist=1
[2021-12-21 11:32:26 #718.1] TRACE ReactorEpoll::add(:107): add events[fd=17#1, type=3, events=512]
[2021-12-21 11:32:26 #718.0] TRACE ReactorEpoll::add(:107): add events[fd=15#0, type=3, events=512]
[2021-12-21 11:32:26 #718.2] TRACE Context::Context(:53): alloc stack: size=2097152, ptr=0x7fb08d146150
[2021-12-21 11:32:26 #718.2] TRACE PHPCoroutine::main_func(:766): Create coro id: 1, origin cid: -1, coro total count: 1, heap size: 2298504
[2021-12-21 11:32:26 #718.2] TRACE ReactorEpoll::add(:107): add events[fd=26#2, type=5, events=512]
[2021-12-21 11:32:26 #718.2] DEBUG ThreadPool::dispatch(:155): push and notify one: 1640086346.199556
[2021-12-21 11:32:26 #718.2] TRACE PHPCoroutine::on_yield(:609): from cid=1 to cid=-1
[2021-12-21 11:32:26 @725.0] TRACE ReactorEpoll::add(:107): add events[fd=16#0, type=3, events=512]
[2021-12-21 11:32:26 *725.1] TRACE ReactorEpoll::add(:107): add events[fd=24#0, type=9, events=512]
[2021-12-21 11:32:26 @724.0] TRACE ReactorEpoll::add(:107): add events[fd=14#0, type=3, events=512]
[2021-12-21 11:32:26 *725.1] TRACE Context::Context(:53): alloc stack: size=2097152, ptr=0x7fb08cbff0c0
[2021-12-21 11:32:26 *725.1] TRACE PHPCoroutine::main_func(:766): Create coro id: 1, origin cid: -1, coro total count: 1, heap size: 2298504
[2021-12-21 11:32:26 *724.0] TRACE ReactorEpoll::add(:107): add events[fd=24#0, type=9, events=512]
[2021-12-21 11:32:26 *724.0] TRACE Context::Context(:53): alloc stack: size=2097152, ptr=0x7fb08cbff0c0
[2021-12-21 11:32:26 *724.0] TRACE PHPCoroutine::main_func(:766): Create coro id: 1, origin cid: -1, coro total count: 1, heap size: 2298504
[2021-12-21 11:32:26 #718.0] DEBUG ThreadPool::create_thread(:241): pop 1 event: 1640086346.215266
[2021-12-21 11:32:26 #718.0] TRACE ThreadPool::create_thread(:254): aio_thread failed. ret=0, error=22
[2021-12-21 11:32:26 #718.0] DEBUG ThreadPool::create_thread(:241): no event: 1640086346.215356
[2021-12-21 11:32:26 #718.0] DEBUG ThreadPool::create_thread(:241): no event: 1640086346.215607
[2021-12-21 11:32:26 $719.0] TRACE Server::kill_event_workers(:632): [Manager]kill worker processor
[2021-12-21 11:32:26 $719.0] TRACE Server::kill_event_workers(:632): [Manager]kill worker processor
[2021-12-21 11:32:26 *725.1] TRACE PHPCoroutine::on_close(:667): coro close cid=1 and resume to -1, 0 remained. usage size: 3768088. malloc size: 2097152
[2021-12-21 11:32:26 *725.1] TRACE Context::~Context(:90): free stack: ptr=0x7fb08cbff0c0
[2021-12-21 11:32:26 *725.1] TRACE ReactorEpoll::del(:128): remove event[reactor_id=0|fd=16]
[2021-12-21 11:32:26 *725.1] TRACE ReactorEpoll::del(:128): remove event[reactor_id=0|fd=24]
[2021-12-21 11:32:26 *724.0] TRACE PHPCoroutine::on_close(:667): coro close cid=1 and resume to -1, 0 remained. usage size: 3767128. malloc size: 2097152
[2021-12-21 11:32:26 *724.0] TRACE Context::~Context(:90): free stack: ptr=0x7fb08cbff0c0
[2021-12-21 11:32:26 *724.0] TRACE ReactorEpoll::del(:128): remove event[reactor_id=0|fd=14]
[2021-12-21 11:32:26 *724.0] TRACE ReactorEpoll::del(:128): remove event[reactor_id=0|fd=24]
====== flag : SWOOLE_HOOK_STDIO ======
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=160, size=152
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:50:32 @945.0] TRACE Table::get_memory_size(:113): _memory_size=35248, _row_num=307, _row_memory_size=104
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=160, size=152
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:50:32 @945.0] TRACE Table::get_memory_size(:113): _memory_size=12415936, _row_num=1228, _row_memory_size=10100
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=160, size=152
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:50:32 @945.0] TRACE Table::get_memory_size(:113): _memory_size=1363936, _row_num=1228, _row_memory_size=1100
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:50:32 @945.0] TRACE ServerObject::on_before_start(:1017): Create Server: host=0.0.0.0, port=80, mode=2, type=1
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=280, size=272
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:50:32 @945.0] TRACE GlobalMemory::alloc(:96): alloc_size=56, size=48
[2021-12-21 11:50:32 @945.0] TRACE ReactorEpoll::add(:107): add events[fd=23#0, type=9, events=512]
[2021-12-21 11:50:32 @945.0] TRACE ReactorEpoll::add(:107): add events[fd=8#0, type=1, events=512]
[2021-12-21 11:50:32 #945.2] TRACE Timer::add(:144): id=1, exec_msec=1000, msec=1000, round=0, exist=1
[2021-12-21 11:50:32 #945.0] TRACE ReactorEpoll::add(:107): add events[fd=15#0, type=3, events=512]
[2021-12-21 11:50:32 #945.1] TRACE ReactorEpoll::add(:107): add events[fd=17#1, type=3, events=512]
[2021-12-21 11:50:32 #945.2] TRACE Context::Context(:53): alloc stack: size=2097152, ptr=0x7f28f55ff150
[2021-12-21 11:50:32 #945.2] TRACE PHPCoroutine::main_func(:766): Create coro id: 1, origin cid: -1, coro total count: 1, heap size: 2298504
[2021-12-21 11:50:32 #945.2] TRACE ReactorEpoll::add(:107): add events[fd=27#2, type=5, events=512]
[2021-12-21 11:50:32 #945.2] DEBUG ThreadPool::dispatch(:155): push and notify one: 1640087432.947014
[2021-12-21 11:50:32 #945.2] TRACE PHPCoroutine::on_yield(:609): from cid=1 to cid=-1
[2021-12-21 11:50:32 @951.0] TRACE ReactorEpoll::add(:107): add events[fd=14#0, type=3, events=512]
[2021-12-21 11:50:32 *951.0] TRACE ReactorEpoll::add(:107): add events[fd=24#0, type=9, events=512]
[2021-12-21 11:50:32 *951.0] TRACE Context::Context(:53): alloc stack: size=2097152, ptr=0x7f28f10350c0
[2021-12-21 11:50:32 *951.0] TRACE PHPCoroutine::main_func(:766): Create coro id: 1, origin cid: -1, coro total count: 1, heap size: 2298504
[2021-12-21 11:50:32 *951.0] TRACE ReactorEpoll::add(:107): add events[fd=26#0, type=5, events=512]
[2021-12-21 11:50:32 *951.0] DEBUG ThreadPool::dispatch(:155): push and notify one: 1640087432.951944
[2021-12-21 11:50:32 *951.0] TRACE PHPCoroutine::on_yield(:609): from cid=1 to cid=-1
[2021-12-21 11:50:32 @952.0] TRACE ReactorEpoll::add(:107): add events[fd=16#0, type=3, events=512]
[2021-12-21 11:50:32 *952.1] TRACE ReactorEpoll::add(:107): add events[fd=24#0, type=9, events=512]
[2021-12-21 11:50:32 *952.1] TRACE Context::Context(:53): alloc stack: size=2097152, ptr=0x7f28f10350c0
[2021-12-21 11:50:32 *952.1] TRACE PHPCoroutine::main_func(:766): Create coro id: 1, origin cid: -1, coro total count: 1, heap size: 2298504
[2021-12-21 11:50:32 *952.1] TRACE ReactorEpoll::add(:107): add events[fd=26#0, type=5, events=512]
[2021-12-21 11:50:32 *952.1] DEBUG ThreadPool::dispatch(:155): push and notify one: 1640087432.972077
[2021-12-21 11:50:32 *952.1] TRACE PHPCoroutine::on_yield(:609): from cid=1 to cid=-1
[2021-12-21 11:50:32 $946.0] TRACE Server::kill_event_workers(:632): [Manager]kill worker processor
[2021-12-21 11:50:32 $946.0] TRACE Server::kill_event_workers(:632): [Manager]kill worker processor
[2021-12-21 11:50:32 *951.0] DEBUG ThreadPool::create_thread(:241): pop 1 event: 1640087432.976708
[2021-12-21 11:50:32 *951.0] TRACE ThreadPool::create_thread(:254): aio_thread failed. ret=0, error=22
[2021-12-21 11:50:32 *951.0] DEBUG ThreadPool::create_thread(:241): no event: 1640087432.976968
[2021-12-21 11:50:32 *951.0] DEBUG ThreadPool::create_thread(:241): no event: 1640087432.987384
[2021-12-21 11:50:32 *952.1] DEBUG ThreadPool::create_thread(:241): pop 1 event: 1640087432.988448
[2021-12-21 11:50:32 *952.1] TRACE ThreadPool::create_thread(:254): aio_thread failed. ret=0, error=22
[2021-12-21 11:50:32 *952.1] DEBUG ThreadPool::create_thread(:241): no event: 1640087432.988541
[2021-12-21 11:50:32 *952.1] DEBUG ThreadPool::create_thread(:241): no event: 1640087432.988582
And another information that may be helpful, It was successfully running if I turn off OPCache extension.
I use OPCache with preload feature. My preload file is located in root dir preload.php
Why do you need preload with Swoole?
Your code only loads once on server start.
@ValiDrv it's less about why, but more about how it works with PHP 8.0 and not on PHP 8.1.
I can confirm that just having opcache extension installed causes worker crashes for me too. I guess opcache probably isn't necessary, but I had it enabled out of habit from other projects. It should probably be noted somewhere in the documentation that these two extensions aren't compatible.
Please answer these questions before submitting your issue. Thanks!
I use swoole with this laravel extension - laravel/octane (https://laravel.com/docs/8.x/octane)
We've adjust all the swoole configs in
config/octane.php
github repository which contains reproducing scripts : https://github.com/chris-lee-lb/swoole-debug-2021-12-21 docker image which contains reproducing scripts : https://hub.docker.com/r/protosschris/swoole-debug-2021-12-21
and then you run docker instance with :
docker run -d -e "PHP_OPCACHE_ENABLED=true" --name test -p 80:80 protosschris/swoole-debug-2021-12-21:debug
and for test curl routes :
curl -vvv 'http://localhost'
Successfully running.
Crashed.
php --ri swoole
)?uname -a
&php -v
&gcc -v
) ?PS : I can successfully running for docker for mac with my Mac Pro, but crashed with GCP GKE 1.20.10-gke.1600