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

UCS IOM メモリリーク問題解析手法

UCS B シリーズにて、以下の問題が報告されています。

CSCuf61116 UCS IOM bmcd memory leak can generate kernel core and crashes IOM

この問題は IOM 上で動作している内部プロセスのメモリリークによりIOM起動から暫く経過するとメモリ不足が原因でIOMがリブートする問題です。

このドキュメントでは IOM のメモリリーク問題の tech support の解析手法をご紹介致します。

まずIOMがリブートすると、UCSM の tech support の sam_techsupport ログに関連するサーバーの VIF がダウンする等、様々な Fault がレポートされます。

その中でも注目すべき Fault は以下の Fault Code:F0478 IOM inaccessible となります。

Severity: Cleared <-----
Code: F0478
Last Transition Time: 201X-XX-22T07:34:52.200 <-----
ID: 2781424
Status: None
Description: left IOM 3/1 (A) is inaccessible <-----
Affected Object: sys/chassis-3/slot-1
Name: Equipment Iocard Inaccessible
Cause: Equipment Inaccessible
Type: Equipment
Acknowledged: No
Occurrences: 2
Creation Time: 201X-XX-22T07:30:25.521 <-----
Original Severity: Critical
Previous Severity: Critical
Highest Severity: Critical

このログは IOM が UCSM からアクセス不可能になったことを意味しております。

また、既に Severity は Cleared となっておりますので、IOMが使用できない状態は既に解消されていることを意味しております。
Creation Time (Fault が作成された日時)と Last Transition Time (この例だと Fault が解消した日時)が 4 分ほどとなっております。
これは IOM が何らかの理由でリブートして、一時的に IOM が使用不可となった事を示唆しております。

次に 'show core detail' のセクションに IOM が使用不可になった直後の時刻にコアファイルが生成されている事がわかります。

`show cores detail`

Core Files:
    Name: <hostname>_BC03_IOM01_kernel_log.0.tar.gz
    Fabric ID: A
    Description: IOM core dump
    Size: 1495
    Timestamp: 201X-XX-22T07:35:20.000
    URI: corefile/<hostname>_BC03_IOM01_kernel_log.0.tar.gz
    Current Task:

何らかの原因で IOM がコアダンプしてコアが生成されたことがわかります。

<hostname>_BC03_IOM01_kernel_log.0.tar.gz のコアファイルを UCSM の GUI より取得します。

取得した <hostname>_BC03_IOM01_kernel_core.0 ファイルには以下のスタックトレースが記録されてます。

Kernel coredump stack trace:

pc     0xc0039ae4
exception_stack_bottom 0xc03ff000
exception_stack_top    0xc0401000
Call Trace:
len 2048 count 117 sp 0xc7e0dcf0
sp 0xc7e0dcf0 prev_sp 0xc7e0c030
sp 0xc7e0dcf0 stack_top 0xc7e0e000

 [<c0039ae4>]out_of_memory+0x18c/0x348 <-----
 [<c004337c>]try_to_free_pages+0x274/0x278
 [<c003ab9c>]__alloc_pages+0x2c0/0x3ac
 [<c003acb0>]__get_free_pages+0x28/0x68
 [<c006a4bc>]__pollwait+0x48/0xe4
 [<c0180d38>]tcp_poll+0x168/0x1cc
 [<c014fc4c>]sock_poll+0x2c/0x3c
 [<c006a7e8>]do_select+0x290/0x370
 [<c006ab18>]sys_select+0x250/0x4bc
 [<c0009830>]ppc_select+0x98/0xa8
 [<c0003f00>]ret_from_syscall+0x0/0x44

このスタックトレースは、select() のシステムコールで TCP パケットの発着を確認しようとしています。
しかしながらその際にメモリを確保しようとしたが、メモリが足りずに out_of_memory() を呼んで明示的にリブートしております。

 

今回の問題の真の原因は select() による TCP パケットではありません。

重要なのはスタックの先頭に out_of_memory() が呼ばれていることです。
これは IOM が何らかの理由でメモリ不足に陥っていたことを意味しております。
これらはいわば被害者のコードであり、既に何らかの原因でメモリが足りない状況になっており、たまたま上記のTCPパケットが最後のトリガーを引いたという事です。つまり、メモリ不足の状況に陥っている場合には、全てのメモリのアロケーションコードで IOM リブートのトリガーを引く可能性があります。

次に調査するログは Chassis の tech support を取得し、IOM のログを確認してみます。

まず最初に確認するログは techsupport_detailed_iocard1\cmc\log\ohms.log のログです。

Logfile: /var/cmc/log/ohms.log

cmc slot number 0
signature                      : 0xa5a50000
version                        : 1
uboot post status              : 0x00000000
cmc post status                : 0x00000000
cmc ohms status                : 0x00000400
chassis ok led status          : ON
chassis fault led status       : ON
cpu single ecc errors          : 0
sysinfo ok                     : 1
uptime                         :  1:01 <-----
total memory                   : 256548 kB
free memory                    : 105992 kB <-----
process count                  : 88
load average                   : 4.69, 3.13, 2.63

peer signature                 : 0xb5b50001
peer version                   : 1
peer uboot post status seeprom : 0x00000000
peer uboot post status         : 0x00000000
peer cmc post status seeprom   : 0x00000000
peer cmc post status           : 0x00000000
peer cmc ohms status           : 0x00001000
peer chassis ok led status     : ON
peer chassis fault led status  : ON
peer cpu single ecc errors     : 0
peer sysinfo ok                : 1
peer uptime                    : 520 days, 17:43 <-----
peer total memory              : 256548 kB
peer free memory               :   5360 kB <-----
peer process count             : 81
peer load average              : 1.67, 1.83, 1.86

Chassis OHMS status          cmc0       cmc1
master                     : 1          -
cmc ohms status            : 0x00000400 0x00001000
cpu error                  : 0          0
memory error               : 0          0
memory controller error    : 0          0
selected image error       : 0          0
alternate image error      : 0          0
i2c bus 0 error            : 0          0
i2c bus 1 error            : 0          0
i2c bus 1 master error     : 0          0
cpu mdio bus error         : 0          0
cpu interrupt error        : 0          0
cpu kernel crash           : 1          0 <-----
user process restart       : 0          0
cpu low memory             : 0          1 <-----
obfl error                 : 0          0
serial link error          : 0          0


まず uptime : 1:01 より IOM の起動時間が 1時間1分であることがわかります。
これは IOM 3/1 リブート直後に tech support を取得したためとなります。

IOM 3/1 の free memory は 105992 kB ほどあります。これはIOMがリブートすることにより十分な量のフリーメモリが確保できている事を意味しております。

注目すべきは IOM 3/1 の対向の IOM 3/2 のステータスとなります。
起動から 520日が経過しており、フリーメモリは 5Mb 程度しかありません。
大抵のケースで両方のIOMはほぼ同時に起動されます。
つまり今回のようなメモリリークのケースでは、両方のIOMが共にフリーメモリが少ない状態となっているケースが多くあります。
IOM 3/2 については近いうちに IOM 3/1 と同様にメモリ不足でリブートする可能性が高いです。
このためこの状態であれば、あらかじめメンテナンス時間を設けて IOM 3/2 の手動リセットを実施する必要があります。

IOM 3/1 については cpu kernel crash のフラグがたっています。
これは前回のリブートがクラッシュによるものであることを示唆しています。

IOM 3/2 については cpu low memory のフラグがたっています。
これは IOM 3/2 のメモリ不足を示唆しています。

IOM がメモリ不足でリブートした際の調査で難しいのは、既にIOMがリブートした後だと、有効な情報があまり残ってないことです。
重要なのはリブート直前でどのプロセスがメモリ肥大の原因になっているかを特定する必要があるのですが、IOM がリブートしてしまうと、被疑のプロセスのメモリ量は正常に戻りますので、原因の特定が難しくなります。
このため、IOMはある一定のフリーメモリの値になると自動でログを残してくれます。
具体的には以下の二つのファイルです。

- IOM のフリーメモリが16Mbを下回った際に作成されるログ
techsupport_detailed_iocard1\mem_low_crit.log

- IOM のフリーメモリが8Mbを下回った際に作成されるログ
techsupport_detailed_iocard1\mem_low_emerg.log

今回は mem_low_emerg.log を見てみます。

 05:38:30 up 414 days, 11:38, load average: 2.68, 2.59, 2.61
              total         used         free       shared      buffers
  Mem:       256548       248388         8160            0            0
 Swap:            0            0            0
Total:       256548       248388         8160
MemTotal:       256548 kB
MemFree:          8160 kB <-----
Buffers:             0 kB
Cached:          85800 kB
SwapCached:          0 kB
Active:         218060 kB
Inactive:         3884 kB
HighTotal:           0 kB
HighFree:            0 kB
LowTotal:       256548 kB
LowFree:          8160 kB
SwapTotal:           0 kB
SwapFree:            0 kB
Dirty:               0 kB
Writeback:           0 kB
Mapped:         150368 kB
Slab:            10556 kB
CommitLimit:    128272 kB
Committed_AS:   257116 kB
PageTables:        936 kB
VmallocTotal:   737280 kB
VmallocUsed:    113236 kB
VmallocChunk:   623956 kB

MemFree の値がフリーメモリの量となります。今回は 8Mb 程度となっております。

重要なのは以下の UNIX の ps コマンドに相当するログです。

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.0  0.2   3192   624 ?        S     2012   0:07 init
root         2  0.0  0.0      0     0 ?        S<    2012   1:44 [ksoftirqd/0]
root         3  0.0  0.0      0     0 ?        S<    2012   3:29 [desched/0]
root         4  0.0  0.0      0     0 ?        S<    2012  10:20 [events/0]
root         5  0.0  0.0      0     0 ?        S<    2012   0:00 [khelper]
root         6  0.0  0.0      0     0 ?        S<    2012  91:44 [kthread]
root        10  0.0  0.0      0     0 ?        S     2012   0:00 [kswapd0]
root        12  0.0  0.0      0     0 ?        S     2012   0:00 [mtdblockd]
root        31  0.0  0.0      0     0 ?        SN    2012   0:00 [jffs2_gcd_mtd8]
root       123  0.0  0.0      0     0 ?        SN    2012   0:07 [jffs2_gcd_mtd3]
root       180  0.0  0.2   3568   760 ?        Ss    2012   0:00 /usr/sbin/inetd
root       301  0.0  0.2   2220   716 ?        Ss    2012   3:47 /nuova/bin/obfllogger --write -F
root       309  0.0  0.9   8804  2504 ?        Sl    2012  12:49 /sbin/rsyslogd -c3 -i/var/run/rsyslogd.pid
root       321  0.0  0.2   3192   532 ?        Ss    2012   0:00 /usr/sbin/telnetd
root       401  0.1  0.2   2128   724 ?        Ss    2012 774:50 /nuova/bin/pmon -f /etc/pmon.conf
root       406  1.3  0.8  15484  2188 ?        Sl    2012 8231:51 platform_ohms -F
root       407  0.5  0.5  17092  1420 ?        Sl    2012 3073:18 dmserver -F
root       436  109  0.7  17664  2024 ?        Sl    2012 652411:57 ipmiserver -F
root       440  5.6  0.6   6752  1792 ?        Sl    2012 33870:31 cmc_manager -F
root       446  0.0  0.3   3660  1024 ?        S     2012 411:45 cluster_manager -F
root       448  0.0  0.3   2808   856 ?        S     2012 404:35 updated -F
root       455  0.0 36.8 114872 94496 ?        Sl    2012 506:33 bmcd -F  <----- !!!!!
root       456  0.4  1.8  16824  4752 ?        Sl    2012 2546:04 thermal -F
root       457  0.0  0.2   3196   748 ?        S     2012   0:00 /bin/sh /etc/init.d/ppp restart
root       458  0.0  0.4  14312  1196 ?        Sl    2012 346:29 pwrmgr -F
root       468  0.0  0.2   3192   712 ?        Ss    2012  22:38 /usr/sbin/crond
root       476  0.0  0.3   2560   936 ?        S     2012  11:26 /usr/sbin/pppd /dev/ttyS1 nodetach

bmcd というプロセスが 36.8% のメモリを消費していることがわかります。
つまり、bmcd が今回のメモリ不足の原因であることが特定できます。

本件は CSCuf61116 が原因となります。
bmcd プロセスはブレードのステータスを定期的に確認をするプロセスとなります。
このブレードのステータス確認時に、bmcd のコードにてメモリリークが発生し、IOM起動から 500日前後でリブートが発生する件となります。

なお、UCSM よりもブレードのファームウェアのバージョンが新しい場合には IOM がブレードを認識できず更にメモリリークが加速する事が報告されております。このため、CSCuf61116 の修正ファームウェアを適用するか、IOMのフリーメモリ量を監視し、フリーメモリの量が減ってきたら定期的にIOMのリブートを実施されることをお勧めします。

IOMのフリーメモリの監視は tech support を取得することで可能ですが、UCSM に ssh ログインし、以下のコマンドでも確認可能です。

UCS-1-A# connect iom 1
Attaching to FEX 1 ...
To exit type 'exit', to abort type '$.'
Bad terminal type: "xterm". Will assume vt100.
fex-1# show platform software cmcctrl process meminfo
MemTotal:       256548 kB
MemFree:        106000 kB <-----
Buffers:             0 kB
Cached:          84484 kB
SwapCached:          0 kB
Active:         115460 kB
Inactive:         3756 kB
HighTotal:           0 kB
HighFree:            0 kB
LowTotal:       256548 kB
LowFree:        106000 kB
SwapTotal:           0 kB
SwapFree:            0 kB
Dirty:               0 kB
Writeback:           0 kB
Mapped:          50400 kB
Slab:            15456 kB
CommitLimit:    128272 kB
Committed_AS:   166612 kB
PageTables:        952 kB
VmallocTotal:   737280 kB
VmallocUsed:    113168 kB
VmallocChunk:   624020 kB

 

上記の例では、100Mb以上のフリーメモリが確保されている状態となります。

 

以上

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