From billf@mu.org Wed Jun 4 13:26:55 2008 Date: Wed, 4 Jun 2008 13:26:55 -0700 From: bill fumerola To: cisco-nsp@puck.nether.net Subject: interrupt cpu // processor routed packets Message-ID: <20080604202655.GG28936@elvis.mu.org> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline User-Agent: Mutt/1.4.2.3i X-Operating-System: FreeBSD 6.3-MUORG-20080227 amd64 X-PGP-DEAD-Key: 1024D/7F868268 X-PGP-DEAD-Fingerprint: 5B2D 908E 4C2B F253 DAEB FC01 8436 B70B 7F86 8268 X-PGP-Key: 1024D/AE9EB579 Status: RO Content-Length: 21276 Lines: 466 folks, at $WORK we use 7301s as border routers at our sites. recently, we've seen an uptick in cpu. it's too difficult to isolate the change that was made, but it's our belief that some feature or option has caused a majority of packets to be run through the processor as opposed to through cef/caches. this is happening on several routers, but i'll limit the output to one of them. rtr1.ash#sh int stats GigabitEthernet0/0 Switch path Pkts In Chars In Pkts Out Chars Out Processor 2784467772 2512553561 3619252418 92352609 Route cache 1983176953 3753638533 1446323093 1223073183 Total 472677429 1971224798 770608215 1315425792 Tunnel1004 Switch path Pkts In Chars In Pkts Out Chars Out Processor 3025559230 3288625164 3990521 311834632 Route cache 238098300 2332344373 2454903224 3851240155 Total 3263657530 1326002241 2458893745 4163074787 there are more tunnels than tu1004. some of them are key'd, but most are not. rtr1.ash# sh int | i key|checksum Tunnel protocol/transport GRE/IP, key disabled, sequencing disabled Tunnel protocol/transport GRE/IP, key disabled, sequencing disabled Tunnel protocol/transport GRE/IP, key disabled, sequencing disabled Tunnel protocol/transport GRE/IP, key disabled, sequencing disabled Tunnel protocol/transport GRE/IP, key disabled, sequencing disabled Tunnel protocol/transport GRE/IP, key 0x138B, sequencing disabled Tunnel protocol/transport GRE/IP, key 0x138D, sequencing disabled rtr1.ash# gi0/0 has a few .1q subints. one is the local machines, three more are transit providers. the unicast/multicast filter tables are not full. i'm most familiar with the cat6k series and i'm unable to find what is causing the processor path to be tripped. we use GRE tunnels fairly heavily in our setup and it's possible that is what is causing such a surge. the counters wrap from time to time. rtr1.ash#sh proc cpu | e 0.0 CPU utilization for five seconds: 52%/46%; one minute: 53%; five minutes: 57% PID Runtime(ms) Invoked uSecs 5Sec 1Min 5Min TTY Process 5 35199292 87282048 403 0.47% 0.32% 0.52% 0 Pool Manager 46 5504888562337240730 235 4.79% 2.40% 3.62% 0 IP Input rtr1.ash# all the cpu seems to be in interrupt context. what i'm looking for from the list is a plethora of commands to investigate what forwarding path is causing this. i've reached the end of my knowledge on this platform. plenty more output after my .sig -- bill fumerola interface Tunnel1004 description ASH <-> PAO bandwidth 1048576 ip address ip mtu 1500 ip pim sparse-dense-mode keepalive 5 3 ipv6 enable ipv6 ospf 36692 area 0 tunnel source tunnel destination no clns route-cache ! interface GigabitEthernet0/0 description trunk to sw1.ash no ip address no ip proxy-arp duplex full speed 1000 media-type rj45 no negotiation auto no clns route-cache ! interface GigabitEthernet0/0.1 description ash management subnet encapsulation dot1Q 1 native ip address secondary ip address secondary ip address ip access-group PRODUCTION out no ip proxy-arp ntp broadcast ntp multicast ttl 1 ipv6 address XXX::/64 eui-64 ipv6 enable ipv6 nd prefix XXX::/64 ipv6 ospf network broadcast ipv6 ospf 36692 area yyy.yy.yy.y ! these two commands were fired one right after another: rtr1.ash#sh ip cef switching st Path Reason Drop Punt Punt2Host RP RIB Packet destined for us 0 2740402100 0 RP RIB Total 0 2740402100 0 RP LES Packet destined for us 0 2852377644 0 RP LES Encapsulation resource 0 7056820 0 RP LES Total 0 2859434464 0 RP PAS Packet destined for us 130 2852377644 0 RP PAS No adjacency 47098437 0 7291703 RP PAS Incomplete adjacency 9582 0 57 RP PAS TTL expired 0 0 28060459 RP PAS IP options set 0 0 502 RP PAS Bad IP packet length 50 0 0 RP PAS Routed to Null0 505265584 0 2740520 RP PAS Features 623282 0 519123 RP PAS IP redirects 0 0 112010 RP PAS Total 552997065 2852377644 38724374 All Total 552997065 4157246912 38724374 rtr1.ash#sh ip cef switching st Path Reason Drop Punt Punt2Host RP RIB Packet destined for us 0 2740402151 0 RP RIB Total 0 2740402151 0 RP LES Packet destined for us 0 2852377695 0 RP LES Encapsulation resource 0 7056820 0 RP LES Total 0 2859434515 0 RP PAS Packet destined for us 130 2852377695 0 RP PAS No adjacency 47098437 0 7291703 RP PAS Incomplete adjacency 9582 0 57 RP PAS TTL expired 0 0 28060460 RP PAS IP options set 0 0 502 RP PAS Bad IP packet length 50 0 0 RP PAS Routed to Null0 505265584 0 2740520 RP PAS Features 623282 0 519123 RP PAS IP redirects 0 0 112010 RP PAS Total 552997065 2852377695 38724375 All Total 552997065 4157247065 38724375 rtr1.ash#sh int gi0/0 | i flush Input queue: 0/75/110893/113688459 (size/max/drops/flushes); Total output drops: 7 rtr1.ash#sh int gi0/0 | i flush Input queue: 24/75/110893/113688459 (size/max/drops/flushes); Total output drops: 7 rtr1.ash#sh int gi0/0 | i flush Input queue: 0/75/110893/113688459 (size/max/drops/flushes); Total output drops: 7 rtr1.ash#sh int gi0/0 | i flush Input queue: 0/75/110893/113688464 (size/max/drops/flushes); Total output drops: 7 rtr1.ash# rtr1.ash#sh int tun1004 Tunnel1004 is up, line protocol is up Hardware is Tunnel Description: ASH <-> PAO Internet address is MTU 1514 bytes, BW 1048576 Kbit, DLY 500000 usec, reliability 255/255, txload 1/255, rxload 1/255 Encapsulation TUNNEL, loopback not set Keepalive set (5 sec), retries 3 Tunnel source destination fastswitch TTL 255 Tunnel protocol/transport GRE/IP, key disabled, sequencing disabled Tunnel TTL 255 Checksumming of packets disabled, fast tunneling enabled Last input 00:00:00, output 00:00:00, output hang never Last clearing of "show interface" counters never Input queue: 0/75/0/0 (size/max/drops/flushes); Total output drops: 6 Queueing strategy: fifo Output queue: 0/0 (size/max) 5 minute input rate 5898000 bits/sec, 562 packets/sec 5 minute output rate 371000 bits/sec, 429 packets/sec 3263777089 packets input, 1485561186 bytes, 0 no buffer Received 0 broadcasts (216 IP multicast) 0 runts, 0 giants, 0 throttles 0 input errors, 0 CRC, 0 frame, 0 overrun, 0 ignored, 0 abort 2458985720 packets output, 4172988844 bytes, 0 underruns 0 output errors, 0 collisions, 0 interface resets 0 output buffer failures, 0 output buffers swapped out rtr1.ash# rtr1.ash#sh int gi0/0 GigabitEthernet0/0 is up, line protocol is up Hardware is BCM1250 Internal MAC, address is 0019.0723.7c1b (bia 0019.0723.7c1b) Description: trunk to sw1.ash MTU 1500 bytes, BW 1000000 Kbit, DLY 10 usec, reliability 255/255, txload 36/255, rxload 36/255 Encapsulation ARPA, loopback not set Keepalive set (10 sec) Full-duplex, 1000Mb/s, media type is RJ45 output flow-control is unsupported, input flow-control is off ARP type: ARPA, ARP Timeout 04:00:00 Last input 00:00:00, output 00:00:00, output hang never Last clearing of "show interface" counters never Input queue: 0/75/110893/113689811 (size/max/drops/flushes); Total output drops: 7 Queueing strategy: fifo Output queue: 0/40 (size/max) 5 minute input rate 144971000 bits/sec, 105268 packets/sec 5 minute output rate 144617000 bits/sec, 104815 packets/sec 506548581 packets input, 3492190905 bytes, 0 no buffer Received 0 broadcasts (60 IP multicast) 0 runts, 0 giants, 10485 throttles 0 input errors, 0 CRC, 0 frame, 2851 overrun, 0 ignored 0 watchdog, 62466151 multicast, 0 pause input 804535373 packets output, 2855171008 bytes, 0 underruns 5 output errors, 0 collisions, 4 interface resets 0 babbles, 0 late collision, 0 deferred 5 lost carrier, 0 no carrier, 0 PAUSE output 0 output buffer failures, 0 output buffers swapped out GigabitEthernet0/1 is up, line protocol is up (connected) Hardware is Gigabit Ethernet, address is 0017.0ec5.fa81 (bia 0017.0ec5.fa81) Description: trunk to rtr1.ash MTU 1500 bytes, BW 1000000 Kbit, DLY 10 usec, reliability 255/255, txload 36/255, rxload 36/255 Encapsulation ARPA, loopback not set Keepalive set (10 sec) Full-duplex, 1000Mb/s, media type is 10/100/1000BaseTX input flow-control is off, output flow-control is unsupported ARP type: ARPA, ARP Timeout 04:00:00 Last input never, output 00:00:01, output hang never Last clearing of "show interface" counters never Input queue: 0/75/0/0 (size/max/drops/flushes); Total output drops: 0 Queueing strategy: fifo Output queue: 0/40 (size/max) 5 minute input rate 143627000 bits/sec, 99179 packets/sec 5 minute output rate 143913000 bits/sec, 101524 packets/sec 1941640569 packets input, 1959608239 bytes, 0 no buffer Received 14836035 broadcasts (0 multicast) 0 runts, 34 giants, 0 throttles 0 input errors, 0 CRC, 0 frame, 0 overrun, 0 ignored 0 watchdog, 176806 multicast, 0 pause input 0 input packets with dribble condition detected 3253282407 packets output, 3316970055 bytes, 0 underruns 0 output errors, 0 collisions, 1 interface resets 0 babbles, 0 late collision, 0 deferred 0 lost carrier, 0 no carrier, 0 PAUSE output 0 output buffer failures, 0 output buffers swapped out rtr1.ash#sh proc cpu his 4444455555999993333344444555554444444444555557777777777666 1111144444999997777711111000005555500000222222222233333000 100 ***** 90 ***** 80 ***** 70 ***** ********** 60 ***** ************* 50 ********** ********** ****************** 40 ********************************************************** 30 ********************************************************** 20 ********************************************************** 10 ********************************************************** 0....5....1....1....2....2....3....3....4....4....5....5.... 0 5 0 5 0 5 0 5 0 5 CPU% per second (last 60 seconds) 1 11 1 1 1 1 11 11 1 0988900998888909997888909989909978809880088889900889889098 0019400967468707207337308681709178806850030523300526262065 100 * **** *** *** *** ** ** ** * ** 90 ** ******* ******* *********** ******** * ***** * ***** 80 ********************************************************** 70 #**************************************#****************** 60 ###*#*############*#*#*#*#######*###*#####*#*#*#*###*##### 50 ########################################################## 40 ########################################################## 30 ########################################################## 20 ########################################################## 10 ########################################################## 0....5....1....1....2....2....3....3....4....4....5....5.... 0 5 0 5 0 5 0 5 0 5 CPU% per minute (last 60 minutes) * = maximum CPU% # = average CPU% 1111111 1 111 1111 1111111 1 11 0000000999999999999909000980000999999999999999000000090999999999009999 0000000856798789999909000690000699273458869978000000070936721939004555 100 ************************** ******* * ****************** ** * *** *** 90 ********************************************************************** 80 ********************************************************************** 70 ********************************************************************** 60 #####***************************************************************** 50 ########********##############***************#########**************** 40 ###################################################################### 30 ###################################################################### 20 ###################################################################### 10 ###################################################################### 0....5....1....1....2....2....3....3....4....4....5....5....6....6....7. 0 5 0 5 0 5 0 5 0 5 0 5 0 CPU% per hour (last 72 hours) * = maximum CPU% # = average CPU% ------------------ show memory statistics ------------------ Head Total(b) Used(b) Free(b) Lowest(b) Largest(b) Processor 62AE8E20 961638740 316495312 645143428 418466788 407990612 I/O C000000 67108864 3819536 63289328 62389760 59792568 ------------------ show process memory ------------------ Total: 1028747604, Used: 320310832, Free: 708436772 rtr1.ash#sh int stats GigabitEthernet0/0 Switch path Pkts In Chars In Pkts Out Chars Out Processor 2785237678 3111284079 3619643339 664678802 Route cache 2067631367 666969097 1530781222 2423385488 Total 557901749 3778253176 855457265 3088063680 GigabitEthernet0/1 Switch path Pkts In Chars In Pkts Out Chars Out Processor 0 0 0 0 Route cache 0 0 0 0 Total 0 0 0 0 GigabitEthernet0/2 Switch path Pkts In Chars In Pkts Out Chars Out Processor 0 0 0 0 Route cache 0 0 0 0 Total 0 0 0 0 Loopback0 Switch path Pkts In Chars In Pkts Out Chars Out Processor 0 0 142535 8368344 Route cache 0 0 0 0 Total 0 0 142535 8368344 Tunnel4 Switch path Pkts In Chars In Pkts Out Chars Out Processor 373469861 3046343742 3690003 272784327 Route cache 23275816 3725601538 283927218 2806689241 Total 396745677 2476977984 287617221 3079473568 Tunnel504 Switch path Pkts In Chars In Pkts Out Chars Out Processor 17385911 1678075426 3563859 259189688 Route cache 27712845 3025461654 8661024 1259982335 Total 45098756 408569784 12224883 1519172023 Tunnel1004 Switch path Pkts In Chars In Pkts Out Chars Out Processor 3025892770 3796521547 3991045 311877040 Route cache 238161330 2343707136 2455214989 3885274948 Total 3264054100 1845261387 2459206034 4197151988 Tunnel3800 Switch path Pkts In Chars In Pkts Out Chars Out Processor 8211288 2542852750 1525188 114050100 Route cache 62716883 1069521078 74749790 2675399475 Total 70928171 3612373828 76274978 2789449575 Tunnel3801 Switch path Pkts In Chars In Pkts Out Chars Out Processor 714577 74801208 1026386 79775264 Route cache 20998778 1692442218 21744435 2287929534 Total 21713355 1767243426 22770821 2367704798 Tunnel5003 Switch path Pkts In Chars In Pkts Out Chars Out Processor 247537 32510851 226170 21713449 Route cache 15310 10756016 9053 1380467 Total 262847 43266867 235223 23093916 Tunnel5005 Switch path Pkts In Chars In Pkts Out Chars Out Processor 243659 25989478 235628 22812424 Route cache 156 7800422 16057 2281736 Total 243815 33789900 251685 25094160 rtr1.ash# rtr1.ash#sh int counter protocol status Protocols allocated: GigabitEthernet0/0: Other, IP, Spanning Tree, ARP, IPv6 GigabitEthernet0/1: Other, IP GigabitEthernet0/2: Other, IP Loopback0: Other, IP, IPv6 Tunnel4: Other, IP, IPv6 Tunnel504: Other, IP, IPv6 Tunnel1004: Other, IP, IPv6 Tunnel3800: Other, IP, IPv6 Tunnel3801: Other, IP, IPv6 Tunnel5003: Other, IP, IPv6 Tunnel5005: Other, IP, IPv6 Allocation failures: 0 rtr1.ash#sh int ac GigabitEthernet0/0 trunk to sw1.ash Protocol Pkts In Chars In Pkts Out Chars Out Other 264692 15117496 17050137 1055304738 IP 556483091 2335985659 836666136 2558588475 Spanning Tree 75 4620 0 0 ARP 7026907 421614516 7421368 474967552 IPv6 8121 697465 99936 13515042 GigabitEthernet0/1 ibx-ash Protocol Pkts In Chars In Pkts Out Chars Out Other 0 0 901882 54112920 GigabitEthernet0/2 Protocol Pkts In Chars In Pkts Out Chars Out Other 0 0 901882 54112920 Loopback0 Protocol Pkts In Chars In Pkts Out Chars Out IP 113422 4688938 113422 4688938 IPv6 29117 3679692 29117 3679692 Tunnel4 Palo Alto <-> Ashburn Protocol Pkts In Chars In Pkts Out Chars Out IP 396425141 2068923018 286064777 2937637278 IPv6 274798 23175878 264441 22365270 Tunnel504 Seattle <-> Ashburn Protocol Pkts In Chars In Pkts Out Chars Out IP 44806526 4261836688 10672780 1380352723 IPv6 274648 23042300 264085 22375392 Tunnel1004 ASH <-> PAO Protocol Pkts In Chars In Pkts Out Chars Out IP 3263784881 2246072058 2457710040 4052359156 IPv6 256929 21734754 247604 21041124 Tunnel3800 NYC/ASH Protocol Pkts In Chars In Pkts Out Chars Out IP 70628512 3388325615 75423944 2715519036 IPv6 292602 24427300 282672 23686330 Tunnel3801 LON/ASH Protocol Pkts In Chars In Pkts Out Chars Out IP 21423029 1717785221 22174960 2313419422 IPv6 262199 22088760 252611 21415144 Tunnel5003 NYC/ASH Protocol Pkts In Chars In Pkts Out Chars Out IP 165838 26258520 157278 10153234 IPv6 90007 7530632 77966 6609290 Tunnel5005 NYC/ASH Protocol Pkts In Chars In Pkts Out Chars Out IP 146196 16743133 164296 11055686 IPv6 90627 7681266 87411 7442894 rtr1.ash# rtr1.ash#sh ip bgp sum BGP router identifier 208.69.32.1, local AS number 36692 BGP table version is 12344783, main routing table version 12344783 254794 network entries using 28791722 bytes of memory 1261161 path entries using 65580372 bytes of memory 17 multipath network entries and 56 multipath paths 261519/45635 BGP path/bestpath attribute entries using 28244052 bytes of memory 154267 BGP AS-PATH entries using 4121068 bytes of memory 66 BGP community entries using 1632 bytes of memory 0 BGP route-map cache entries using 0 bytes of memory 0 BGP filter-list cache entries using 0 bytes of memory BGP using 126738846 total bytes of memory Dampening enabled. 320 history paths, 596 dampened paths 503501 received paths for inbound soft reconfiguration BGP activity 502024/247223 prefixes, 10834511/9573341 paths, scan interval 60 secs