ping 的 cpu 使用率奇高

[15015613]

最近发现笔记本风扇狂转， top 看了一下，发现 ping 的 cpu 使用率奇高。
把 ping 关了之后一切恢复正常。
有人知道这是什么原因吗？

日志如下：

  PID USER      PR  NI    VIRT    RES  %CPU %MEM     TIME+ S COMMAND
10080 arch      20   0   36.5m   3.9m  97.4  0.1   1:18.44 R ping
 8111 arch      20   0 3810.0m 1.427g   3.3 18.7 505:03.19 S telegram-deskto
10441 root      20   0    0.0m   0.0m   0.7  0.0   0:06.31 S kworker/6:2
11739 arch      20   0   48.7m   4.0m   0.7  0.1   0:00.09 R top
15026 arch      20   0 1618.3m  82.8m   0.7  1.1  26:00.00 S konsole
    1 root      20   0  196.4m   5.5m   0.0  0.1   0:04.48 S systemd
    2 root      20   0    0.0m   0.0m   0.0  0.0   0:00.18 S kthreadd
    4 root       0 -20    0.0m   0.0m   0.0  0.0   0:00.00 S kworker/0:0H
    6 root      20   0    0.0m   0.0m   0.0  0.0   0:48.72 S ksoftirqd/0
    7 root      20   0    0.0m   0.0m   0.0  0.0   4:48.71 S rcu_preempt

64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3289 ttl=55 time=84.5 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3290 ttl=55 time=179 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3291 ttl=55 time=4.30 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3292 ttl=55 time=30.1 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3293 ttl=55 time=8.40 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3294 ttl=55 time=61.9 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3295 ttl=55 time=98.8 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3296 ttl=55 time=9.58 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3297 ttl=55 time=7.74 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3298 ttl=55 time=7.22 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3299 ttl=55 time=6.84 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3301 ttl=55 time=5.90 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3302 ttl=55 time=26.1 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3303 ttl=55 time=8.37 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3304 ttl=55 time=6.57 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3305 ttl=55 time=8.36 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3306 ttl=55 time=9.38 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3307 ttl=55 time=11.0 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3308 ttl=55 time=3.66 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3309 ttl=55 time=52.8 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3310 ttl=55 time=4.51 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3311 ttl=55 time=4.62 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3312 ttl=55 time=3.69 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3313 ttl=55 time=4.28 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3314 ttl=55 time=18.3 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3315 ttl=55 time=6.83 ms
64 bytes from 119.75.218.70 (119.75.218.70): icmp_seq=3316 ttl=55 time=13.3 ms

[Systemd]

会不会是二进制文件被人调包了？

[simpx]

strace -p pid ，看下有哪些系统调动

[15015613]

@Systemd 应该不会吧，我重装一下试试。

[15015613]

@simpx
等了半天问题终于再次出现， strace 结果如下：

正常情况下
https://gist.github.com/yingziwu/b0abe335f0594d488c0ee636e7cf86ac

cpu 占用高时
https://gist.github.com/yingziwu/7682fd07c19f35e09c0ffd71f9de08dc
贴上去的仅为屏幕输出的一小部分

google 了一下，好像也没有说明什么解决办法

[simpx]

@15015613 #4
你好像贴了两次 strace_ping_normal
另一次 cpu 高时的 strace 结果是什么？

[15015613]

@simpx
抱歉，贴错了
https://gist.github.com/yingziwu/7682fd07c19f35e09c0ffd71f9de08dc


google 出的相似问题
https://unix.stackexchange.com/questions/168873/recvmsg-returns-eagain-resource-temporarily-unavailable

[simpx]

@15015613 #6

从我本地测试来看，"poll([{fd=3, events=POLLIN|POLLERR}], 1, 995)"是用来做超时的，应该是必返回 0. 但在你出问题时候的 poll 调用返回了 1 ，并且是 POLLERR 错误

1. 出错的时候，你 ping 是不是指定了间隔时间？因为你的 poll 第三个参数是 747

2. 能不能在出错的时候"lsof -p pid"看下 fd 3 是不是已经不是原来的 socket 了

[simpx]

@15015613 #6
简单看了 ping 的代码，看起来你的 recvmsg 不支持 SO_RCVTIMEO ，才会用 poll 来做超时。
你可以自己编译一个 ping ， gdb 调试下

代码： http://www.skbuff.net/iputils/

[15015613]

@simpx
发现只有在 ping 的时间足够长，包号特别大的情况下才出现 cpu 使用特别高的情况，时间短的话一切都是正常的。
一般要包号 50000+好像才会出现。

lsof -p 的日志， cpu 使用高时
https://gist.github.com/yingziwu/19845a94e7210eedd8aa6770b682f8f2

正常时
https://gist.github.com/yingziwu/6e5c4023b89b89daae30414f4f01b8f0

[15015613]

@15015613
咦，我明明贴了两个不同的 gist 地址，怎么变成一样了

正常的时候的 lsof -p 的记录
https://gist.github.com/yingziwu/6e5c4023b89b89daae30414f4f01b8f0

[simpx]

@15015613 #10

从你的现象来看，似乎是一旦出错就无法恢复。可能包号大，发包多，出错概率高，一旦出现就不会恢复了。

lsof 上看没什么区别

看来只能自己编译一份试试了，看下 poll 出来的 POLLERR 是什么

实际上这里 poll 改成 sleep 应该也行吧，不知道为什么要用 poll