UCS IOM Memory Leak Problem Analytical Technique

[CscTsWebDocs]

The following problem is reported in the UCS B series:

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

This problem causes IOM to reboot due to out of memory after some time has passed from rebooting IOM which is caused by memory leak from the internal process operating on IOM.

This document introduces analytical techniques of tech support for IOM memory leak problem.

When IOM is rebooted, various Faults are reported, such as VIFs of the server related to the sam_techsupport log of UCSM tech support being down.

A notable Fault among them is Fault Code:F0478 IOM inaccessible, explained below:

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

This log means that it is impossible to access IOM from UCSM.

As Severity is already Cleared, the state where IOM cannot be used is already solved.
The time between Creation Time (the date when the Fault is created) and Last Transition Time (in this example, the date when the Fault is solved) is about four minutes.
This indicates that IOM was temporarily disabled, as IOM was rebooted for some reason.

Next, it shows that the core file is generated in the 'show core detail' section immediately after IOM was disabled.

`show core 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:

It shows that the core was generated since IOM was core-dumped for some reason.

Obtain a core file of <hostname>_BC03_IOM01_kernel_log.0.tar.gz from UCSM GUI.

The following stack trace is recorded in the obtained <hostname>_BC03_IOM01_kernel_core.0 file.

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

This stack trace tries to check arrival and departure of TCP packet by select() system call.

During that time, however, although it tried to allocate memory, it is explicitly rebooted by calling out_of_memory() due to out of memory.

The real root cause of the core-dump is not TCP packet received by select().
What is important here is out_of_memory() is called at the start of the stack.
This means that IOM was out of memory for some reason.
This is, so to speak, the code of a victim, and a trigger of IOM dow may be pulled by every memory allocation code.

For the next log to investigate, obtain Chassis tech support to check the IOM log.

The first log to check is 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

By looking at uptime : 01:01, it is important that It shows that the boot time of IOM is one hour and one minute.
This is because of obtaining tech support immediately after rebooting IOM 3/1.

Free memory of IOM 3/1 is approximately 105992 kB. This means that sufficient free memory is secured by rebooting IOM.

What should be noticed is the status of IOM 3/2 which is a peer of IOM 3/1.
Only 5Mb of free memory is available, since 520 days passed from rebooting.
In most cases, both IOM are booted almost simultaneously.
In short, there are many cases where free memory of both IOMs is low in this type of memory leak.
IOM 3/2 will likely to be rebooted soon due to out of memory like IOM 3/1.
As a result, with this state, IOM 3/2 needs to be manually reset by having a maintenance time in advance.

For IOM 3/1, a flag of cpu kernel crash is on.
This indicates that the previous reboot is caused by the crash.

For IOM 3/2, a flag of cpu low memory is on.
This indicates that IOM 3/2 is out of memory.

Difficult aspect of investigation for rebooting due to out of memory of IOM is that not much valid information is left after IOM is already rebooted.
It is important to specify which process caused taking up large memory immediately before rebooting. Once IOM is rebooted, however, the amount of memory of suspected process returns to normal, making it difficult to specify the cause.
For this purpose, IOM automatically records a log when the free memory becomes a certain amount.
Specifically, the following two files are recorded:

- a log created when IOM's free memory becomes below 16Mb
techsupport_detailed_iocard1\mem_low_crit.log

- a log created when IOM's free memory becomes below 8Mb
techsupport_detailed_iocard1\mem_low_emerg.log

Take a look at mem_low_emerg.log at this time.

 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

A value of MemFree is the amount of free memory.This time, it is about 8Mb.

The following log, which is equivalent to ps command for UNIX, is important.

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

Notice that a process called bmcd takes up 36.8% of memory.
In other words, bmcd is identified as the cause of out of memory this time.

In this case, CSCuf61116 is the cause.
The bmcd process is a process to check the status of the blade regularly.
In this case, when checking the status of the blade, memory leak occurred in the bmcd code, causing reboot around 500 days since IOM was booted.

Note that it is reported that memory leak is further accelerated, as IOM cannot recognize the blade when a version of firmware of the blade is newer than UCSM.Given this situation, we recommend applying the correction firmware of CSCuf61116, or monitoring the amount of IOM's free memory and rebooting IOM regularly if the free memory becomes low.

IOM's free memory can be monitored by obtaining tech support, or logging in to UCSM with ssh and checking it by using the following command:

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

In the above example, 100Mb or greater of free memory is secured.

Related Information

Original Document: https://supportforums.cisco.com/ja/document/12335256
Author: Satoshi Kinoshita
Posted on Oct 24, 2014