Continuously high RPD is seen on transit routers.
In the below command output, you will see rpd always on 100%. There were no logs, triggers like commits, or any action performed on the router, but still, rpd would go high randomly and stay high for 10 to 20 minutes.
---(refreshed at 2024-02-16 05:27:35 UTC)---
8506 root 103 0 4619M 3652M CPU1 1 692.0H 100.00% rpd{rpd}
8506 root 20 0 4619M 3652M kqread 2 169:51 0.00% rpd{krtio-th}
8506 root 20 0 4619M 3652M kqread 0 161:21 0.00% rpd{bgpio-0-th}
8506 root 20 0 4619M 3652M kqread 0 88:33 0.00% rpd{TraceThread}
8717 root 20 0 880M 23148K kqread 1 0:53 0.00% rpdtmd
---(refreshed at 2024-02-16 05:27:45 UTC)---
8506 root 103 0 4619M 3652M CPU0 0 692.0H 99.66% rpd{rpd}
8506 root 20 0 4619M 3652M kqread 0 169:51 0.00% rpd{krtio-th}
8506 root 20 0 4619M 3652M kqread 2 88:33 0.00% rpd{TraceThread}
Generally, in cases where the router is in transit and there are no triggers or logs for a high RPD CPU on such a router, it becomes difficult to identify the reason for the high RPD CPU.
This KB is to help you gain an understanding of how to approach and find the root cause in such cases.
Firstly, whenever you see a high RPD CPU, collect the below set of data for complete analysis.
***************** For High RPD CPU *****************Please share graph of below from problematic stateRE CPU graph with 5-minute interval for 2 hours, including the time frame of impactRPD CPU graph with 5-minute interval for 2 hours, including the time frame of impactFPC CPU graph with 5-minute interval for 2 hours, including the time frame of impact+++++ Part 1 of Data collection +++++ Open a new session, enable timestamps, and then "on" task accounting. Execute "show task accounting details" and keep it running for 5 minutes. After 5 minutes, stop the command and turn "off" the task accounting. Please find below the commands for this part. set cli timestamp set task accounting on show task accounting detail | no-more | refresh 10 ---------> Open 1st sessionset task accounting off +++++ Part 2 of Data collection +++++Please start all the sessions of Part 2 at the same time to correlate the data for each output. Please keep it running for 10 minutesshow task io | no-more | refresh 10 ----------> Open 2nd sessionshow task jobs | no-more | refresh 10 ----------> Open 3rd sessionshow krt state | no-more | refresh 10 ----------> Open 4th sessionshow krt queue | no-more | refresh 10 ----------> Open 5th sessionshow krt async queue | no-more | refresh 10 ----------> Open 6th sessionshow krt acknowledgement | no-more | refresh 10 ----------> Open 7th sessionshow system processes extensive | no-more | refresh 10 ----------> Open 8th sessionshow route summary | no-more | refresh 10 ----------> Open 9th sessionshow bgp group | match Flags | no-more | refresh 10 ----------> Open 10th sessionshow bgp neighbor | no-more | refresh 10 ----------> Open 11th sessionshow syshow bgp bmp | no-more | refresh 10 ----------> Open 12th session +++++ Part 3 of Data collection +++++To obtain the ifsmon output, please run these commands three times at an interval of 10 secs:> start shell user rootifsmon -cifsmon -gifsmon -P+++++ Part 4 of Data collection +++++Obtain rtsockmon output from the RE shell:> start shell user root% rtsockmon -nrt >> rtsockmon-jtac <<<< run this command for 15 minute
++++++++ Below is the Analysis ++++++++>> Please check the timestamp when high RPD started and analyze RSI and Varlogs to see if you find any logs.>> With the help of the above command, we collected data from problematic times when the RPD CPU was high.>> Here, RPD is showing high, and it was constantly high for 10 minutes.
+++++ show system process extensive | match rpd +++++ 8506 root 102 0 4619M 3625M CPU1 1 791.9H 98.58% rpd{rpd} -------> high RPD 8506 root 20 0 4619M 3625M kqread 2 189:43 0.10% rpd{krtio-th} 8506 root 20 0 4619M 3625M kqread 2 179:11 0.00% rpd{bgpio-0-th} 8506 root 20 0 4619M 3625M kqread 2 98:35 0.00% rpd{TraceThread} 8717 root 20 0 880M 23116K kqread 1 0:59 0.00% rpdtmd
>> Task jobs and task accounting highlight where exactly RPD is busy. So looking at the below output, we can confirm that RPD is busy with route churn and processing export and import policies.
+++++ show task jobs | no-more +++++Background jobs:Pri Task Job Name Runs Misses Wait Flags 4 bgp-thrio/BGP Read 0 19 1 <SubJob> 4 Resolve tree 1/Nexthop resolution 85 10 1 4 BGP MultiPath/bgp multipath 0 10 1 4 Resolve tree 3/Nexthop resolution 85 10 0 5 RT/Flash update INET6 1 522 1 <SubJob> 5 KRT/Route Install 0 266 1 5 RT/Flash update INET 1 266 1 <SubJob> 6 RT/rt_nh_cache 0 2835 1 6 RT/rt_nh_cache 0 6 0+++++ show task accounting detail | no-more +++++Task accounting is enabled.Task Started User Time System Time Longest RunScheduler 393 0.00375 0.00006 0.00037RT 22 0.00413 0.00005 0.00049 Jobs 22 0.00413 0.00005 0.00049 BGP MultiPath 17 0.70600 0.00071 0.07880 Jobs 17 0.70600 0.00071 0.07880 BGP_RT_Background 1 0.00000 0 0.00000 Timers 1 0.00000 0 0.00000 bgpio-0 230 0.00169 0.00002 0.00008 Jobs 230 0.00169 0.00002 0.00008 bgp-thrio 47 0.03087 0.00017 0.00251 Jobs 47 0.03087 0.00017 0.00251Resolve tree 3 16 1.58089 0.03952 0.10451 Jobs 16 1.58089 0.03952 0.10451 Resolve tree 1 16 1.57423 0.04659 0.10410 Jobs 16 1.57423 0.04659 0.10410+++++ show task accounting detail | no-more +++++Task accounting is enabled.Task Started User Time System Time Longest RunRT 343 0.13581 0.00157 0.00592 Jobs 343 0.13581 0.00157 0.00592 BGP MultiPath 199 7.99677 0.01222 0.07880 Jobs 199 7.99677 0.01222 0.07880bgpio-0 2850 0.01855 0.00791 0.00756 Jobs 2850 0.01855 0.00791 0.00756bgp-thrio 551 2.23126 0.00714 0.10350 Jobs 551 2.23126 0.00714 0.10350Resolve tree 3 175 16.6691 0.57160 0.10650 Jobs 175 16.6691 0.57160 0.10650 Resolve tree 1 199 19.2333 0.84376 0.10431 Jobs 199 19.2333 0.84376 0.10431KRT IO task 123 0.02118 0.00023 0.00252 Jobs 123 0.02118 0.00023 0.00252 KRT 164 0.03774 0.00789 0.00757 Jobs 158 0.03771 0.00789 0.00757 Timers 6 0.00003 0 0.00000
>> You can see there are some routes stuck in KRT queue.
+++++ show krt queue | no-more +++++Routing table add queue: 0 queuedInterface add/delete/change queue: 0 queuedTop-priority deletion queue: 0 queuedTop-priority change queue: 0 queuedTop-priority add queue: 0 queuedhigh priority V4oV6 tcnh delete queue: 0 queuedhigh prioriy anchor gencfg delete queue: 0 queuedHigh-priority multicast add/change: 0 queuedIndirect next hop top priority add/change: 0 queuedIndirect next hop add/change: 0 queuedhigh prioriy anchor gencfg add-change queue: 0 queuedMPLS add queue: 0 queuedIndirect next hop delete: 0 queuedHigh-priority deletion queue: 0 queuedMPLS change queue: 0 queuedHigh-priority change queue: 0 queuedHigh-priority add queue: 0 queuedNormal-priority indirect next hop queue: 0 queuedNormal-priority deletion queue: 0 queuedNormal-priority composite next hop deletion queue: 0 queuedLow prioriy Statistics-id-group deletion queue: 0 queuedNormal-priority change queue: 1 queued CHANGE FROM gf 1 inst id 0 41.75.208.0/20 type 3 (2) kqp '0xdb35e00' TO gf 1 inst id 0 41.75.208.0/20 type 3 -----> This is the problematic route (2) kqp '0xdb35e00'Normal-priority add queue: 1 queued ADD gf 6 inst id 0 2a01:9e00:4d0e::/48 type 3 -----> This is the problematic route kqp '0xdb48880'Least-priority delete queue: 0 queuedLeast-priority change queue: 0 queuedLeast-priority add queue: 0 queuedNormal-priority pfe table nexthop queue: 0 queuedEVPN gencfg queue: 0 queuedNormal-priority gmp queue: 0 queuedRouting table delete queue: 0 queuedLow priority route retry queue: 0 queued
>> The below BGP group output helps us know which BGP groups are having the route churn. The flag below is set for export evaluation, which helps us know churn is taking place in these groups.
+++++ show bgp group | match Flags | no-more +++++Sat Feb 24 12:30:09 UTC 2024 Name: IBGP-LUL-ERR Index: 0 Flags: <Export Eval> Name: IBGP-LUL-FNC-T1 Index: 1 Flags: <Export Eval> Name: IPV6-IBGP-LUL-FNC-T1 Index: 2 Flags: <Export Eval> Name: IBGP-LUL-IRR Index: 3 Flags: <Export Eval> Name: IBGP-LUL-TO-LUL Index: 4 Flags: <Export Eval>
>> Here RTSOCKMON is the important part that helps us know which next- hop is going under route churn, and after analyzing, we could find the below data.>> Below shows which next-hop is getting added, deleted, or changed. There are a few next-hops that are going under these three actions continuously. They are the top contributors to route churn.>> RTSOCKMON ran for 10 minutes, and we could see high numbers of churn.
> start shell user root% rtsockmon -nrt >> rtsockmon-jtac[13:28:23:695.725] rpd rpd PI route add inet6 2a01:9e00:4d0e:: tid=0 plen=48 type=user flags=0x0 nh=comp nhflags=0x0 nhidx=1368 rt_nhiflist = 0 altfwdnhidx=0 filtidx=0 lr_id = 0 featureid=0 rt_mcast_nhiflist=0 dflags 0x0[13:28:23:695.746] rpd self P route add inet6 2a01:9e00:4d0e:: tid=0 plen=48 type=user flags=0x0 nh=comp nhflags=0x4 nhidx=1368 rt_nhiflist = 0 altfwdnhidx=0 filtidx=0 lr_id = 0 featureid=0 rt_mcast_nhiflist=0 dflags 0x0[13:29:45:927.314] rpd rpd PI route add inet 130.137.140.0 tid=0 plen=24 type=user flags=0x0 nh=comp nhflags=0x0 nhidx=736 rt_nhiflist = 0 altfwdnhidx=0 filtidx=0 lr_id = 0 featureid=0 rt_mcast_nhiflist=0 dflags 0x0[13:29:45:927.343] rpd self P route add inet 130.137.140.0 tid=0 plen=24 type=user flags=0x0 nh=comp nhflags=0x4 nhidx=736 rt_nhiflist = 0 altfwdnhidx=0 filtidx=0 lr_id = 0 featureid=0 rt_mcast_nhiflist=0 dflags 0x0[13:29:46:135.360] rpd unknown PI route change inet6 2a01:9e00:4d0e:: tid=0 plen=48 type=user flags=0x0 nh=comp nhflags=0x0 nhidx=1368 rt_nhiflist = 0 altfwdnhidx=0 filtidx=0 lr_id = 0 featureid=0 rt_mcast_nhiflist=0 dflags 0x0[13:29:46:135.398] rpd self P route change inet6 2a01:9e00:4d0e:: tid=0 plen=48 type=user flags=0x0 nh=comp nhflags=0x4 nhidx=1368 rt_nhiflist = 0 altfwdnhidx=0 filtidx=0 lr_id = 0 featureid=0 rt_mcast_nhiflist=0 dflags 0x0[13:28:28:210.373] rpd unknown PI route delete inet6 2a01:9e00:4d0e:: tid=0 plen=48 type=user flags=0x0 nh=dscd nhflags=0x0 nhidx=0 rt_nhiflist = 0 altfwdnhidx=0 filtidx=0 lr_id = 0 featureid=0 rt_mcast_nhiflist=0 dflags 0x0[13:28:28:210.425] rpd rpd P route delete inet6 2a01:9e00:4d0e:: tid=0 plen=48 type=user flags=0x180 nh=comp nhflags=0x4 nhidx=1368 rt_nhiflist = 0 altfwdnhidx=0 filtidx=0 lr_id = 0 featureid=0 rt_mcast_nhiflist=0 dflags 0x0
***** RTSOCKMON output is difficult to sort; use RTSOCKMON Analyzer via below link and upload the file containing RTSOCKMON logs and it will help you get data in below format with all the next-hop going through add/ delete/ change operation ******
Route_v6 -- Add [ Total : 212 ] ================ 2a01:9e00:4d0e:: : 866 ---------------->>>> ThisRoute_v6 -- Delete [ Total : 143 ] ================ 2a01:9e00:4d0e:: : 864 ---------------->>>> This Route_v6 -- Change [ Total : 871 ] ================ 2404:aac0:: : 514 ---------------->>>> This 2600:40fc:1004:: : 406 ---------------->>>> This 2a01:9e00:4d0e:: : 260 2401:2fa0:: : 257
>> This router is not the trigger of high RPD but the victim of route churn, which eventually increases the RPD CPU.>> We can share the above findings with the customer and let them know that they need to check in their network to see where this churn initiated.>> If the above command does not point to any specific problem area, then collect two RPD cores. If RPD stays high for more than 20 minutes, then collect the first core at the start of the high RPD and another one after a gap of 10 minutes or more, depending on the time the RPD CPU stays high.>> You can reach out to Escalation or Engineering for further debugging of the issue after the above data collection.