シスコサポートコミュニティ
キャンセル
次の結果を表示 
次の代わりに検索 
もしかして: 

IOS-XR: CPU 使用率高騰時のトラブルシューティング

 

 

概要

本ドキュメントでは、IOS-XR ルータにて CPU 使用率高騰時のトラブルシューティング方法について解説しています。

IOS-XR ルータは Route processor (RP) や Line card (LC) 等のノード上にそれぞれ CPU が搭載されており、各 CPU 上では複数のプロセスが、各 プロセス内部では複数のスレッドがお互いに独立して動作するマルチプロセス・マルチスレッドな分散ソフトウェアアーキテクチャとなっております。

そのため CPU 使用率が高騰した場合等のプロセスに関するトラブルシューティングを実施する際は、以下の手順にて被疑箇所を特定することがまず重要になります。

  1.  どのノードの CPU 使用率が高騰しているか?
  2.  どのプロセスの CPU 使用率が高騰しているか?
  3.  被疑プロセスはどのような処理を行っているか?

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--

上記出力例より、下記の状態を確認することができます。

  1. LC 0/0/CPU0 の CPU 使用率は 4.2 % (95.8% が Idle 状態: 特別な処理を行っていない状態)
  2. CPU 使用率 4.2 % のうちユーザプロセスによる CPU 使用率が 3.8%
  3. 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. 過去 1 分の平均 CPU 使用率は 6 %
  2. 過去 5 分の平均 CPU 使用率は 2 %
  3. 過去 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 使用率が高騰しているかを確認します。

下記ログを定期的に取得してモニタリングすることにより、被疑プロセスがどのような処理を行っているかをある程度把握することができます。

  1. show processes blocked コマンド
  2. show processes <process name> コマンド
  3. 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. 参照

 

277
閲覧回数
0
いいね!
0
コメント