[nsp] CEF Scanning / CEF process high CPU utilization?

[Francisco Rivas]

Hi all,

I have several 7206vxr, with NPE-300, and FE/GB interfaces.
A week ago, we did an IOS upgrade to 12.2(18)S4, and all the routers
worked without any problems, except one. This one is configured almost
exactly as the others (BGP,ISIS,OSPF,MPLS), the only extra thing is RIP
running for a couple of clients there. This router is heavily loaded
(70%-80% cpu utilization), but one of the process that uses most CPU is
the "CEF Scanner". This behavior doesn't appears on the old IOS (that
was 12.2(14)s3 ), so I tried 12.2(18)S5 too, and it shows the same
behavior. So, I downloaded IOS 12.2(14)S5, and it seems to run more
stable, with lower CPU utilization.

For example, this is the CPU utilization with 12.2(18)S4, at night, when
the router have less traffic (about 30-35 megs up/down):

7206x3#show processes cpu sorted 5min | include CEF
 110        9016       217      41548 48.62%  7.49%  1.78%   0 CEF
Scanner
  74         608       176       3454  2.28%  0.20%  0.04%   0 CEF
process
7206x3#show processes cpu sorted 5min | include CEF
 110       11056       225      49137 42.49% 10.29%  2.46%   0 CEF
Scanner
  74         720       179       4022  6.38%  0.70%  0.14%   0 CEF
process


This is the CPU utilization with 12.2(14)S5, at the time that I'm
writing this email, with more traffic (about 50-60 megs up/down):

7206x3#show processes cpu sorted 5min | include CEF
  66       19816    104706        189  0.00%  0.02%  0.00%   0 CEF
process      
 102      307928      5420      56813  0.00%  0.00%  0.00%   0 CEF
Scanner      
7206x3#show processes cpu sorted 5min | include CEF
  66       19952    105098        189  0.08%  0.02%  0.00%   0 CEF
process      
 102      307940      5440      56606  0.00%  0.00%  0.00%   0 CEF
Scanner      



I did some debug on the router while changing IOS, and I've got several
logs like this:

Jun 11 04:36:40 UTC: CEF: background resolution thread state:
Jun 11 04:36:40 UTC: Thread fast_thread: Empty
Jun 11 04:36:40 UTC: Thread todothread: Empty
Jun 11 04:36:40 UTC: Thread slow_thread: Empty
Jun 11 04:36:41 UTC: CEF: Scanner - FIB scan walker started
Jun 11 04:36:41 UTC: CEF: Scanner - no loadsharing check, no adjacency
check, no stats check
Jun 11 04:36:42 UTC: CEF: background resolution thread state:
Jun 11 04:36:42 UTC: Thread fast_thread: Empty
Jun 11 04:36:42 UTC: Thread todothread: Empty
Jun 11 04:36:42 UTC: Thread slow_thread: Empty
Jun 11 04:36:43 UTC: CEF: Scanner - CEF scan walker completed
Jun 11 04:36:43 UTC: CEF: background resolution thread state:
Jun 11 04:36:43 UTC: Thread fast_thread: Empty
Jun 11 04:36:43 UTC: Thread todothread: Empty
Jun 11 04:36:43 UTC: Thread slow_thread:
Jun 11 04:36:43 UTC:  Path 0 for prefix 10.10.225.0/30 (flags 3)
Jun 11 04:36:43 UTC:  Path 0 for prefix 10.10.224.0/30 (flags 3)
Jun 11 04:36:43 UTC:  Path 0 for prefix 10.10.196.0/30 (flags 3)
Jun 11 04:36:43 UTC:  Path 0 for prefix 10.10.188.0/30 (flags 3)

<several lines with many prefixes>

Jun 11 04:36:43 UTC:  Path 0 for prefix 200.43.252.0/22 (flags 3)
Jun 11 04:36:43 UTC:  Path 0 for prefix 200.43.248.0/22 (flags 3)
Jun 11 04:36:46 UTC: CEF: background resolution thread state:
Jun 11 04:36:46 UTC: Thread fast_thread: Empty
Jun 11 04:36:46 UTC: Thread todothread: Empty
Jun 11 04:36:46 UTC: Thread slow_thread: Empty
Jun 11 04:36:46 UTC: CEF:background resolution [1s, gone idle]
Jun 11 04:36:47 UTC: CEF: background resolution thread state:
Jun 11 04:36:47 UTC: Thread fast_thread: Empty
Jun 11 04:36:47 UTC: Thread todothread: Empty
Jun 11 04:36:47 UTC: Thread slow_thread: Empty
Jun 11 04:36:48 UTC: CEF: background resolution thread state:
Jun 11 04:36:48 UTC: Thread fast_thread: Empty
Jun 11 04:36:48 UTC: Thread todothread: Empty
Jun 11 04:36:48 UTC: Thread slow_thread: Empty
Jun 11 04:36:48 UTC: CEF: Scanner - FIB scan walker started
Jun 11 04:36:48 UTC: CEF: Scanner - no loadsharing check, no adjacency
check, no stats check
Jun 11 04:36:49 UTC: CEF: background resolution thread state:
Jun 11 04:36:49 UTC: Thread fast_thread: Empty
Jun 11 04:36:49 UTC: Thread todothread: Empty
Jun 11 04:36:49 UTC: Thread slow_thread: Empty
Jun 11 04:36:50 UTC: CEF: Scanner - CEF scan walker completed
Jun 11 04:36:50 UTC: CEF: Scanner - FIB scan walker started
Jun 11 04:36:50 UTC: CEF: Scanner - no loadsharing check, no adjacency
check, no stats check
Jun 11 04:36:51 UTC: CEF: background resolution thread state:
Jun 11 04:36:51 UTC: Thread fast_thread: Empty
Jun 11 04:36:51 UTC: Thread todothread: Empty
Jun 11 04:36:51 UTC: Thread slow_thread: Empty
Jun 11 04:36:52 UTC: CEF: background resolution thread state:
Jun 11 04:36:52 UTC: Thread fast_thread: Empty
Jun 11 04:36:52 UTC: Thread todothread: Empty
Jun 11 04:36:52 UTC: Thread slow_thread:
Jun 11 04:36:52 UTC:  Path 0 for prefix 10.10.225.0/30 (flags 3)
Jun 11 04:36:52 UTC:  Path 0 for prefix 10.10.224.0/30 (flags 3)
Jun 11 04:36:52 UTC:  Path 0 for prefix 10.10.196.0/30 (flags 3)
Jun 11 04:36:52 UTC:  Path 0 for prefix 10.10.188.0/30 (flags 3)
Jun 11 04:36:52 UTC:  Path 0 for prefix 10.10.176.4/30 (flags 3)

<and again, several lines with many prefixes>

Jun 11 04:36:52 UTC:  Path 0 for prefix 200.46.196.0/23 (flags 3)
Jun 11 04:36:55 UTC: CEF: background resolution thread state:
Jun 11 04:36:55 UTC: Thread fast_thread: Empty
Jun 11 04:36:55 UTC: Thread todothread: Empty
Jun 11 04:36:55 UTC: Thread slow_thread: Empty
Jun 11 04:36:55 UTC: CEF:background resolution [1s, gone idle]

And this repeats forever...


So, my questions are:

- what's the meaning of the "Path 0 for prefix X.X.X.X/X" ??

- could this be the cause of the high CPU utilization??? I've run the
debug on another router, doing almost the same job, and I've never seen
any messages about "Path 0 for prefix...". The strange thing, is that
the other routers are running 12.2(18)S4 without any problems.

- what else could I do to detect why the CEF Scanner is eating the
CPU???



Thanks a lot for any help on this issue :)

-- 
--
Francisco Rivas Catalan
Senior Network Engineer
IFX Networks
francisco.rivas at ifxnw.cl
(56) 2 3744500