thinkphp中,gatewayworker出现buys调试发现卡数据库,不知道哪里有问题

ric

程序运行一段时间后,总是出现大量的buys。
直接上代码:
strace -ttp 13190
strace: Process 13190 attached
23:13:34.562338 restart_syscall(<... resuming interrupted read ...>) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
23:13:53.306786 --- SIGALRM {si_signo=SIGALRM, si_code=SI_USER, si_pid=3990, si_uid=0} ---
23:13:53.306876 rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system call)
23:13:53.307042 poll([{fd=31, events=POLLIN|POLLERR|POLLHUP}], 1, 86400000) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)

php 13190 root 29u IPv4 337856578 0t0 TCP 127.0.0.1:43928->127.0.0.1:2016 (ESTABLISHED)
php 13190 root 30u IPv4 338776580 0t0 TCP 127.0.0.1:42530->127.0.0.1:63794 (ESTABLISHED)
php 13190 root 31u IPv4 339256252 0t0 TCP 10.88.88.16:39998->10.88.88.10:4936 (ESTABLISHED)
php 13190 root 32u IPv4 339279700 0t0 TCP 10.88.88.16:50944->10.88.88.10:4936 (ESTABLISHED)
php 13190 root 34u REG 253,1 9216 923360 /etc/pki/nssdb/cert9.db
php 13190 root 35u REG 253,1 11264 923362 /etc/pki/nssdb/key4.db

其中 10.88.88.10 是数据库。
求赐教

762 3 0
3个回答

Tinywan

业务代码有死循环

  • ric 2022-01-10

    应该没有,都是正常业务,到最后执行完, 看31u的话是卡在 链接10.88.88.10 这个数据库中,但检查查询是没问题的

walkor

卡在数据库,可能是有慢sql,也可能是连数据库超时

  • ric 2022-01-11

    看了sql慢查询,并没有,实际测试也不存在慢查询的情况,数据库链接超时的话,,这个使用了tp的,开启了断开自动重链。所以感觉也不是很像

  • walkor 2022-01-11

    strace 一个正常的进程,直到它卡在poll调用,看下poll之前几个系统调用是什么,大概能定位到问题

  • ric 2022-01-11

    buys的是 BusinessWorker

  • ric 2022-01-11

    ttp 后返回的大概是

    poll([{fd=9, events=POLLIN|POLLERR|POLLHUP}], 1, 0) = 1 ([{fd=9, revents=POLLIN}])
    accept(9, {sa_family=AF_INET, sin_port=htons(50748), sin_addr=inet_addr("127.0.0.1")}, [128->16]) = 51
    fcntl(51, F_GETFL) = 0x2 (flags O_RDWR)
    fcntl(51, F_SETFL, O_RDWR|O_NONBLOCK) = 0
    epoll_ctl(6, EPOLL_CTL_ADD, 51, {EPOLLIN, {u32=51, u64=51}}) = 0
    epoll_wait(6, [{EPOLLIN, {u32=51, u64=51}}], 32, 3280) = 1
    recvfrom(51, "\0\0\0'\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\v1788"..., 65535, 0, NULL, NULL) = 39
    sendto(51, "\0\0\0\6a:0:{}", 10, 0, NULL, 0) = 10
    epoll_wait(6, [{EPOLLIN, {u32=51, u64=51}}], 32, 3279) = 1
    recvfrom(51, "", 65535, 0, NULL, NULL) = 0
    epoll_ctl(6, EPOLL_CTL_DEL, 51, 0x7ffec4aa5f70) = 0
    close(51) = 0
    epoll_wait(6, [{EPOLLIN, {u32=9, u64=9}}], 32, 3279) = 1
    poll([{fd=9, events=POLLIN|POLLERR|POLLHUP}], 1, 0) = 1 ([{fd=9, revents=POLLIN}])
    accept(9, {sa_family=AF_INET, sin_port=htons(50796), sin_addr=inet_addr("127.0.0.1")}, [128->16]) = 51
    fcntl(51, F_GETFL) = 0x2 (flags O_RDWR)
    fcntl(51, F_SETFL, O_RDWR|O_NONBLOCK) = 0
    epoll_ctl(6, EPOLL_CTL_ADD, 51, {EPOLLIN, {u32=51, u64=51}}) = 0
    epoll_wait(6, [{EPOLLIN, {u32=51, u64=51}}], 32, 2808) = 1
    recvfrom(51, "\0\0\1\t\16\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\17[\"17"..., 65535, 0, NULL, NULL) = 265
    epoll_wait(6, [{EPOLLIN, {u32=51, u64=51}}], 32, 2807) = 1
    recvfrom(51, "", 65535, 0, NULL, NULL) = 0
    epoll_ctl(6, EPOLL_CTL_DEL, 51, 0x7ffec4aa5f70) = 0
    close(51) = 0

  • walkor 2022-01-11

    卡在 epoll_wait 是正常的。需要定位卡在poll的情况

  • ric 2022-01-11

    就是一直监控着,然后等到它卡住时再看日志是吗?我监控下

  • walkor 2022-01-11

    对,长时间卡在poll不动的情况下

  • ric 2022-01-11

    好的,我先监控下,发现不懂的再请教[抱拳]

  • ric 2022-01-11

    我好像看到了redis 返回了 +OK, 这个有办法确认是哪行语句吗?我所有的redis都是在子进程实例化的
    14:20:49.652824 recvfrom(30, "+OK\r\n", 8192, MSG_DONTWAIT, NULL, NULL) = 5

  • walkor 2022-01-11

    有可能和这个SQL有关系,SELECT account,name,`im"... , 完整sql没打印出来。
    看起来是数据库一直没返回数据,进程一直在等返回。

    下次strace可以加个 -s500 的参数,类似 strace -s500 -ttp 进程pid 这样可以打印完整的参数包括sql语句出来

  • walkor 2022-01-11

    看起来确实和 SELECT account,name,imname,id,nickname,impassword,logo FROM touser_auth_user WHERE imname = ? 这个sql有一定关系,你可以尝试下写个脚本请求下数据库看下是否有问题。看下数据库是否有有错误日志或者慢sql。

walkor

fd 32是数据库,不是redis,那两个写操作看不出来是发送得什么数据给数据库

  • ric 2022-01-12

    哦,好像是的,32是给sql传参, 就是说还是卡在这个sql,但根据时间,找到sql日志,显示是执行成功的,这个就疑惑了😅

  • walkor 2022-01-12

    这个sql之后pdo向mysql发送了两段数据,不知道这两段数据时是什么。发完这两段就卡住了。

  • ric 2022-01-15

    大大,经过调试,和打印sql,拿出sql比较和执行,那些sql都是正常的,也是能返回数据的,最终跟踪发现,就是不定时,不定sql的会出现问题,卡住在那,原因不明。 有没有什么语句可以监控到busy,或者进程长时间busy时让这个进程重启的方法?

  • walkor 2022-01-15

    每个进程设置个定时器,定时向磁盘写入当前时间戳到一个自己pid命名的文件。另外启动一个进程,这个进程读取磁盘上所有的pid文件里的时间戳,如果时间戳超过一定时间没更新,认为这个pidbusy,然后执行 posix_kill($pid, SiGKILL);杀死进程。

    另外尝试给pdo加个超时,应该是在php.ini中设置,找下资料,比如读数据超过1秒就返回失败,这样就不会卡几分钟这种。

    这个问题有可能是php的bug,不要用小版本太新的php版本。另外也有可能是硬件网卡丢包导致,也可能是mysql服务端linux内核配置有问题,甚至也有可能是防火墙问题。参考这里https://www.workerman.net/doc/workerman/appendices/kernel-optimization.html 尝试优化下linux内核包括mysql服务端。

  • ric 2022-01-15

    数据库用的是阿里的PolarDB ,找到对应的时间和sql看了下,返回都是0.0x毫秒的返回。 pdo的话,一开始我觉的可能是tp的 orm有问题,因为用到了多库,出现问题的大部分是第二个库,然后就部分改造为了使用workerman/mysql,但事实发现,其实第一个库也会,使用workerman/mysql的也会, 硬件的话,使用的是阿里的ecs, 我也长时间ping过,未发现丢包,而且都是0.x毫秒级别的响应。 linux内容优化是按照上面这个教程优化的。 唯一还能定义的,可能就php版本问题? 目前使用的是 v7.3.33, 不知道是不是这个。 之前我用8.0 进程断的更离谱,然后降下版本来的

  • walkor 2022-01-15

    阿里的DB好像连接超过1分钟就会被断开,并且不带fin通知的那种,导致客户端傻等。在onWorkerStart里尝试加个定时器,定时select 1,保持连接试下。定时间隔先设置为25秒。

  • ric 2022-01-16

    select 1后,我配合2小时自动重启一次,好像昨晚到现在是正常的了,如果是这样的话,那么的确很有可能是阿里的DB不带fin通知的那种断开,说到这个,虽然无法确认是否1分钟,但通过排查这个业务来看的话,最长不超过300s,正常里面的业务是 300s缓存在redis,过期才去重新取db,所以很可能的确是这里问题了。有新问题我再反馈。谢谢walkor大大

🔝