2014-10-24 06:53 PM
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以上のフリーメモリが確保されている状態となります。
以上
検索バーにキーワード、フレーズ、または質問を入力し、お探しのものを見つけましょう
シスコ コミュニティをいち早く使いこなしていただけるよう役立つリンクをまとめました。みなさんのジャーニーがより良いものとなるようお手伝いします
下記より関連するコンテンツにアクセスできます