概要
本ドキュメントでは、IOS-XR ルータにて CPU 使用率高騰時のトラブルシューティング方法について解説しています。
IOS-XR ルータは Route processor (RP) や Line card (LC) 等のノード上にそれぞれ CPU が搭載されており、各 CPU 上では複数のプロセスが、各 プロセス内部では複数のスレッドがお互いに独立して動作するマルチプロセス・マルチスレッドな分散ソフトウェアアーキテクチャとなっております。
そのため CPU 使用率が高騰した場合等のプロセスに関するトラブルシューティングを実施する際は、以下の手順にて被疑箇所を特定することがまず重要になります。
- どのノードの CPU 使用率が高騰しているか?
- どのプロセスの CPU 使用率が高騰しているか?
- 被疑プロセスはどのような処理を行っているか?
1. 被疑ノードの特定: どのノードの CPU 使用率が高騰しているか?
a) admin show platform
IOS-XR ルータ上のノード情報一覧を admin show platform コマンドにて確認します。
admin show platform
RP/0/RSP0/CPU0:ASR9K#admin show platform
Node Type State Config State
-----------------------------------------------------------------------------
0/RSP0/CPU0 A9K-RSP880-TR(Active) IOS XR RUN PWR,NSHUT,MON
0/RSP1/CPU0 A9K-RSP880-TR(Standby) IOS XR RUN PWR,NSHUT,MON
0/FT0/SP ASR-9904-FAN READY
0/0/CPU0 A9K-40GE-SE IOS XR RUN PWR,NSHUT,MON
0/1/CPU0 A9K-8X100GE-L-SE UNPOWERED NPWR,NSHUT,MON
0/PM0/0/SP PWR-3KW-AC-V2 READY PWR,NSHUT,MON
0/PM0/1/SP PWR-3KW-AC-V2 READY PWR,NSHUT,MON
- IOS-XR ルータのプラットフォーム種別 (CRS/ASR9K など) により異なりますが、基本的には名前に CPU が含まれるものがノードとなります。
b) top
次に各ノード毎の CPU 使用率を top コマンドにより確認します。
下記例では LC 0/0/CPU0 の CPU 使用率を確認しています。
top dumbtty location 0/0/CPU0
RP/0/RSP0/CPU0:ASR9904b#top dumbtty location 0/0/CPU0
Computing times...168 processes; 736 threads;
CPU states: 95.8% idle, 3.8% user, 0.3% kernel
Memory: 8192M total, 5685M avail, page size 4K
JID TID LAST_CPU PRI STATE HH:MM:SS CPU COMMAND
181 1 3 10 Rcv 1:01:21 0.57% fialc
57 5 1 21 Intr 0:09:58 0.45% eth_server
57 1 0 10 Rcv 0:01:39 0.41% eth_server
85 7 2 10 Rdy 0:01:44 0.36% qnet
85 6 1 10 Rply 0:03:10 0.36% qnet
--snip--
上記出力例より、下記の状態を確認することができます。
- LC 0/0/CPU0 の CPU 使用率は 4.2 % (95.8% が Idle 状態: 特別な処理を行っていない状態)
- CPU 使用率 4.2 % のうちユーザプロセスによる CPU 使用率が 3.8%
- CPU 使用率 4.2 % のうちカーネルによる CPU 使用率が 0.3%
- dumbtty オプションにより top コマンドによる出力結果が上書きされることなく追加出力されます。
2. 被疑プロセスの特定: どのプロセスの CPU 使用率が高騰しているか?
a) show processes cpu
被疑ノードを特定した後は、どのプロセスの CPU 使用率が高騰しているかを show processes cpu コマンドにて確認します。
下記例では Active RSP である 0/RSP0/CPU0 上の各プロセスの CPU 使用率を確認しています。
show processes cpu location 0/RSP0/CPU0
RP/0/RSP0/CPU0:ASR9K#show processes cpu location 0/RSP0/CPU0
CPU utilization for one minute: 6%; five minutes: 2%; fifteen minutes: 1%
PID 1Min 5Min 15Min Process
1 0% 0% 0% kernel
8195 0% 0% 0% dllmgr
12290 0% 0% 0% wd-critical-mon
12295 0% 0% 0% pkgfs
12296 0% 0% 0% devc-ser8250
--snip--
上記出力例より、ノード 0/RSP0/CPU0 上にて下記の状態を確認することができます。
- 過去 1 分の平均 CPU 使用率は 6 %
- 過去 5 分の平均 CPU 使用率は 2 %
- 過去 15 分の平均 CPU 使用率は 1 %
各プロセス毎の過去 1 分、5 分、15 分の平均 CPU 使用率もプロセス ID (PID) 順に出力されるため、CPU 使用率の高い被疑プロセスを確認することができます。
なお、上記出力のうち過去の平均 CPU 使用率が 0% 以外のものだけを以下のような正規表現で抽出することもできます。
show processes cpu location 0/RSP0/CPU0 | exclude 0%.*0%.*0%
RP/0/RSP0/CPU0:ASR9K#show processes cpu location 0/RSP0/CPU0 | exclude 0%.*0%.*0%
CPU utilization for one minute: 6%; five minutes: 2%; fifteen minutes: 1%
PID 1Min 5Min 15Min Process
90153 1% 1% 1% eth_server
229543 1% 1% 1% fib_mgr
553271 1% 1% 1% ipv4_rib
557264 2% 1% 1% bgp
3. 被疑プロセスの状態確認: 被疑プロセスはどのような処理を行っているか?
被疑プロセスを特定した後は、どのような処理で被疑プロセスの CPU 使用率が高騰しているかを確認します。
下記ログを定期的に取得してモニタリングすることにより、被疑プロセスがどのような処理を行っているかをある程度把握することができます。
- show processes blocked コマンド
- show processes <process name> コマンド
- follow jobid <Job ID> iteration 1 stackonly コマンド
- 例えば 10 秒おきに 3 回取得するなど、状況に応じて複数回定期的に取得します。
a) show processes blocked
show processes blocked コマンドの出力結果より、特定ノード上のプロセス間通信の状態を確認することができます。
下記は 0/RSP0/CPU0 上の状態を確認した出力例となります。
show processes blocked
RP/0/RSP0/CPU0:ASR9K#show processes blocked
Jid Pid Tid Name State TimeInState Blocked-on
--snip --
86 135204 6 qnet Reply 0:00:00:0001 90153 eth_server
60 90153 2 eth_server Mutex 0:00:00:0000 0-00 #0
65578 98346 2 devb-umass Reply 0:00:01:0921 98344 io-usb
52 135215 2 attach_server Reply 101:19:03:0649 12303 mqueue
426 200795 1 tftp_server Reply 101:16:11:0519 12303 mqueue
310 540905 2 lpts_fm Reply 0:00:10:0069 221327 lpts_pa
65789 2212093 1 exec Reply 0:00:00:0065 1 kernel
1144 553271 6 ipv4_rib Reply 0:00:00:0000 553271 ipv4_rib
65856 2695488 1 more Reply 0:00:00:0009 12301 pipe
65860 2695492 1 show_processes Reply 0:00:00:0000 1 kernel
b) show processes <process name>
下記は 0/RSP0/CPU0 上の eth_server プロセスの状態確認の出力例となっています。
下記出力結果より、eth_server プロセスの Job ID は 60 であること、またプロセス内部の各スレッドの状態を確認することができます。
show processes <process name>
RP/0/RSP0/CPU0:ASR9904b#show processes eth_server
Job Id: 60
PID: 90153
Executable path: /asr9k-os-5.3.1/0x100305/bin/eth_server
--snip--
Process cpu time: 2645.406 user, 283.327 kernel, 2928.733 total
JID TID CPU Stack pri state TimeInState HR:MM:SS:MSEC NAME
60 1 3 164K 10 Receive 0:00:03:0830 0:10:32:0408 eth_server
60 2 7 164K 10 Sem 0:00:00:0000 0:02:31:0386 eth_server
60 3 4 164K 50 Sem 0:00:00:0311 0:00:54:0235 eth_server
60 4 3 164K 49 Sem 0:00:00:0000 0:01:39:0256 eth_server
60 5 2 164K 10 Receive 0:00:52:0858 0:00:00:0003 eth_server
60 6 7 164K 10 Receive 0:00:52:0847 0:00:00:0000 eth_server
60 7 7 164K 10 Receive 0:00:00:0944 0:00:00:0007 eth_server
60 8 4 164K 30 Condvar 0:00:08:0964 0:00:00:0007 eth_server
60 9 7 164K 20 Condvar 0:00:06:0756 0:00:00:0000 eth_server
60 10 6 164K 10 Condvar 0:00:00:0033 0:00:27:0805 eth_server
60 11 5 164K 10 Receive 101:18:08:0743 0:00:00:0000 eth_server
60 12 5 164K 10 Receive 0:01:03:0877 0:00:00:0001 eth_server
60 13 3 164K 10 Running 0:00:00:0000 0:11:03:0713 eth_server
60 14 5 164K 10 Receive 0:00:00:0001 0:10:54:0884 eth_server
60 15 5 164K 10 Receive 0:00:00:0345 0:10:46:0881 eth_server
-------------------------------------------------------------------------------
c) follow job <Job ID> iteration 1 stackonly
下記は 0/RSP0/CPU0 上の eth_server プロセスに対して follow コマンドを実施した出力例ととなっています。
follow コマンドではプロセス内部の処理のスナップショットを確認することができます。
follow job <Job ID> iteration 1 stackonly
RP/0/RSP0/CPU0:ASR9K#follow job 60 iteration 1 stackonly
Attaching to process pid = 90153 (pkg/bin/eth_server)
No tid specified, following all threads
Iteration 1 of 1
------------------------------
Current process = "pkg/bin/eth_server", PID = 90153 TID = 1 (main)
-- snip --
ENDOFSTACKTRACE
4. 被疑プロセスに関連した追加ログ
もちろん多くの場合は上記ログだけで原因を特定するのは難しく、被疑プロセスがどのようなプロセスかに応じて各種統計情報や内部トレースログを追加で取得し、CPU 使用率高騰の原因を詳細調査して行くことになります。
5. 参照
