%SYS-3-CPUHOG: Per minute Job

Shajil Melethil · ‎12-16-2012

Dear All,

I am facing an issue with one of my router . Accessing the rouer is sometimes for few seconds is hard and feel some delay in sometime while working on it. you can see below output takken from router. I dont understand what could be the problem. We are observing packet loss on the link and when i saw the utilization i suspect si it due to CPU or something ?

Please let me know your findings and if you need more output let me know to provide you

Shajil

RTR#sh processes cpu history

RTR06:12:54 AM Sunday Dec 16 2012 UTC

17777
022223333333333333333322222333332222244444222223333355555444
100
90
80
70 ****
60 ****
50 ****
40 ****
30 ****
20 ****
10 ***** *****
0....5....1....1....2....2....3....3....4....4....5....5....6
0 5 0 5 0 5 0 5 0 5 0
CPU% per second (last 60 seconds)

67777 7 7 7 7 73767676767676767777 7 7 7 7 73767676767676767
422225252625252624242424342424222252526253526242424242424243
100
90
80
70 **** * * * * * * * * * * * * **** * * * * * * * * * * * * *
60 ***** * * * * * ****************** * * * * * ***************
50 ***** * * * * * ****************** * * * * * ***************
40 ***** * * * * ******************** * * * * *****************
30 ***** * * * * ******************** * * * * *****************
20 ****# # # # # #******************# # # # # #****************
10 #####*#*#*#*#*####################*#*#*#*#*#################
0....5....1....1....2....2....3....3....4....4....5....5....6
0 5 0 5 0 5 0 5 0 5 0
CPU% per minute (last 60 minutes)
* = maximum CPU% # = average CPU%

1
7777777777777770999
3323333332323430999
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%

RTR#

RTR#sh processes cpu sorted
CPU utilization for five seconds: 8%/0%; one minute: 12%; five minutes: 11%
PID Runtime(ms) Invoked uSecs 5Sec 1Min 5Min TTY Process
192 384 83980 4 4.17% 0.37% 0.08% 578 Virtual Exec
43 1105532 68832 16061 1.72% 1.70% 1.71% 0 Per-Second Jobs
5 106732 9602 11115 0.98% 0.17% 0.13% 0 Check heaps
227 221668 448104 494 0.65% 0.54% 0.51% 0 Crypto IKMP
48 110460 14238 7758 0.16% 0.16% 0.16% 0 Compute load avg
291 4776 4746 1006 0.16% 0.01% 0.00% 0 BGP Scanner
2 2592 14237 182 0.08% 0.02% 0.00% 0 Load Meter
238 2940 341862 8 0.08% 0.05% 0.06% 0 Atheros LED Ctro
107 24704 310326 79 0.08% 0.07% 0.06% 0 IP Input
106 736 2039374 0 0.08% 0.02% 0.00% 0 IP ARP Retry Age
169 4172 667676 6 0.08% 0.08% 0.08% 0 RBSCP Background
117 340 267549 1 0.08% 0.00% 0.00% 0 SSS Feature Time
27 59112 13938 4241 0.08% 0.13% 0.14% 0 HC Counter Timer
13 0 1 0 0.00% 0.00% 0.00% 0 IPC Zone Manager
12 4 1188 3 0.00% 0.00% 0.00% 0 IPC Dynamic Cach
14 36 68229 0 0.00% 0.00% 0.00% 0 IPC Periodic Tim
15 40 68229 0 0.00% 0.00% 0.00% 0 IPC Deferred Por
18 0 19 0 0.00% 0.00% 0.00% 0 ARP Input
16 0 1 0 0.00% 0.00% 0.00% 0 IPC Seat Manager
20 0 2 0 0.00% 0.00% 0.00% 0 ATM Idle Timer
17 0 1 0 0.00% 0.00% 0.00% 0 IPC BackPressure
19 328 71731 4 0.00% 0.00% 0.00% 0 ARP Background
23 0 1 0 0.00% 0.00% 0.00% 0 Policy Manager
24 0 2 0 0.00% 0.00% 0.00% 0 DDR Timers
25 0 4 0 0.00% 0.00% 0.00% 0 Entity MIB API
26 44 934 47 0.00% 0.00% 0.00% 0 EEM ED Syslog
21 0 2 0 0.00% 0.00% 0.00% 0 AAA high-capacit
28 0 2 0 0.00% 0.00% 0.00% 0 Serial Backgroun
29 0 1 0 0.00% 0.00% 0.00% 0 RO Notify Timers
30 0 1 0 0.00% 0.00% 0.00% 0 RMI RM Notify Wa
22 0 1 0 0.00% 0.00% 0.00% 0 AAA_SERVER_DEADT
32 72 68809 1 0.00% 0.00% 0.00% 0 GraphIt
33 0 2 0 0.00% 0.00% 0.00% 0 Dialer event
31 0 2 0 0.00% 0.00% 0.00% 0 SMART
35 0 2 0 0.00% 0.00% 0.00% 0 XML Proxy Client
36 0 2 0 0.00% 0.00% 0.00% 0 cpf_process_msg_
37 0 1 0 0.00% 0.00% 0.00% 0 Inode Table Dest
38 0 1 0 0.00% 0.00% 0.00% 0 Critical Bkgnd
39 124076 107980 1149 0.00% 0.25% 0.25% 0 Net Background
40 0 3 0 0.00% 0.00% 0.00% 0 IDB Work
41 92 1435 64 0.00% 0.00% 0.00% 0 Logger
42 92 68212 1 0.00% 0.00% 0.00% 0 TTY Background
8 0 1 0 0.00% 0.00% 0.00% 0 OIR Handler

some omitted.

RTR#sh version
Cisco IOS Software, 3800 Software (C3825-ADVIPSERVICESK9-M), Version 12.4(15)T7,
RELEASE SOFTWARE (fc3)
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 1986-2008 by Cisco Systems, Inc.
Compiled Wed 13-Aug-08 23:16 by prod_rel_team

ROM: System Bootstrap, Version 12.4(13r)T10, RELEASE SOFTWARE (fc1)

NCB-DETECON-MITC uptime is 19 hours, 47 minutes
System returned to ROM by Reload Command at 10:21:54 UTC Sat Dec 15 2012
System image file is "flash:c3825-advipservicesk9-mz.124-15.T7.bin"

This product contains cryptographic features and is subject to United
States and local country laws governing import, export, transfer and
use. Delivery of Cisco cryptographic products does not imply
third-party authority to import, export, distribute or use encryption.
Importers, exporters, distributors and users are responsible for
compliance with U.S. and local country laws. By using this product you
agree to comply with applicable laws and regulations. If you are unable
to comply with U.S. and local laws, return this product immediately.

A summary of U.S. laws governing Cisco cryptographic products may be found at:
http://www.cisco.com/wwl/export/crypto/tool/stqrg.html

If you require further assistance please contact us by sending email to
export@cisco.com.

Cisco 3825 (revision 1.2) with 487424K/36864K bytes of memory.
Processor board ID FCZ1307722E
2 Gigabit Ethernet interfaces
2 Virtual Private Network (VPN) Modules
DRAM configuration is 64 bits wide with parity enabled.
479K bytes of NVRAM.
126976K bytes of ATA System CompactFlash (Read/Write)

Configuration register is 0x2102

RTR#

RTR#sh logging
Syslog logging: enabled (12 messages dropped, 410 messages rate-limited,
0 flushes, 0 overruns, xml disabled, filtering disabled)

No Active Message Discriminator.

No Inactive Message Discriminator.

Console logging: level debugging, 1504 messages logged, xml disabled,
filtering disabled
Monitor logging: level debugging, 0 messages logged, xml disabled,
filtering disabled
Buffer logging: level debugging, 1912 messages logged, xml disabled,
filtering disabled
Logging Exception size (4096 bytes)
Count and timestamp logging messages: disabled
Persistent logging: disabled

No active filter modules.

ESM: 0 messages dropped

Trap logging: disabled

Log Buffer (4096 bytes):
(2/1),process = Per-minute Jobs.
-Traceback= 0x6337B3DC 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x63114D54 0x
629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:00:49.727: %SYS-3-CPUHOG: Task is running for (4004)msecs, more than
(2000)msecs (2/1),process = Per-minute Jobs.
-Traceback= 0x6339AC7C 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x
63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:02:47.727: %SYS-3-CPUHOG: Task is running for (2004)msecs, more than
(2000)msecs (1/0),process = Per-minute Jobs.
-Traceback= 0x6339ACB8 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x
63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:02:49.731: %SYS-3-CPUHOG: Task is running for (4004)msecs, more than
(2000)msecs (2/0),process = Per-minute Jobs.
-Traceback= 0x6339AD50 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x
63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:04:47.727: %SYS-3-CPUHOG: Task is running for (2004)msecs, more than
(2000)msecs (1/0),process = Per-minute Jobs.
-Traceback= 0x6339ACB8 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x
63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:04:49.731: %SYS-3-CPUHOG: Task is running for (4004)msecs, more than
(2000)msecs (2/0),process = Per-minute Jobs.
-Traceback= 0x6339AC7C 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x
63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:06:47.727: %SYS-3-CPUHOG: Task is running for (2004)msecs, more than
(2000)msecs (1/0),process = Per-minute Jobs.
-Traceback= 0x6339AC7C 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x
63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:06:49.731: %SYS-3-CPUHOG: Task is running for (4004)msecs, more than
(2000)msecs (2/0),process = Per-minute Jobs.
-Traceback= 0x616A10B4 0x6339D110 0x6339ACFC 0x6337B420 0x6339F508 0x6338E924 0x
63114CC4 0x6339ACFC 0x63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:08:47.727: %SYS-3-CPUHOG: Task is running for (2004)msecs, more than
(2000)msecs (1/0),process = Per-minute Jobs.
-Traceback= 0x6339ACB8 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x
63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:08:49.731: %SYS-3-CPUHOG: Task is running for (4004)msecs, more than
(2000)msecs (2/0),process = Per-minute Jobs.
-Traceback= 0x6339ACB8 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x
63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:10:47.727: %SYS-3-CPUHOG: Task is running for (2004)msecs, more than
(2000)msecs (1/0),process = Per-minute Jobs.
-Traceback= 0x6339AC94 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x
63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:10:49.731: %SYS-3-CPUHOG: Task is running for (4004)msecs, more than
(2000)msecs (2/0),process = Per-minute Jobs.
-Traceback= 0x6339ACB8 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x
63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:12:47.727: %SYS-3-CPUHOG: Task is running for (2004)msecs, more than
(2000)msecs (2/1),process = Per-minute Jobs.
-Traceback= 0x6339ACB4 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x
63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:12:49.731: %SYS-3-CPUHOG: Task is running for (4004)msecs, more than
(2000)msecs (3/1),process = Per-minute Jobs.
-Traceback= 0x6339ACB8 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x6339ACFC 0x
63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:14:47.727: %SYS-3-CPUHOG: Task is running for (2004)msecs, more than
(2000)msecs (1/0),process = Per-minute Jobs.
-Traceback= 0x616A10D8 0x6339D110 0x6339ACFC 0x6337B420 0x6339F508 0x6338E924 0x
63114CC4 0x6339ACFC 0x63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124
*Dec 16 06:14:49.731: %SYS-3-CPUHOG: Task is running for (4004)msecs, more than
(2000)msecs (2/0),process = Per-minute Jobs.
-Traceback= 0x6339D148 0x6339ACFC 0x6337B420 0x6339F508 0x6338E924 0x63114CC4 0x
6339ACFC 0x63114D54 0x629F7C40 0x6067BBEC 0x629C1140 0x629C1124

could you please let me know any solution ?

Thnaks

Shajil

jiangchenchen · ‎04-02-2013

I have config eigrp protocol ,line protocol on interface ,changed state to up / down ,

then display %sys-3-cpuhog:task is running for (2004) msecs, more than (2000) msecs(2996/195) process=net input

-traceback=0x41155B68 …………..

nbr changed down ,interface goodbye received..

please tell me how do i solution?

paolo bevilacqua · ‎04-03-2013

You should consider moving away from EIGRP and its many defects.

InayathUlla Sharieff · ‎04-02-2013

Hi Shajil,

I just decoded the traceback and The bugs listed below, are likely to be the root cause of the

problem, and upgrading to a version in which the bug is integrated will most probably solve the issue.

Most likely bugs (of a total of 5 matches):

- CSCsa87076 - Adding acl to client triggers spurious accesses in process Crypto IKMP, R

Fixed in versions : 12.4(2.2) 12.4(2.2)T 12.4(22.3.4)PIC1 12.4(24.5.2)PIC1

- CSCsb81265 - IKE negotiation fails using security ipsec in stateful switch over (SSO), R

Fixed in versions : 12.4(5.2)T 12.4(5.3)PI3a 12.4(22.3.4)PIC1 12.4(24.5.2)PIC1

- CSCsl49350 - Console keep showing %SYS-3-CPUHOG, process =Per-minute Jobs, R

Fixed in versions : 12.2(32.8.11)SRC5 12.2(32.8.11)SR114 12.2(33)SRC 12.4(18.4)T1 12.2(32.8.11)SX150 12.2(32.8.99a)SR133 12.5(0.7) 12.2(50)SY

- CSCtl00995 - ikev2: ASR1K with 1897 svti tunnels & ikev2 reloads @ IPSEC Key Engine, R

Fixed in versions : 15.2(0.16)T 15.2(0.5)S 15.1(2.16)S0.7 15.2(0.6)S 15.2(0.17.1)PIA17 15.2(0.13.6)PIB17 15.2(0.17.3)PIA17 15.1(1)SG5.32 15.1(2)S1.4 15.1(1)SG5.33 15.1(4)M1.1 15.1(2)EY 15.1(2)S2 15.1(1)SG5.83.1 15.1(1)SG5.78.11 15.1(3)S 15.1(1)SG5.98 15.1(1)SG5.13 15.1(4)XB6 15.1(1)SG5.124 15.1(1)SG5.163 15.1(1)SG5.169 15.1(1)SG5.170 15.0(5.21)SID 15.1(1)SD5.1 15.1(2)SNH 15.1(2)SNH1 15.0(5.2)DPB35 15.1(4)GC 15.1(3)MR 15.1(1)SY 15.1(4)M2 15.2(1.0.0)IPI2

HTH

Regards

Inayath

*Plz rate the usefull posts.

Shajil Melethil · ‎04-09-2013

Hi Inayat,

Thanks for the email. I upgraded IOS before. i was trying a luck. but u did a good experiment and reached to the exact point of upgradation. You are great.

Please also let know how to decode the traceback ?

InayathUlla Sharieff · ‎04-09-2013

Hi Shajil,

We dont have any external tool to provide to decode the traceback.

I had decoded your traceback and its exactly matching the bug which I stated above.

CSCsl49350 <http://cdetsweb-prd.cisco.com/apps/goto?identifier=CSCsl49350> CSCsl49350

which is a non-process impacting Bug. The Symptoms and the workaround for

this Bug is as mentioned below.

Symptoms

An IOS router that has been configured with large amount of Static Virtual

IPsec tunnels (sVTI) could experience CPUHOG errmsg from the process of

Per-minute Jobs.

Condition

This issue shows up when all of the below conditions are met:

a) large amount (500-2000) of static VTI tunnels has been configured

b) the ipsec negotiations for those tunnels have been failed, and by design the sVTI, it will keep negotiating for IKE/IPsec SAs until all the

tunnel have been brought up (sVTI can only be up when IPsec SAs are up).

Workaround

1) shut down all the sVTI tunnels, and then unshut a small number (~50)

at a time to bring them up, then thep-by-step to bring all the other tunnels; or,

2) use crypto map or tunnel protection (GRE+Ipsec) configuration

HTH

Regards

Inayath

*Please do not forget to rate the post and close the thread if no more info required.