[c-nsp] CEF CPUHOG on GSR 12.0(S)

Sun Oct 14 17:13:52 EDT 2007

Hello Peter,

Based on the information provided by show cef event command, I can tell that CEF CPU Hog was due to a flapping 128.0.0.0/1 prefix. When this prefix gets installed in a line card forwarding, it is installed almost in the root of the forwarding table. It is CPU intensive and older line cards example Engine 0 and Engine 2 might experience CEF CPU hogs. 

  This issue can be easily solved by adding one additional entry to inbound filter which would deny prefixes with a subnet mask less than 7 bits. Prefixes with subnet mask less than 7 bits are not legal on the internet as far as I know, so it is safe  to drop them.

ip prefix-list example 10 deny 0.0.0.0/0 le 7

Here is a link to Cisco document which talk about CEF CPU hogs.

http://www.cisco.com/warp/public/63/cpuhog.shtml#cpuhog-cef

Thank you

Serguei

> From: pkranz at unwiredltd.com> To: sbezverkhi at hotmail.com; david.freedman at uk.clara.net; cisco-nsp at puck.nether.net> Subject: RE: [c-nsp] CEF CPUHOG on GSR 12.0(S)> Date: Sun, 14 Oct 2007 09:14:54 -0700> > I've been getting these as well:> > System image file is "disk1:gsr-k4p-mz.120-32.S7.bin"> > SLOT 3:Oct 12 00:17:41: %SYS-3-CPUHOG: Task ran for 7124 msec (12/5),> process = CEF LC IPC Background, PC = 400FD7D4.> -Traceback= 400FD7DC 4127876C 412789B0 412798C4> SLOT 3:Oct 12 00:29:19: %SYS-3-CPUHOG: Task ran for 2292 msec (2/0), process> = CEF LC IPC Background, PC = 400FD7D4.> -Traceback= 400FD7DC 4127876C 412789B0 412798C4> > ========= Line Card (Slot 3) =========> > CEF events (165/0 recorded/ignored)> > Time Event Details> +00:00:00.000 SubSys ipfib init> +00:00:00.000 Flag NSF FIB sync set to yes> +00:00:00.464 SubSys ipfib_lc init> +00:00:00.480 SubSys ipfib_bflc init> +00:00:00.796 Process LC IPC created> +00:00:00.800 ReqRld Reload context bg process init. Held off 0 times> +00:00:00.800 Process LC IPC event loop enter> +00:00:00.804 Process LC Stats created> +00:00:00.804 Process LC Stats event loop enter> +00:00:00.812 RldAck reload request acknowledgement> +00:00:13.992 GState Resequence new epoch 1> +00:00:13.992 Flag FIB enabled set to yes> +00:00:13.992 Flag dFIB running set to yes> +00:00:14.020 GState CEF enabled> +00:00:14.024 Process Background created> +00:00:14.032 Flag FIB running set to yes> +00:00:14.032 Process Background event loop enter> +00:00:14.036 Process Scanner created> +00:00:14.036 Flag 0x429C4410 set to yes> +00:00:14.040 Process Scanner event loop enter> +00:00:14.684 Phase fibidbs installed reached> +00:00:22.160 CPUHOG 2512ms XDRtyp 9=control len=13> Hex:0800000003F0A1AD5401> +00:00:22.252 Phase prefixes installed reached> +00:00:22.252 Flag FIB switching running set to yes> +00:00:22.328 Phase linecards ready reached> +00:02:31.596 Phase linecards ready reached> +00:02:51.104 CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:010000C26B5E00FFFFFF0000008000FF00> +00:13:31.056 CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000055724000FFFFE00001008000FF00> +12:11:57.004 CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000505F8000FFFFF00001008000FF00> +14:55:41.520 CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400003F60CB00FFFFFF0001008000FF00> +2d15h CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400004A324000FFFFF00001008000FF00> +6d16h CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400004DF38000FFFFF00001008000FF00> +6d18h CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000CBBE9300FFFFFF0000008000FF00> +1w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000018D88C00FFFFFC0001008000FF00> +1w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000405FC100FFFFFF0001008000FF00> +1w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C3BD5000FFFFFC0000008001FF00> +1w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000059048300FFFFFF0001008000FF00> +1w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000CA33BE00FFFFFF0000008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000056376A00FFFFFF0001008000FF00> +2w2d Flag Switchover in progress set to yes> +2w2d SwitchO Start, mode is sso> +2w2d GState Resequence new epoch 2> +2w2d GState Resequence new epoch 3> +2w2d GState CEF enabled> +2w2d Flag FIB switching running set to no> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0100005767A800FFFFFC0000008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:010000C1E3C800FFFFFE0000008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:010000C35D3800FFFFFF0000008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:010000C8081E00FFFFFE0000008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:010000D4F8C000FFFFC00000008000FF00> +2w2d Phase prefixes installed reached> +2w2d Flag FIB switching running set to yes> +2w2d Flag Switchover in progress set to no> +2w2d SwitchO End> +2w2d Phase linecards ready reached> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000451BA400FFFFFF0000008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:01000052D51B00FFFFFF0001008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:010000792A0000FFFE000001008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:010000CA4FAA00FFFFFE0000008001FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:010000CA8D2500FFFFFF0000008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:01000052B61000FFFFFF0001008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400003D113B00FFFFFF0001008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000436B0D00FFFFFF0001008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000A7D34000FFFFE00001008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400000CC03B00FFFFFF0001008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400003A548000FFFFC00001008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000044558000FFFFE00001008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C6B38200FFFFFF0000008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400009508FC00FFFFFC0001008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400000CA93900FFFFFF0001008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000AA626A00FFFFFF0001008000FF00> +2w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400003CF25000FFFFFE0001008000FF00> +2w2d Phase linecards ready reached> +3w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400008F496400FFFFFF0001008000FF00> +3w3d CPUHOG -4ms XDRtyp 0=prefix len=27> Hex:020000C86C1C00FFFFFF0000008000FF00> +3w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000CBBE7000FFFFFF0000008000FF00> +3w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400003A410100FFFFFF0001808000FF00> +4w0d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000029CD7200FFFFFF0001008000FF00> +4w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400002664F800FFFFFE0001008000FF00> +4w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400000C1B5800FFFFFF0001008000FF00> +4w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400000C6A1E00FFFFFF0001008000FF00> +4w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000CA5B8F00FFFFFF0000808000FF00> +5w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400005BC19400FFFFFC0001008000FF00> +5w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C2094C00FFFFFE0000008001FF00> +5w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000CA08C800FFFFF80000008001FF00> +5w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400000C6A1E00FFFFFF0001008000FF00> +5w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000405FC000FFFFFE0001808000FF00> +5w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000041F7F300FFFFFF0001808000FF00> +5w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000415A3900FFFFFF0001808000FF00> +6w0d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000041C7E400FFFFFF0001808000FF00> +6w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C16F4800FFFFFE0000808001FF00> +6w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000041254400FFFFFC0001008000FF00> +6w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000092DEE100FFFFFF0001808000FF00> +6w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400003D093600FFFFFF0001808000FF00> +6w4d CPUHOG -4ms XDRtyp 0=prefix len=27> Hex:02000059269000FFFFF80001008000FF00> +6w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000052775E00FFFFFF0001808000FF00> +6w5d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400004474F000FFFFF80001008000FF00> +6w5d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000054CD4300FFFFFF0001808000FF00> +7w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000D04C4000FFFFFF0000808000FF00> +7w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000059211000FFFFF00001008000FF00> +7w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000041D50A00FFFFFE0001808000FF00> +7w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000CD5E2000FFFFE00000008001FF00> +7w5d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000059F98000FFFFF00001808000FF00> +7w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000059048100FFFFFF0001808000FF00> +7w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400003FA75100FFFFFF0001808000FF00> +7w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000405FC000FFFFFE0001008000FF00> +7w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C689BB00FFFFFF0000008000FF00> +8w0d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000CB3F1A00FFFFFF0000008000FF00> +8w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000042B8C600FFFFFF0001008000FF00> +8w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000D0BB6400FFFFFF0000008000FF00> +8w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000018205200FFFFFF0001008000FF00> +8w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000505C2200FFFFFE0001808000FF00> +8w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000041D50A00FFFFFE0001808000FF00> +8w5d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000D2D6DC00FFFFFF0000008000FF00> +8w5d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C3A8D000FFFFFF0000808000FF00> +8w5d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400003FAA0B00FFFFFF0001008000FF00> +8w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000D8CB5000FFFFF80000008001FF00> +9w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400005BC44C00FFFFFC0001008000FF00> +9w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400002664D100FFFFFF0001808000FF00> +9w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000896D4000FFFFFE0001808000FF00> +9w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000BE041400FFFFFC0001008000FF00> +9w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000CB225800FFFFFF0000808000FF00> +9w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000AAD27000FFFFF80001008000FF00> +9w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C2C9FD00FFFFFF0000808000FF00> +9w5d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000050575F00FFFFFF0001808000FF00> +10w0d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400008CDB8400FFFFFF0001808000FF00> +10w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000059048100FFFFFF0001008000FF00> +10w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000AAD24400FFFFFF0001808000FF00> +10w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000CA531000FFFFFC0000808001FF00> +10w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000042BB6300FFFFFF0001008000FF00> +10w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000988A0300FFFFFF0001808000FF00> +10w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000CA38FA00FFFFFF0000808000FF00> +10w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400000CC03800FFFFFF0001008000FF00> +11w0d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000515FA000FFFFF80001008000FF00> +11w0d CPUHOG -4ms XDRtyp 0=prefix len=27> Hex:02000094D0EB00FFFFFF0001008000FF00> +11w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000060A08000FFFF800001008000FF00> +11w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C2B7A800FFFFFF0000008000FF00> +11w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:010000CC59C500FFFFFF0000008000FF00> +11w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C2813C00FFFFFF0000008000FF00> +11w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C38A8600FFFFFF0000808000FF00> +11w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000052743800FFFFFC0001008000FF00> +11w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C42E6000FFFFF00000008001FF00> +11w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000052B22000FFFFFE0001808000FF00> +11w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000052C20000FFFFF80001008000FF00> +11w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400003F87F000FFFFF00001008000FF00> +11w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C68CB800FFFFFF0000008000FF00> +11w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400004816A700FFFFFF0001008000FF00> +11w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C15D0400FFFFFC0000008001FF00> +11w5d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000D2D6B100FFFFFF0000808000FF00> +11w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000050F34000FFFFF00001808000FF00> +12w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000BE071C00FFFFFE0001008000FF00> +12w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C83AF800FFFFF80000008001FF00> +12w4d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C6999900FFFFFF0000808000FF00> +12w4d CPUHOG -4ms XDRtyp 0=prefix len=27> Hex:020000551CC000FFFFF00001008000FF00> +12w5d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C8106000FFFFF00000008001FF00> +12w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000042802C00FFFFFF0001808000FF00> +12w6d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000CA2E8100FFFFFF0000008000FF00> +13w1d CPUHOG 7116ms XDRtyp 0=prefix len=38> Hex:010000800000008000000000008001FF00> +13w1d CPUHOG 2292ms XDRtyp 0=prefix len=27> Hex:020000800000008000000000008001FF00> +13w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:04000041056400FFFFFF0001008000FF00> +13w1d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400004DDE6000FFFFF80001008000FF00> +13w2d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:040000C395D800FFFFF80000008001FF00> +13w3d CPUHOG -4ms XDRtyp 0=prefix len=38> Hex:0400005BC16000FFFFFC0001808000FF00> +13w5d CPUHOG 7124ms XDRtyp 0=prefix len=38> Hex:010000800000008000000000008001FF00> +13w5d CPUHOG 2292ms XDRtyp 0=prefix len=27> Hex:020000800000008000000000008001FF00> > Peter Kranz> Founder/CEO - Unwired Ltd> www.UnwiredLtd.com> Desk: 510-868-1614 x100> Mobile: 510-207-0000> pkranz at unwiredltd.com> > -----Original Message-----> From: cisco-nsp-bounces at puck.nether.net> [mailto:cisco-nsp-bounces at puck.nether.net] On Behalf Of Serguei Bezverkhi> Sent: Sunday, October 14, 2007 8:56 AM> To: David Freedman; cisco-nsp at puck.nether.net> Subject: Re: [c-nsp] CEF CPUHOG on GSR 12.0(S)> > Hello David,> > Could you please post the output of the following command:> > exec slot 6 sh cef events> > > This information could help to identify the root cause for CEF CPU Hog.> > Thank you> > Serguei> > > > > Date: Sun, 14 Oct 2007 13:34:08 +0100> From: david.freedman at uk.clara.net>> To: cisco-nsp at puck.nether.net> Subject: [c-nsp] CEF CPUHOG on GSR 12.0(S)> >> Recently we've been seeing some messages in the log with regards to> a> CPUHOG event occuring on some engine 2 linecards we have running.> > It> didn't seem to be traffic affecting, and looked a little like this:> > SLOT> 6:Oct 12 03:17:41 DST: %SYS-3-CPUHOG: Task ran for 7312 msec (0/0),> process> = CEF LC IPC Background, PC = 400FC324.> > Box is running 12.0(32)S5 and has> not logged these messages before.> > This slot faces an upstream provider.>> > Upon speaking with another provider, running 12.0(32)S6, they have> been> seeing the same messages on their kit but not at the same times, on> E2> linecards facing an IXP, they are running S6.> > We are both running IPv6> and I have all routing messages filtered on the> upstream port (in case this> was related to any RH0 nastyness)> > #sh ipv6 access-list> IPv6 access list> bogons6> deny!> ipv6 any any routing sequence 10> <snip>> > One thing of note is that this> could be related to bugid CSCsb12281 but> this does not seem to effect S6,> could any friendly cisco people on here> expand a bit on this bug?> > Many> thanks,> > Dave.> _______________________________________________> cisco-nsp> mailing list cisco-nsp at puck.nether.net>> https://puck.nether.net/mailman/listinfo/cisco-nsp> archive at> http://puck.nether.net/pipermail/cisco-nsp/> _______________________________________________> cisco-nsp mailing list cisco-nsp at puck.nether.net> https://puck.nether.net/mailman/listinfo/cisco-nsp> archive at http://puck.nether.net/pipermail/cisco-nsp/> 