故障排除由 IP Input 进程引起的 High CPU 问题

ywanxin · ‎04-01-2015

本帖最后由 ywanxin 于 2015-4-2 13:21 编辑

我们经常会遇到High CPU的问题，一般来说CPU 分进程高和中断高两种。中断高很多时候是由于实时的流量造成的，要根据网络的实际情况具体分析，原因有很多种，在此不一一列举了。进程高，不同的进程也有不同的root cause。在比较常见的几种占用CPU资源进程中，有一种叫 IP Input。

在 IOS 中，我们把 SW process 叫做 IP Input 进程，顾名思义就是数据报文没有被硬件 switching cache 或者 CEF 处理，而是 punt 到 CPU 去做进一步的处理。对于一个数据包而言，有几种情况会被 punt 到 CPU。

在 switching cache 里没有该报文相关的条目。如该报文的目的地址是 1.1.1.1 而这个目的前缀在如接口所在的 cache 里找不到该条目，那么这个报文将上送CPU做进一步查找。
目的地址是到本机的报文。
广播报文。
IP 头里携带 option 的报文。
需要协议转换的报文。
需要加密或者压缩的报文（如果有了 CSA(Compression Service Adapter)和 ESA(Encryption Service Adapter) 则不需要上送 CPU 只是本地处理了）。
分片报文或者需要重组的报文。（MTU设置的不合理，就可能会出发这类问题）。

故障诊断步骤

步骤 1，通过 show cpu process 或者 sh processes cpu sorted | exclude 0.00 来查看是 CPU 高，CPU 资源是否是被 IP Input 或者其他资源占用了。

l ln-t1a-rt05>sh processes cpu sorted | exclude 0.00
CPU utilization for five seconds: 97%/40%; one minute: 99%; five minutes: 99%
PID Runtime(ms) Invoked uSecs 5Sec 1Min 5Min TTY Process
188 112780212 404873385 278 54.14% 47.34% 48.09% 0 IP Input
452 32291128 170096816 189 1.43% 0.85% 0.60% 0 BGP Router
444 31584160 54483137 579 0.31% 0.19% 0.17% 0 SNMP ENGINE
442 7514572 54233626 138 0.15% 0.12% 0.10% 0 IP SNMP
2 239608 2221363 107 0.07% 0.06% 0.05% 0 Load Meter
332 9940 2296 4329 0.07% 0.07% 0.05% 0 Syslog Traps
433 14477844 2116934 6839 0.07% 0.13% 0.16% 0 Tag Control
321 12935848 171140132 75 0.07% 0.04% 0.05% 0 BGP I/O
259 660104 50553708 13 0.07% 0.04% 0.05% 0 TCP Timer
264 417244 1429570 291 0.07% 0.62% 0.54% 0 XDR mcast
446 265680 424691 625 0.07% 0.19% 0.22% 0 SNMP Traps

步骤 2，如果是 IP Input 进程导致的 CPU 利用率高，那么执行 show interface status 和 show interface，来查看哪些接口有较多的流量需要转发，以及这些接口是用何种转发机制， (fast switching / cef switching /processor)

sh int stat

Switching path Pkts In Chars In Pkts Out Chars Out
Processor 650856 73671257 526830 62471991
Route cache 330217560 821433561 6624091 1799996569
Distributed cache 0 0 0 0
Total 330868416 895104818 7150921 1862468560
Interface POS0/1/0 is disabled <<<<<<<<

FastEthernet1/0/0
Switching path Pkts In Chars In Pkts Out Chars Out
Processor 376139751 259046650 373525823 58361131
Route cache 212836164 1931396850 344019086 233164671
Distributed cache 0 0 0 0
Total 588975961 2190447507 717544911 291525922
Serial1/1/0
Switching path Pkts In Chars In Pkts Out Chars Out
Processor 34782 9898739 869284 85447616
Route cache 14178391 3542542743 206212532 2364427002
Distributed cache 0 0 0 0
Total 14213173 3552441482 207081816 2449874618
Commtouch-SC4-7513#

步骤 3，show ip traffic 的输出，可以告诉我们是哪类流量增长最快，之后我们再检查一下这类流量是否需要上送 CPU 做进一步处理的（参考上述第一部分）。就能得出一个大致的结论----High CPU 问题是什么流量导致的。

Commtouch-SC4-7513#sh ip traffic
IP statistics:
Rcvd: 3764825155 total, 1632039 local destination
0 format errors, 0 checksum errors, 46716 bad hop count
0 unknown protocol, 0 not a gateway
0 security failures, 0 bad options, 7772 with options
Opts: 103 end, 10 nop, 387 basic security, 0 loose source route
0 timestamp, 0 extended security, 44 record route
0 stream ID, 0 strict source route, 7282 alert, 0 cipso
0 other
Frags: 0 reassembled, 0 timeouts, 0 couldn't reassemble
4 fragmented, 0 couldn't fragment
Bcast: 103181 received, 61 sent
Mcast: 0 received, 32678 sent
Sent: 2929975 generated, 3758313272 forwarded
Drop: 54546 encapsulation failed, 0 unresolved, 0 no adjacency
589 no route, 0 unicast RPF, 0 forced drop

ICMP statistics:
Rcvd: 0 format errors, 0 checksum errors, 0 redirects, 10299
unreachable
319787 echo, 24545 echo reply, 0 mask requests, 0 mask replies,
1
quench
0 parameter, 0 timestamp, 0 info request, 0 other
0 irdp solicitations, 0 irdp advertisements
Sent: 0 redirects, 1205238 unreachable, 24671 echo, 319787 echo reply
0 mask requests, 0 mask replies, 0 quench, 0 timestamp
0 info reply, 45869 time exceeded, 0 parameter problem
0 irdp solicitations, 0 irdp advertisements

UDP statistics:
Rcvd: 390403 total, 1 checksum errors, 292907 no port
Sent: 199023 total, 5 forwarded broadcasts

TCP statistics:
Rcvd: 883671 total, 0 checksum errors, 1878 no port
Sent: 1135440 total

Probe statistics:
Rcvd: 0 address requests, 0 address replies
0 proxy name requests, 0 where-is requests, 0 other
Sent: 0 address requests, 0 address replies (0 proxy)
0 proxy name replies, 0 where-is replies

EGP statistics:
Rcvd: 0 total, 0 format errors, 0 checksum errors, 0 no listener
Sent: 0 total

IGRP statistics:
Rcvd: 0 total, 0 checksum errors
Sent: 0 total

OSPF statistics:
Rcvd: 0 total, 0 checksum errors
0 hello, 0 database desc, 0 link state req
0 link state updates, 0 link state acks

Sent: 0 total

IP-IGRP2 statistics:
Rcvd: 0 total
Sent: 0 total

PIMv2 statistics: Sent/Received
Total: 0/0, 0 checksum errors, 0 format errors
Registers: 0/0, Register Stops: 0/0, Hellos: 0/0
Join/Prunes: 0/0, Asserts: 0/0, grafts: 0/0
Bootstraps: 0/0, Candidate_RP_Advertisements: 0/0

IGMP statistics: Sent/Received
Total: 0/0, Format errors: 0/0, Checksum errors: 0/0
Host Queries: 0/0, Host Reports: 0/0, Host Leaves: 00
DVMRP: 0/0, PIM: 0/0

ARP statistics:
Rcvd: 2159586 requests, 978 replies, 0 reverse, 0 other
Sent: 8855 requests, 27586 replies (25987 proxy), 0 reverse

当然，我们也可以通过 debug ip packet(detail) 来更直接地查看到底是什么样的报文上送到CPU触发了CPU High，但是由于此时CPU的利用率已经很高了，所以建议先执行

router(config)#no logging consolerouter(config)#no logging monitor

之后再执行 logging buffered，这样 Debug 的结果将被直接记录到 log buffer 里，而不会再 session 里不停的弹出。最后，show log 就可以看到具体的报文了。

现在可以开始 debug:

router#debug ip packet detailIP packet debugging is on (detailed)

Debug最长不能超过 3 到 5 秒钟。可以使用 undebug all 命令停止：

router#undebug allAll possible debugging has been turned off

可以使用show logging 命令检查结果：

router#show logging
Syslog logging: enabled (0 messages dropped, 0 flushes, 0 overruns)
Console logging: disabled
Monitor logging: disabled
Buffer logging: level debugging, 145 messages logged
Trap logging: level informational, 61 message lines logged
Log Buffer (64000 bytes):

*Mar 3 03:43:27.320: IP: s=192.168.40.53 (Ethernet0/1), d=144.254.2.204
(Ethernet0/0), g=10.200.40.1, len 100, forward
*Mar 3 03:43:27.324: ICMP type=8, code=0
*Mar 3 03:43:27.324: IP: s=192.168.40.53 (Ethernet0/1), d=144.254.2.205
(Ethernet0/0), g=10.200.40.1, len 100, forward
*Mar 3 03:43:27.324: ICMP type=8, code=0
*Mar 3 03:43:27.328: IP: s=192.168.40.53 (Ethernet0/1), d=144.254.2.206
(Ethernet0/0), g=10.200.40.1, len 100, forward
*Mar 3 03:43:27.328: ICMP type=8, code=0

该log显示：

每 4ms 收到一个包
报文的源 IP 地址是 192.168.40.53
报文从 interface Ethernet0/1 进入的.
这些上送 CPU 的报文有不同的destination 地址.
这些报文时从 interface Ethernet0/0 发出去的
报文的下一跳是 10.200.40.1
报文是 ICMP requests (type=8)

在该例中，可以看到IP Input 进程中的 High CPU 是由源自 IP 地址 192.168.40.53 的 ping flood 造成的。

通过这种方式，SYN flood 可以很容易地被发现，因为在 debugging 输出中发现了 SYN flag ：

*Mar 3 03:54:40.436: IP: s=192.168.40.53 (Ethernet0/1), d=144.254.2.204 (Ethernet0/0), g=10.200.40.1, len 44, forward *Mar 3 03:54:40.440: TCP src=11004, dst=53, seq=280872555, ack=0, win=4128 SYN

siyzhang · ‎04-01-2015

沙发！写得很详细，对我非常有帮助！

Ning Zhang · ‎04-01-2015

ISR 平台可以参考这个步奏！

xupeng · ‎04-04-2015

谢谢分享

savi_bj · ‎04-30-2015

我也遇到这个问题了

blgao · ‎04-30-2015

好帖！