New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

skynet占满cpu,但是所有服务都正常响应 #644

Closed
jxfzlmb opened this Issue May 26, 2017 · 12 comments

Comments

Projects
None yet
2 participants
@jxfzlmb

jxfzlmb commented May 26, 2017

skynet占满cpu,但是所有服务都正常响应

很难重现,只有一个现场,这个服务器大概跑了一周,发现cpu被占满

PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
27510 game      20   0  252912  27224   1484 R 99.9  2.7   4941:45 skynet

但是所有的服务都正常,没有拥塞,任务很少,响应也都正确,应该不是死循环或者循环call问题。

stat
:00000004       cpu:0.001394    message:29      mqlen:0 task:0
:00000006       cpu:0.000784    message:11      mqlen:0 task:0
:00000007       cpu:0.001686    message:11      mqlen:0 task:0
:00000008       cpu:0.014091    message:29      mqlen:0 task:0
:00000009       cpu:0.000965    message:12      mqlen:0 task:1
:0000000a       cpu:0.012387    message:78      mqlen:0 task:1
:0000000b       cpu:0.041549    message:21      mqlen:0 task:1
:0000000c       cpu:0.760351    message:12507   mqlen:0 task:2
:0000000d       cpu:0.012948    message:12      mqlen:0 task:0
:0000000e       cpu:2.329448    message:39209   mqlen:0 task:4
:0000000f       cpu:0.08777     message:1539    mqlen:0 task:0
:00000010       cpu:0.016192    message:519     mqlen:0 task:0
:00000011       cpu:0.158207    message:3214    mqlen:0 task:0
:00000012       cpu:1.905713    message:17686   mqlen:0 task:6
:000002d3       cpu:0.040202    message:424     mqlen:0 task:1
:000002d5       cpu:0.031169    message:376     mqlen:0 task:1
:000002d6       cpu:0.046675    message:390     mqlen:0 task:1
:000002d7       cpu:0.012635    message:281     mqlen:0 task:0
:000002dd       cpu:0.007929    message:54      mqlen:0 task:1
<CMD OK>

另外发现占用cpu都在系统空间,看起来不是lua逻辑问题
%Cpu(s): 20.5 us, 79.1 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.3 st

后来发现占cpu的不是工作线程,好像是socket线程,backtrace了一下看到停在这。

#0  0x00007fcf9e6a0c53 in __atomic_preadv_replacement (fd=-1657083256, vector=0x7fcf9bfa5ccc, count=-1678091056, 
    offset=140529692707923) at ../sysdeps/posix/preadv.c:75
#1  0x000000000040c8fb in skynet_socket_poll () at skynet-src/skynet_socket.c:79
#2  0x000000000040b5d3 in thread_socket (p=0x7fcf9e21d280) at skynet-src/skynet_start.c:68
#3  0x00007fcf9f46a184 in start_thread (arg=0x7fcf9bfa6700) at pthread_create.c:312
#4  0x00007fcf9e6a937d in __ecvt_r (value=9.532824124368238e-130, ndigit=0, decpt=0x0, sign=0x0, 
    buf=0x7fcf9bfa69c0 "\300yz\234\317\177", len=140529651836672) at efgcvt_r.c:218
#5  0x0000000000000000 in ?? ()

但服务器网络是好的,所有的功能也都正常,不看cpu占用的话不会发现这个问题。

请问这可能会是什么问题?从哪个方向查?

@cloudwu

This comment has been minimized.

Show comment
Hide comment
@cloudwu

cloudwu May 26, 2017

Owner

从 backtrace 看是 epoll wait 占用了 cpu , 这里 epoll wait 是无限等待直到有消息触发。

可以考虑看是不是 epoll ctrl 传入了错误的值。所有socket 对象都在一个全局数组里,可以用 gdb 遍历查看有多少活跃连接。

Owner

cloudwu commented May 26, 2017

从 backtrace 看是 epoll wait 占用了 cpu , 这里 epoll wait 是无限等待直到有消息触发。

可以考虑看是不是 epoll ctrl 传入了错误的值。所有socket 对象都在一个全局数组里,可以用 gdb 遍历查看有多少活跃连接。

@cloudwu

This comment has been minimized.

Show comment
Hide comment
@cloudwu

cloudwu May 26, 2017

Owner

另外可以加点 printf 看看epoll wait 的调用频率,比如每1000 次 wait 输出一下,看出问题的时候是否在高频调用它。

Owner

cloudwu commented May 26, 2017

另外可以加点 printf 看看epoll wait 的调用频率,比如每1000 次 wait 输出一下,看出问题的时候是否在高频调用它。

@jxfzlmb

This comment has been minimized.

Show comment
Hide comment
@jxfzlmb

jxfzlmb May 26, 2017

恩,正常的服务器随便断下,基本是停在epoll_wait

#0  0x00007fd80b14aa13 in epoll_wait () at ../sysdeps/unix/syscall-template.S:81
#1  0x000000000040e823 in sp_wait (max=64, e=0x7fd809e4f1b8, efd=<optimized out>) at skynet-src/socket_epoll.h:55
#2  socket_server_poll (ss=0x7fd809e4f180, result=result@entry=0x7fd808a46cd0, more=more@entry=0x7fd808a46ccc)
    at skynet-src/socket_server.c:1218
#3  0x000000000040c8fb in skynet_socket_poll () at skynet-src/skynet_socket.c:79
#4  0x000000000040b5b7 in thread_socket (p=0x7fd80acb8280) at skynet-src/skynet_start.c:68
#5  0x00007fd80bf0b184 in start_thread (arg=0x7fd808a47700) at pthread_create.c:312
#6  0x00007fd80b14a37d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

不正常的服务器会停在这2个地方,从来没有停在过epoll_wait

#0  0x00007fcf9e6a0c53 in __atomic_preadv_replacement (fd=-1657083256, vector=0x7fcf9bfa5ccc, count=-1678091056, offset=-1)
    at ../sysdeps/posix/preadv.c:75
#1  0x000000000040c8fb in skynet_socket_poll () at skynet-src/skynet_socket.c:79
#2  0x000000000040b5d3 in thread_socket (p=0x7fcf9e21d280) at skynet-src/skynet_start.c:68
#3  0x00007fcf9f46a184 in start_thread (arg=0x7fcf9bfa6700) at pthread_create.c:312
#4  0x00007fcf9e6a937d in __ecvt_r (value=6.9430831659744263e-310, ndigit=0, decpt=0x0, sign=0x0, 
    buf=0x7fcf9bfa69c0 "\300yz\234\317\177", len=140529651836672) at efgcvt_r.c:218
#5  0x0000000000000000 in ?? ()


#0  0x00007fcf9e6a9a13 in __qecvt_r (value=<optimized out>, ndigit=-1678091056, decpt=0x7fcf9bfa5cb0, sign=0x7fcf9bfa5ccc, 
    buf=0x7fcf9bfa58e8 "\020", len=140529672840760) at efgcvt_r.c:237
#1  0x00007fcf90f82380 in ?? ()
#2  0x00007fcf9d3ae600 in ?? ()
#3  0x00000000000000b5 in ?? ()
#4  0x0000000000000000 in ?? ()

用gdb把里面的活动socket找出来,我需要研究下,以前没做过,晚些回复你结果。
由于没法重现,所以也没法加printf调试。

jxfzlmb commented May 26, 2017

恩,正常的服务器随便断下,基本是停在epoll_wait

#0  0x00007fd80b14aa13 in epoll_wait () at ../sysdeps/unix/syscall-template.S:81
#1  0x000000000040e823 in sp_wait (max=64, e=0x7fd809e4f1b8, efd=<optimized out>) at skynet-src/socket_epoll.h:55
#2  socket_server_poll (ss=0x7fd809e4f180, result=result@entry=0x7fd808a46cd0, more=more@entry=0x7fd808a46ccc)
    at skynet-src/socket_server.c:1218
#3  0x000000000040c8fb in skynet_socket_poll () at skynet-src/skynet_socket.c:79
#4  0x000000000040b5b7 in thread_socket (p=0x7fd80acb8280) at skynet-src/skynet_start.c:68
#5  0x00007fd80bf0b184 in start_thread (arg=0x7fd808a47700) at pthread_create.c:312
#6  0x00007fd80b14a37d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

不正常的服务器会停在这2个地方,从来没有停在过epoll_wait

#0  0x00007fcf9e6a0c53 in __atomic_preadv_replacement (fd=-1657083256, vector=0x7fcf9bfa5ccc, count=-1678091056, offset=-1)
    at ../sysdeps/posix/preadv.c:75
#1  0x000000000040c8fb in skynet_socket_poll () at skynet-src/skynet_socket.c:79
#2  0x000000000040b5d3 in thread_socket (p=0x7fcf9e21d280) at skynet-src/skynet_start.c:68
#3  0x00007fcf9f46a184 in start_thread (arg=0x7fcf9bfa6700) at pthread_create.c:312
#4  0x00007fcf9e6a937d in __ecvt_r (value=6.9430831659744263e-310, ndigit=0, decpt=0x0, sign=0x0, 
    buf=0x7fcf9bfa69c0 "\300yz\234\317\177", len=140529651836672) at efgcvt_r.c:218
#5  0x0000000000000000 in ?? ()


#0  0x00007fcf9e6a9a13 in __qecvt_r (value=<optimized out>, ndigit=-1678091056, decpt=0x7fcf9bfa5cb0, sign=0x7fcf9bfa5ccc, 
    buf=0x7fcf9bfa58e8 "\020", len=140529672840760) at efgcvt_r.c:237
#1  0x00007fcf90f82380 in ?? ()
#2  0x00007fcf9d3ae600 in ?? ()
#3  0x00000000000000b5 in ?? ()
#4  0x0000000000000000 in ?? ()

用gdb把里面的活动socket找出来,我需要研究下,以前没做过,晚些回复你结果。
由于没法重现,所以也没法加printf调试。

@jxfzlmb

This comment has been minimized.

Show comment
Hide comment
@jxfzlmb

jxfzlmb May 26, 2017

通过gdb拿SOCKET_SERVER的信息发现,epool会不断的给出一个相同的消息

0x00007fcf9e6a0c53 in __atomic_preadv_replacement (fd=-1657083256, vector=0x7fcf9bfa5ccc, count=-1678091056, offset=-1)
    at ../sysdeps/posix/preadv.c:75
75      ../sysdeps/posix/preadv.c: No such file or directory.
5: *(struct socket*)SOCKET_SERVER.ev[0] = {opaque = 9, high = {head = 0x0, tail = 0x0}, low = {head = 0x0, tail = 0x0}, wb_size = 0, 
  fd = 0, id = 1, protocol = 0, type = 8, p = {size = 64, udp_address = "@", '\000' <repeats 17 times>}}
4: SOCKET_SERVER.ev[0] = {s = 0x7fcf9d3aea88, read = false, write = false}
3: SOCKET_SERVER.event_index = 1
2: SOCKET_SERVER.event_n = 1
1: SOCKET_SERVER.checkctrl = 1

应该就是这个导致了wait不断被唤醒,占满cpu。这个消息不是 EPOLLOUT,也不是 EPOLLIN。
这个消息是干什么的呢?怎么出现的?

jxfzlmb commented May 26, 2017

通过gdb拿SOCKET_SERVER的信息发现,epool会不断的给出一个相同的消息

0x00007fcf9e6a0c53 in __atomic_preadv_replacement (fd=-1657083256, vector=0x7fcf9bfa5ccc, count=-1678091056, offset=-1)
    at ../sysdeps/posix/preadv.c:75
75      ../sysdeps/posix/preadv.c: No such file or directory.
5: *(struct socket*)SOCKET_SERVER.ev[0] = {opaque = 9, high = {head = 0x0, tail = 0x0}, low = {head = 0x0, tail = 0x0}, wb_size = 0, 
  fd = 0, id = 1, protocol = 0, type = 8, p = {size = 64, udp_address = "@", '\000' <repeats 17 times>}}
4: SOCKET_SERVER.ev[0] = {s = 0x7fcf9d3aea88, read = false, write = false}
3: SOCKET_SERVER.event_index = 1
2: SOCKET_SERVER.event_n = 1
1: SOCKET_SERVER.checkctrl = 1

应该就是这个导致了wait不断被唤醒,占满cpu。这个消息不是 EPOLLOUT,也不是 EPOLLIN。
这个消息是干什么的呢?怎么出现的?

@cloudwu

This comment has been minimized.

Show comment
Hide comment
@cloudwu

cloudwu May 26, 2017

Owner

type = 8 是 SOCKET_TYPE_BIND , 说明这个是个 listen 的端口,可以从 opaque = 9 (服务地址) 去确认一下,是否是你的 gate 监听端口。id =1 是内部的 fd 。不过, fd = 0 比较奇怪,因为这通常是保留给 stdin 的。

如果不是 EPOLLIN 和 EPOLLOUT 则可能是出错了。建议把 epoll 返回的 flag 拿出来看看到底是什么。skynet 这里并没有处理 EPOLLERR ,可能是一个需要完善的点。

Owner

cloudwu commented May 26, 2017

type = 8 是 SOCKET_TYPE_BIND , 说明这个是个 listen 的端口,可以从 opaque = 9 (服务地址) 去确认一下,是否是你的 gate 监听端口。id =1 是内部的 fd 。不过, fd = 0 比较奇怪,因为这通常是保留给 stdin 的。

如果不是 EPOLLIN 和 EPOLLOUT 则可能是出错了。建议把 epoll 返回的 flag 拿出来看看到底是什么。skynet 这里并没有处理 EPOLLERR ,可能是一个需要完善的点。

@cloudwu

This comment has been minimized.

Show comment
Hide comment
@cloudwu

cloudwu May 26, 2017

Owner

我推测是触发了 EPOLLERR ,但是没有触发过 EPOLLOUT EPOLLIN 导致代码无法关闭这个 fd ,而 epoll 使用的是 LT 模式,不处理的话会一直触发。这里需要完善一下错误的处理。

不过是否是 EPOLLERR ,最好可以进一步的确认。

另外,这应该只是一个表象,关键是为什么 fd = 0 处于 SOCKET_TYPE_BIND 状态。stdin 很容易和别的东西冲突。目前 skynet 即使在后台,fd = 0 应该也是重定向到 /dev/null 的。

Owner

cloudwu commented May 26, 2017

我推测是触发了 EPOLLERR ,但是没有触发过 EPOLLOUT EPOLLIN 导致代码无法关闭这个 fd ,而 epoll 使用的是 LT 模式,不处理的话会一直触发。这里需要完善一下错误的处理。

不过是否是 EPOLLERR ,最好可以进一步的确认。

另外,这应该只是一个表象,关键是为什么 fd = 0 处于 SOCKET_TYPE_BIND 状态。stdin 很容易和别的东西冲突。目前 skynet 即使在后台,fd = 0 应该也是重定向到 /dev/null 的。

@jxfzlmb

This comment has been minimized.

Show comment
Hide comment
@jxfzlmb

jxfzlmb May 27, 2017

9号服务是console,用的确实是stdin,我没有用daemon,直接用的(./skynet xxx >> xxx.log),然后远程连接断开,进程也没关。

另外说下我做的可能有关联的改动,在gate里面(不是9号服务),我把redirect默认的dummy session从1改成了fd,想在收到消息时知道是谁发的,我也不大确认会不会出问题。
skynet.redirect(agent, c.client, "client", fd, msg, sz)

jxfzlmb commented May 27, 2017

9号服务是console,用的确实是stdin,我没有用daemon,直接用的(./skynet xxx >> xxx.log),然后远程连接断开,进程也没关。

另外说下我做的可能有关联的改动,在gate里面(不是9号服务),我把redirect默认的dummy session从1改成了fd,想在收到消息时知道是谁发的,我也不大确认会不会出问题。
skynet.redirect(agent, c.client, "client", fd, msg, sz)

@cloudwu

This comment has been minimized.

Show comment
Hide comment
@cloudwu

cloudwu May 27, 2017

Owner

首先,可以看看我今天的修改能不能解决部分问题。

我刚才做了一些测试,虽然没有还原你的情况,但是发现另一个潜在的问题:如果不小心把一个 fd close 掉,但是却在 close 之前没有调用 sp_del 从 epoll 中删除,就会导致一个已经删除的 fd 的消息依然被 sp_wait 报告。而且由于 fd 已经 close ,所以即无法读这个 fd 来删除消息,也无法再 sp_del 去删。结果这个死消息就不断地抛出来了。

在我的测试中,我强行关闭了 fd 0 ,结果就不断地打印 socket-server: invalid socket

我 google 了一下,这个应该属于很难解决的问题。 https://idea.popcount.org/2017-03-20-epoll-is-fundamentally-broken-22/ 这个帖子的解决建议是把整个 epollfd 都废除掉新建一个。这也是 libev 遇到过的问题: http://lists.schmorp.de/pipermail/libev/2016q1/002680.html ,否则:

Thus it is possible to close an fd, and afterwards forever receive events for it, and you can't do anything about that.


至于 dummy session ,之所以写的 1 ,是想回避 0 。这个是想将 socket 上的消息模拟成一个内部请求,redirect 给 client 。如果这里 session 为 0 的话,你的 client 里的 skynet.ret 就会被直接丢弃掉。改成 fd 的风险在于,当 fd 真的是 0 时,client 服务无法用 skynet.ret 回应这个请求。

这应该和上面讨论的问题无关。

Owner

cloudwu commented May 27, 2017

首先,可以看看我今天的修改能不能解决部分问题。

我刚才做了一些测试,虽然没有还原你的情况,但是发现另一个潜在的问题:如果不小心把一个 fd close 掉,但是却在 close 之前没有调用 sp_del 从 epoll 中删除,就会导致一个已经删除的 fd 的消息依然被 sp_wait 报告。而且由于 fd 已经 close ,所以即无法读这个 fd 来删除消息,也无法再 sp_del 去删。结果这个死消息就不断地抛出来了。

在我的测试中,我强行关闭了 fd 0 ,结果就不断地打印 socket-server: invalid socket

我 google 了一下,这个应该属于很难解决的问题。 https://idea.popcount.org/2017-03-20-epoll-is-fundamentally-broken-22/ 这个帖子的解决建议是把整个 epollfd 都废除掉新建一个。这也是 libev 遇到过的问题: http://lists.schmorp.de/pipermail/libev/2016q1/002680.html ,否则:

Thus it is possible to close an fd, and afterwards forever receive events for it, and you can't do anything about that.


至于 dummy session ,之所以写的 1 ,是想回避 0 。这个是想将 socket 上的消息模拟成一个内部请求,redirect 给 client 。如果这里 session 为 0 的话,你的 client 里的 skynet.ret 就会被直接丢弃掉。改成 fd 的风险在于,当 fd 真的是 0 时,client 服务无法用 skynet.ret 回应这个请求。

这应该和上面讨论的问题无关。

@jxfzlmb

This comment has been minimized.

Show comment
Hide comment
@jxfzlmb

jxfzlmb May 27, 2017

调试了下,那个出错的flag是16,也就是EPOLLHUP。
也就是说这问题的起源是ssh退出后,console的stdin收到了EPOLLHUP消息。
但是我试了启动skynet再退出ssh,又重现不了这个现象。

jxfzlmb commented May 27, 2017

调试了下,那个出错的flag是16,也就是EPOLLHUP。
也就是说这问题的起源是ssh退出后,console的stdin收到了EPOLLHUP消息。
但是我试了启动skynet再退出ssh,又重现不了这个现象。

zhangshiqian1214 added a commit to zhangshiqian1214/skynet that referenced this issue May 29, 2017

Merge pull request #2 from cloudwu/master
support error event, see #644
@jxfzlmb

This comment has been minimized.

Show comment
Hide comment
@jxfzlmb

jxfzlmb May 31, 2017

我这边改成daemon就不会出问题了,另外 #644 最好把EPOLLHUP也处理了,保险一些。
你看看这个问题还需不需要跟进,不需要我就关了。

jxfzlmb commented May 31, 2017

我这边改成daemon就不会出问题了,另外 #644 最好把EPOLLHUP也处理了,保险一些。
你看看这个问题还需不需要跟进,不需要我就关了。

cloudwu added a commit that referenced this issue May 31, 2017

@cloudwu

This comment has been minimized.

Show comment
Hide comment
@cloudwu

cloudwu May 31, 2017

Owner

从 man epoll_ctl 上看,似乎直接把 EPOLLHUP 看作 EPOLLIN ,然后让 read 正常工作就可以了?

EPOLLHUP Hang up happened on the associated file descriptor. epoll_wait(2) will always wait for this event; it is not necessary to set it in events. Note that when reading from a channel such as a pipe or a stream socket, this event merely indicates that the peer closed its end of the channel. Subsequent reads from the channel will return 0 (end of file) only after all outstanding data in the channel has been consumed.

Owner

cloudwu commented May 31, 2017

从 man epoll_ctl 上看,似乎直接把 EPOLLHUP 看作 EPOLLIN ,然后让 read 正常工作就可以了?

EPOLLHUP Hang up happened on the associated file descriptor. epoll_wait(2) will always wait for this event; it is not necessary to set it in events. Note that when reading from a channel such as a pipe or a stream socket, this event merely indicates that the peer closed its end of the channel. Subsequent reads from the channel will return 0 (end of file) only after all outstanding data in the channel has been consumed.

zhangshiqian1214 added a commit to zhangshiqian1214/skynet that referenced this issue May 31, 2017

Merge pull request #3 from cloudwu/master
consider EPOLLHUP as EPOLLIN, see #644
@jxfzlmb

This comment has been minimized.

Show comment
Hide comment
@jxfzlmb

jxfzlmb May 31, 2017

好的,这个问题算是解决了,关单了,多谢。

jxfzlmb commented May 31, 2017

好的,这个问题算是解决了,关单了,多谢。

@jxfzlmb jxfzlmb closed this May 31, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment