thinkphp中，gatewayworker出現(xiàn)buys調(diào)試發(fā)現(xiàn)卡數(shù)據(jù)庫，不知道哪里有問題

ric 2022-01-10

程序運(yùn)行一段時(shí)間后，總是出現(xiàn)大量的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 是數(shù)據(jù)庫。
求賜教

 2564  3 1

3個(gè)回答

Tinywan 2022-01-10

業(yè)務(wù)代碼有死循環(huán)

ric 2022-01-10

應(yīng)該沒有，都是正常業(yè)務(wù)，到最后執(zhí)行完，看31u的話是卡在鏈接10.88.88.10 這個(gè)數(shù)據(jù)庫中，但檢查查詢是沒問題的

walkor 2022-01-11

打賞

卡在數(shù)據(jù)庫，可能是有慢sql，也可能是連數(shù)據(jù)庫超時(shí)

ric 2022-01-11

看了sql慢查詢，并沒有，實(shí)際測試也不存在慢查詢的情況，數(shù)據(jù)庫鏈接超時(shí)的話，，這個(gè)使用了tp的，開啟了斷開自動重鏈。所以感覺也不是很像
walkor 2022-01-11

strace 一個(gè)正常的進(jìn)程，直到它卡在poll調(diào)用，看下poll之前幾個(gè)系統(tǒng)調(diào)用是什么，大概能定位到問題
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

就是一直監(jiān)控著，然后等到它卡住時(shí)再看日志是嗎？我監(jiān)控下
walkor 2022-01-11

對，長時(shí)間卡在poll不動的情況下
ric 2022-01-11

好的，我先監(jiān)控下，發(fā)現(xiàn)不懂的再請教[抱拳]
ric 2022-01-11

我好像看到了redis 返回了 +OK，這個(gè)有辦法確認(rèn)是哪行語句嗎？我所有的redis都是在子進(jìn)程實(shí)例化的
14:20:49.652824 recvfrom(30, "+OK\r\n", 8192, MSG_DONTWAIT, NULL, NULL) = 5
walkor 2022-01-11

有可能和這個(gè)SQL有關(guān)系，SELECT account,name,`im"... , 完整sql沒打印出來。
看起來是數(shù)據(jù)庫一直沒返回?cái)?shù)據(jù)，進(jìn)程一直在等返回。

下次strace可以加個(gè) -s500 的參數(shù)，類似 strace -s500 -ttp 進(jìn)程pid 這樣可以打印完整的參數(shù)包括sql語句出來
walkor 2022-01-11

看起來確實(shí)和 SELECT account,name,imname,id,nickname,impassword,logo FROM touser_auth_user WHERE imname = ? 這個(gè)sql有一定關(guān)系，你可以嘗試下寫個(gè)腳本請求下數(shù)據(jù)庫看下是否有問題?？聪聰?shù)據(jù)庫是否有有錯(cuò)誤日志或者慢sql。

walkor 2022-01-11

打賞

fd 32是數(shù)據(jù)庫，不是redis，那兩個(gè)寫操作看不出來是發(fā)送得什么數(shù)據(jù)給數(shù)據(jù)庫

ric 2022-01-12

哦，好像是的，32是給sql傳參，就是說還是卡在這個(gè)sql，但根據(jù)時(shí)間，找到sql日志，顯示是執(zhí)行成功的，這個(gè)就疑惑了??
walkor 2022-01-12

這個(gè)sql之后pdo向mysql發(fā)送了兩段數(shù)據(jù)，不知道這兩段數(shù)據(jù)時(shí)是什么。發(fā)完這兩段就卡住了。
ric 2022-01-15

大大，經(jīng)過調(diào)試，和打印sql，拿出sql比較和執(zhí)行，那些sql都是正常的，也是能返回?cái)?shù)據(jù)的，最終跟蹤發(fā)現(xiàn)，就是不定時(shí)，不定sql的會出現(xiàn)問題，卡住在那，原因不明。有沒有什么語句可以監(jiān)控到busy，或者進(jìn)程長時(shí)間busy時(shí)讓這個(gè)進(jìn)程重啟的方法？
walkor 2022-01-15

每個(gè)進(jìn)程設(shè)置個(gè)定時(shí)器，定時(shí)向磁盤寫入當(dāng)前時(shí)間戳到一個(gè)自己pid命名的文件。另外啟動一個(gè)進(jìn)程，這個(gè)進(jìn)程讀取磁盤上所有的pid文件里的時(shí)間戳，如果時(shí)間戳超過一定時(shí)間沒更新，認(rèn)為這個(gè)pidbusy，然后執(zhí)行 posix_kill($pid, SiGKILL);殺死進(jìn)程。

另外嘗試給pdo加個(gè)超時(shí)，應(yīng)該是在php.ini中設(shè)置，找下資料，比如讀數(shù)據(jù)超過1秒就返回失敗，這樣就不會卡幾分鐘這種。

這個(gè)問題有可能是php的bug，不要用小版本太新的php版本。另外也有可能是硬件網(wǎng)卡丟包導(dǎo)致，也可能是mysql服務(wù)端linux內(nèi)核配置有問題，甚至也有可能是防火墻問題。參考這里http://wtbis.cn/doc/workerman/appendices/kernel-optimization.html 嘗試優(yōu)化下linux內(nèi)核包括mysql服務(wù)端。
ric 2022-01-15

數(shù)據(jù)庫用的是阿里的PolarDB ，找到對應(yīng)的時(shí)間和sql看了下，返回都是0.0x毫秒的返回。 pdo的話，一開始我覺的可能是tp的 orm有問題，因?yàn)橛玫搅硕鄮?，出現(xiàn)問題的大部分是第二個(gè)庫，然后就部分改造為了使用workerman/mysql，但事實(shí)發(fā)現(xiàn)，其實(shí)第一個(gè)庫也會，使用workerman/mysql的也會，硬件的話，使用的是阿里的ecs，我也長時(shí)間ping過，未發(fā)現(xiàn)丟包，而且都是0.x毫秒級別的響應(yīng)。 linux內(nèi)容優(yōu)化是按照上面這個(gè)教程優(yōu)化的。唯一還能定義的，可能就php版本問題？目前使用的是 v7.3.33，不知道是不是這個(gè)。之前我用8.0 進(jìn)程斷的更離譜，然后降下版本來的
walkor 2022-01-15

阿里的DB好像連接超過1分鐘就會被斷開，并且不帶fin通知的那種，導(dǎo)致客戶端傻等。在onWorkerStart里嘗試加個(gè)定時(shí)器，定時(shí)select 1，保持連接試下。定時(shí)間隔先設(shè)置為25秒。
ric 2022-01-16

select 1后，我配合2小時(shí)自動重啟一次，好像昨晚到現(xiàn)在是正常的了，如果是這樣的話，那么的確很有可能是阿里的DB不帶fin通知的那種斷開，說到這個(gè)，雖然無法確認(rèn)是否1分鐘，但通過排查這個(gè)業(yè)務(wù)來看的話，最長不超過300s，正常里面的業(yè)務(wù)是 300s緩存在redis，過期才去重新取db，所以很可能的確是這里問題了。有新問題我再反饋。謝謝walkor大大