10、Workerman 基本使用 - 调试 - 基本调试 & 运行状态

作者: 温新

图书: 【Workerman 基本使用】

阅读: 159

时间: 2024-04-23 10:23:17

hi,我是温新,一名 PHPer

基本调试

到现在为止,一直使用的是 php start.php start,此时,代码中使用 echo、var_dump、print_r 等函数时,信息会在服务终端中显示。

但是在实际的生产环境,都是使用 daemon 模式,此时呢,echo 这些函数就不好使了。

解决方法,把调试信息写入到文件中,使用 Worker::$stdoutFile 属性设置。

<?php
/**
 * debug.php
 *
 * 调试 - 基本调试
 */

use Workerman\Worker;
use Workerman\Connection\TcpConnection;

require_once __DIR__ . '/vendor/autoload.php';

// 将屏幕打印输出到 Worker::$stdoutFile 指定的文件中
Worker::$stdoutFile = '/tmp/workerman/workerman.log';

$worker = new Worker('tcp://0.0.0.0:8888');

$worker->count = 8;

$worker->name = 'debug-php';

$worker->onMessage = function (TcpConnection $connection, $data) {
    while (true) {
        sleep(1);
        $connection->send('hello world');
    }
};

Worker::runAll();

1、启动服务端

$ php debug.php start -d

2、客户端连接

$ telnet 127.0.0.1 8888
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
1
hello world^C

3、查看记录文件

$ cat /tmp/workerman/workerman.log 
hellohellohello

查看运行状态

使用 status 可以查看服务运行状态:

$ php debug.php status
Workerman[debug.php] status 
----------------------------------------------GLOBAL STATUS----------------------------------------------------
Workerman version:4.1.15          PHP version:8.2.0
start time:2024-03-01 08:56:22   run 0 days 0 hours   
load average: 1.18, 1.28, 1.25   event-loop:\Workerman\Events\Event
1 workers       8 processes
worker_name  exit_status      exit_count
debug-php    0                0
----------------------------------------------PROCESS STATUS---------------------------------------------------
pid     memory  listening          worker_name  connections send_fail timers  total_request qps    status
50490   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
50491   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
50492   N/A     tcp://0.0.0.0:8888 debug-php    N/A         N/A       N/A     N/A           N/A    [busy] 
50493   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
50494   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
50495   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
50496   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
50497   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
----------------------------------------------PROCESS STATUS---------------------------------------------------
Summary 14M     -                  -            0           0         0       0             0      [Summary]

从输出中,可以看到,信息分为了两大块:GLOBAL STATUSPROCESS STATUS,它们的含义如下:

GLOBAL STATUS

字段 含义
Workerman version Workerman 版本
PHP version PHP 版本
start time 服务启动时间
run 服务运行时长
load average 服务器负载,最近 1 分钟、5 分钟、15 分钟内系统的平均负载
event-loop 使用的 IO 事件库
1 workers 工作的哪种进程。3 种进程,包括 ChatGateway、ChatBusinessWorker、Register 进程、WebServer 进程
8 processes 8 个进程
worker_name worker 进程名称
exit_status worker 进程退出状态码
exit_count 该状态码的退出次数

PROCESS STATUS

字段 含义
pid 进程 PID
memory 该进程当前占用内存
listening 传输层协议及监听 ip 端口
worker_name 该进程运行的服务服务名
connections 该进程当前有多少个 TCP 连接实例
total_request 表示该进程从启动到现在一共接收了多少个请求
send_fail 该进程向客户端发送数据失败次数
timers 该进程活动的定时器数量
qps 当前进程每秒收到的网络请求数

需要注意显示 busy 的进程,这是由于进程忙于处理业务,无法上报状态,导致显示 busy

调试 busy 进程

通过 php start.php status 可以查看到 busy 状态的进程,进程处理完成任务后,正常情况下状态会恢复为 idle,若没有恢复,则说明进程内的业务存在阻塞或者无限循环。可以利用 strace + lsof 定位问题。

1、查找 busy 进程的 PID

$ php debug.php status
Workerman[debug.php] status 
----------------------------------------------GLOBAL STATUS----------------------------------------------------
Workerman version:4.1.15          PHP version:8.2.0
start time:2024-03-01 08:56:22   run 0 days 0 hours   
load average: 1.18, 1.28, 1.25   event-loop:\Workerman\Events\Event
1 workers       8 processes
worker_name  exit_status      exit_count
debug-php    0                0
----------------------------------------------PROCESS STATUS---------------------------------------------------
pid     memory  listening          worker_name  connections send_fail timers  total_request qps    status
50490   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
50491   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
50492   N/A     tcp://0.0.0.0:8888 debug-php    N/A         N/A       N/A     N/A           N/A    [busy] 
50493   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
50494   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
50495   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
50496   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
50497   2.11M   tcp://0.0.0.0:8888 debug-php    0           0         0       0             0      [idle]
----------------------------------------------PROCESS STATUS---------------------------------------------------
Summary 14M     -                  -            0           0         0       0             0      [Summary]

可以看到 50492 的进程为 busy 状态。

2、strace 跟踪进程

$ sudo strace -ttp 50492
strace: Process 50492 attached
16:58:03.822573 restart_syscall(<... resuming interrupted read ...>) = 0
16:58:04.542515 sendto(8, "hello world", 11, 0, NULL, 0) = 11
16:58:04.542850 nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffd0542b850) = 0
16:58:05.543068 sendto(8, "hello world", 11, 0, NULL, 0) = 11
16:58:05.543233 nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffd0542b850) = 0
16:58:06.543439 sendto(8, "hello world", 11, 0, NULL, 0) = 11
16:58:06.543615 nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffd0542b850) = 0
16:58:07.543777 sendto(8, "hello world", 11, 0, NULL, 0) = 11
16:58:07.543921 nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffd0542b850) = 0
16:58:08.544131 sendto(8, "hello world", 11, 0, NULL, 0) = 11
16:58:08.544340 nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffd0542b850) = 0
16:58:09.544528 sendto(8, "hello world", 11, 0, NULL, 0) = 11
16:58:09.544697 nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffd0542b850) = 0
16:58:10.544912 sendto(8, "hello world", 11, 0, NULL, 0) = 11
16:58:10.545088 nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffd0542b850) = 0
16:58:11.545365 sendto(8, "hello world", 11, 0, NULL, 0) = 11
16:58:11.545631 nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffd0542b850) = 0
16:58:12.545820 sendto(8, "hello world", 11, 0, NULL, 0) = 11
16:58:12.545947 nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffd0542b850) = 0
16:58:13.546100 sendto(8, "hello world", 11, 0, NULL, 0) = 11
  1. strace: Process 50492 attached:表明 strace 成功附加到了 PID 为 50492 的进程中,开始对其进行追踪。
  2. restart_syscall(<... resuming interrupted read ...>) = 0:表示进程正在进行或恢复了一个被中断的系统调用(可能是 read 系统调用)。这里的返回值 0 通常表示成功完成。
  3. sendto(8, "hello world", 11, 0, NULL, 0) = 11:显示了该进程在进行sendto系统调用,向文件描述符为 8 的套接字发送了 "hello world" 字符串,长度为 11 个字节,并且成功发送了所有数据。
  4. nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffd0542b850) = 0:表示进程调用了nanosleep函数进行休眠,参数指定休眠时间为 1 秒(tv_sec=1),没有纳秒级别的精度要求(tv_nsec=0)。调用成功返回 0,意味着进程已按照指定时间休眠。

3、lsof 查看进程描述符

$ lsof -nPp 50492
lsof: WARNING: can't stat() vfat file system /boot/efi
      Output information may be incomplete.
lsof: WARNING: can't stat() overlay file system /var/lib/docker/overlay2/ba08094c7c9c86fdb87ddf0cd48231699252e75e3b106be2648df826522c8361/merged
      Output information may be incomplete.
lsof: WARNING: can't stat() nsfs file system /run/docker/netns/ac008c9c7c90
      Output information may be incomplete.
COMMAND   PID    USER   FD      TYPE DEVICE SIZE/OFF     NODE NAME
php     50492 codeing  cwd       DIR  259,5     4096 21764569 /www/workerman/wm-study
php     50492 codeing  rtd       DIR  259,4     4096        2 /
php     50492 codeing  txt       REG  259,4 67557976  6822479 /usr/local/php-8.2.0/bin/php
php     50492 codeing  DEL       REG    0,1             29700 /dev/zero
php     50492 codeing  mem       REG  259,4 54818560  6822491 /usr/local/php-8.2.0/lib/php/extensions/no-debug-non-zts-20220829/swoole.so
php     50492 codeing  mem       REG  259,4    55792  3933503 /usr/lib/x86_64-linux-gnu/libnss_files-2.28.so
php     50492 codeing  mem       REG  259,4    89016  3933497 /usr/lib/x86_64-linux-gnu/libnsl-2.28.so
php     50492 codeing  mem       REG  259,4   231440  3938808 /usr/lib/x86_64-linux-gnu/libevent_core-2.1.so.6.0.2
php     50492 codeing  mem       REG  259,4 10984352  3279225 /usr/lib/locale/locale-archive
php     50492 codeing  mem       REG  259,4   145712  3938812 /usr/lib/x86_64-linux-gnu/libevent_extra-2.1.so.6.0.2
php     50492 codeing  mem       REG  259,4    47608  3933507 /usr/lib/x86_64-linux-gnu/libnss_nis-2.28.so
php     50492 codeing  mem       REG  259,4    39736  3933499 /usr/lib/x86_64-linux-gnu/libnss_compat-2.28.so
php     50492 codeing  mem       REG  259,4  1246320  6822703 /usr/local/php-8.2.0/lib/php/extensions/no-debug-non-zts-20220829/event.so
php     50492 codeing  mem       REG  259,4   485272  3407880 /usr/local/lib/libsodium.so.23.3.0
php     50492 codeing  mem       REG  259,4    74688  3935248 /usr/lib/x86_64-linux-gnu/libbz2.so.1.0.4
php     50492 codeing  mem       REG  259,4   114224  3937193 /usr/lib/x86_64-linux-gnu/libzip.so.4.0
php     50492 codeing  mem       REG  259,4   500088  6822544 /usr/local/php-8.2.0/lib/php/extensions/no-debug-non-zts-20220829/sodium.so
php     50492 codeing  mem       REG  259,4   137520  3935235 /usr/lib/x86_64-linux-gnu/libbrotlicommon.so.1.0.7
php     50492 codeing  mem       REG  259,4    30632  3938820 /usr/lib/x86_64-linux-gnu/libevent_openssl-2.1.so.6.0.2
php     50492 codeing  mem       REG  259,4   575560  3935239 /usr/lib/x86_64-linux-gnu/libbrotlienc.so.1.0.7
php     50492 codeing  mem       REG  259,4    96760  6822555 /usr/local/php-8.2.0/lib/php/extensions/no-debug-non-zts-20220829/sysvmsg.so
php     50492 codeing  mem       REG  259,4   485624  6822537 /usr/local/php-8.2.0/lib/php/extensions/no-debug-non-zts-20220829/zip.so
php     50492 codeing  mem       REG  259,4  3778696  6822486 /usr/local/php-8.2.0/lib/php/extensions/no-debug-non-zts-20220829/redis.so
php     50492 codeing  mem       REG  259,4   200752  3279208 /usr/lib/locale/C.UTF-8/LC_CTYPE
php     50492 codeing  mem       REG  259,4    35224  3935553 /usr/lib/x86_64-linux-gnu/libffi.so.6.0.4
php     50492 codeing  mem       REG  259,4   137424  3935769 /usr/lib/x86_64-linux-gnu/libgpg-error.so.0.26.1
php     50492 codeing  mem       REG  259,4  1236720  3936516 /usr/lib/x86_64-linux-gnu/libp11-kit.so.0.3.0
php     50492 codeing  mem       REG  259,4   113392  3936766 /usr/lib/x86_64-linux-gnu/libsasl2.so.2.0.25
php     50492 codeing  mem       REG  259,4  1193016  3935648 /usr/lib/x86_64-linux-gnu/libgcrypt.so.20.2.4
php     50492 codeing  mem       REG  259,4   533280  3935736 /usr/lib/x86_64-linux-gnu/libgmp.so.10.3.2
php     50492 codeing  mem       REG  259,4   236952  3936389 /usr/lib/x86_64-linux-gnu/libnettle.so.6.5
php     50492 codeing  mem       REG  259,4   229200  3935979 /usr/lib/x86_64-linux-gnu/libhogweed.so.4.5
php     50492 codeing  mem       REG  259,4  1748352  3935752 /usr/lib/x86_64-linux-gnu/libgnutls.so.30.23.2
php     50492 codeing  mem       REG  259,4  1574952  3936963 /usr/lib/x86_64-linux-gnu/libunistring.so.2.1.0
php     50492 codeing  mem       REG  259,4  1570256  3936861 /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25
php     50492 codeing  mem       REG  259,4 29476552  3936027 /usr/lib/x86_64-linux-gnu/libicudata.so.70.1
php     50492 codeing  mem       REG  259,4    75776  3933155 /usr/lib/x86_64-linux-gnu/libtasn1.so.6.5.5
php     50492 codeing  mem       REG  259,4   100712  3935636 /usr/lib/x86_64-linux-gnu/libgcc_s.so.1
php     50492 codeing  mem       REG  259,4   331088  3932182 /usr/lib/x86_64-linux-gnu/libldap_r-2.4.so.2.10.10
php     50492 codeing  mem       REG  259,4   203600  3934153 /usr/lib/x86_64-linux-gnu/libk5crypto.so.3.1
php     50492 codeing  mem       REG  259,4   913280  3933999 /usr/lib/x86_64-linux-gnu/libkrb5.so.3.3
php     50492 codeing  mem       REG  259,4   309744  3933996 /usr/lib/x86_64-linux-gnu/libgssapi_krb5.so.2.2
php     50492 codeing  mem       REG  259,4  2046128  3936057 /usr/lib/x86_64-linux-gnu/libicuuc.so.70.1
php     50492 codeing  mem       REG  259,4  3295400  3936033 /usr/lib/x86_64-linux-gnu/libicui18n.so.70.1
php     50492 codeing  mem       REG  259,4    22448  3936153 /usr/lib/x86_64-linux-gnu/libkeyutils.so.1.8
php     50492 codeing  mem       REG  259,4    56352  3934149 /usr/lib/x86_64-linux-gnu/libkrb5support.so.0.1
php     50492 codeing  mem       REG  259,4    63672  3932181 /usr/lib/x86_64-linux-gnu/liblber-2.4.so.2.10.10
php     50492 codeing  mem       REG  259,4    18344  3935317 /usr/lib/x86_64-linux-gnu/libcom_err.so.2.1
php     50492 codeing  mem       REG  259,4    71520  3936660 /usr/lib/x86_64-linux-gnu/libpsl.so.5.3.1
php     50492 codeing  mem       REG  259,4   186696  3936850 /usr/lib/x86_64-linux-gnu/libssh2.so.1.0.1
php     50492 codeing  mem       REG  259,4   122280  3936745 /usr/lib/x86_64-linux-gnu/librtmp.so.1
php     50492 codeing  mem       REG  259,4   120752  3936063 /usr/lib/x86_64-linux-gnu/libidn2.so.0.3.4
php     50492 codeing  mem       REG  259,4   158128  3936399 /usr/lib/x86_64-linux-gnu/libnghttp2.so.14.17.1
php     50492 codeing  mem       REG  259,4   158400  3936242 /usr/lib/x86_64-linux-gnu/liblzma.so.5.2.5
php     50492 codeing  mem       REG  259,4  1824496  3933485 /usr/lib/x86_64-linux-gnu/libc-2.28.so
php     50492 codeing  mem       REG  259,4  1183192  3936839 /usr/lib/x86_64-linux-gnu/libsqlite3.so.0.8.6
php     50492 codeing  mem       REG  259,4   568256  3936482 /usr/lib/x86_64-linux-gnu/libonig.so.5.0.0
php     50492 codeing  mem       REG  259,4   432128  3936129 /usr/lib/x86_64-linux-gnu/libjpeg.so.62.2.0
php     50492 codeing  mem       REG  259,4  3068768  3938548 /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
php     50492 codeing  mem       REG  259,4   146968  3933511 /usr/lib/x86_64-linux-gnu/libpthread-2.28.so
php     50492 codeing  mem       REG  259,4   227248  3936615 /usr/lib/x86_64-linux-gnu/libpng16.so.16.36.0
php     50492 codeing  mem       REG  259,4   588232  3934179 /usr/lib/x86_64-linux-gnu/libcurl.so.4.5.0
php     50492 codeing  mem       REG  259,4   117184  3934117 /usr/lib/x86_64-linux-gnu/libz.so.1.2.11
php     50492 codeing  mem       REG  259,4   601952  3938582 /usr/lib/x86_64-linux-gnu/libssl.so.1.1
php     50492 codeing  mem       REG  259,4  1740024  3933775 /usr/lib/x86_64-linux-gnu/libxml2.so.2.9.4
php     50492 codeing  mem       REG  259,4    14592  3933489 /usr/lib/x86_64-linux-gnu/libdl-2.28.so
php     50492 codeing  mem       REG  259,4  1579448  3933491 /usr/lib/x86_64-linux-gnu/libm-2.28.so
php     50492 codeing  mem       REG  259,4    14720  3933515 /usr/lib/x86_64-linux-gnu/libutil-2.28.so
php     50492 codeing  mem       REG  259,4    35808  3933513 /usr/lib/x86_64-linux-gnu/librt-2.28.so
php     50492 codeing  mem       REG  259,4    93000  3933512 /usr/lib/x86_64-linux-gnu/libresolv-2.28.so
php     50492 codeing  mem       REG  259,4   745016  6822488 /usr/local/php-8.2.0/lib/php/extensions/no-debug-non-zts-20220829/bcmath.so
php     50492 codeing  mem       REG  259,4    55472  3935237 /usr/lib/x86_64-linux-gnu/libbrotlidec.so.1.0.7
php     50492 codeing  mem       REG  259,4    26402  3938790 /usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache
php     50492 codeing  mem       REG  259,4   165640  3933477 /usr/lib/x86_64-linux-gnu/ld-2.28.so
php     50492 codeing    0u      CHR  136,1      0t0        4 /dev/pts/1
php     50492 codeing    1w      REG  259,4       15  1835086 /tmp/workerman/workerman.log
php     50492 codeing    2w      REG  259,4       15  1835086 /tmp/workerman/workerman.log
php     50492 codeing    3r      REG  259,5      559 21764585 /www/workerman/wm-study/debug.php
php     50492 codeing    4u  a_inode   0,14        0    12445 [eventpoll]
php     50492 codeing    5u     IPv4 467936      0t0      TCP *:8888 (LISTEN)
php     50492 codeing    6r     FIFO   0,13      0t0   484076 pipe
php     50492 codeing    7w     FIFO   0,13      0t0   484076 pipe
php     50492 codeing    8u     IPv4 484122      0t0      TCP 127.0.0.1:8888->127.0.0.1:53932 (ESTABLISHED)
php     50492 codeing   22u  a_inode   0,14        0    12445 [eventpoll]
php     50492 codeing   23r     FIFO   0,13      0t0    55943 pipe
php     50492 codeing   24w     FIFO   0,13      0t0    55943 pipe

使用lsof -nPp 50492的输出显示了进程 ID 为 50492 的 PHP 进程(用户为codeing)当前打开的所有文件描述符以及相关的资源信息:

  • 详细列出了进程所打开的各种类型的文件资源,包括:
    • cwd:当前工作目录是 /www/workerman/wm-study
    • rtd:根目录是 /
    • txt:执行的主程序文本位于 /usr/local/php-8.2.0/bin/php
  • 大量的mem类型条目展示了进程加载的共享库文件(.so文件),这是进程运行时所需的动态链接库,例如swoole.soevent.so
  • 最后一部分列出了进程的文件描述符(FD):
    • 0:标准输入,连接到终端 /dev/pts/1
    • 12:标准输出和错误输出都重定向到同一个文件 /tmp/workerman/workerman.log,且均为写入模式(w
    • 3:读取一个脚本文件 /www/workerman/wm-study/debug.php
    • 422:内核事件多路复用机制(如epoll)
    • 5:监听TCP端口8888
    • 67:组成一个管道用于进程间通信
    • 8:已建立的TCP连接(源IP与目标IP都是127.0.0.1,分别在端口8888和53932之间)
    • 2324:另一组管道

注意

8u IPv4 484122 这行,127.0.0.1:8888->127.0.0.1:53932 (ESTABLISHED),连接着一个客户端。

出现 busy 的原因

摘抄于文档

1、业务有致命错误导致进程不断退出

现象: 这种情况下能看到系统负载比较高,status中的load average为1或者更高。能看到进程的exit_count数字很高,并且不断增长

解决: debug 方式运行 (php start.php start不加-d) workerman 看下业务报错,把报错解决即可

2、代码里无限死循环

现象: top 中能看到 busy 进程占用 cpu 很高,strace -ttp pid命令没有打印出任何系统调用信息

解决: 参考鸟哥的文章通过 gdb和php源码定位,步骤总结大概如下:

  • 1、php -v查看版本
  • 2、下载对应php版本的源码
  • 3、gdb --pid=busy 进程的 pid
  • 4、source php 源码路径/.gdbinit
  • 5、zbacktrace 打印调用栈

3、无限添加定时器

业务代码不停的添加定时器又不删除,导致进程内定时器越来越多,最终造成进程无限运行定时器。例如以下代码:

$worker = new Worker;
$worker->onConnect = function($con){
    Timer::add(10, function(){});
};
Worker::runAll();

以上代码在有客户端连接上来后会增加一个定时器,但是整个业务代码里没有删除定时器的逻辑,这样随着时间推移,进程内会不断增加定时器,最终导致进程无限运行定时器导致busy。

正确的代码:

$worker = new Worker;
$worker->onConnect = function($con){
    $con->timer_id = Timer::add(10, function(){});
};
$worker->onClose = function($con){
    Timer::del($con->timer_id);
};
Worker::runAll();
请登录后再评论