Bug 601507 - kernel panic on vmware using hugemem pages
kernel panic on vmware using hugemem pages
Status: CLOSED WONTFIX
Product: Red Hat Enterprise Linux 4
Classification: Red Hat
Component: kernel (Show other bugs)
4.8
All Linux
high Severity high
: rc
: ---
Assigned To: Red Hat Kernel Manager
Red Hat Kernel QE team
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2010-06-08 02:03 EDT by Lachlan McIlroy
Modified: 2015-04-12 19:14 EDT (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-06-14 15:05:50 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Lachlan McIlroy 2010-06-08 02:03:50 EDT
Description of problem:

Kernel panic - not syncing: Out of memory and no killable processes...

------------[ cut here ]------------
kernel BUG at kernel/panic.c:77!
invalid operand: 0000 [#1]
SMP 
Modules linked in: iptable_nat ip_conntrack iptable_mangle iptable_filter ip_tables netconsole netdump nfs lockd nfs_acl vmmemctl(U) sunrpc cpufreq_powersave dm_mirror dm_mod button battery ac pcnet32 vmxnet(U) mii floppy ata_piix libata ext3 jbd mptscsih mptsas mptspi mptfc mptscsi mptbase sd_mod scsi_mod
CPU:    1
EIP:    0060:[<c0122d0a>]    Not tainted VLI
EFLAGS: 00010286   (2.6.9-89.ELsmp) 
EIP is at panic+0x47/0x166
eax: 0000004b   ebx: 0c25961d   ecx: ea1ecc70   edx: c02ef568
esi: 000001d2   edi: 00000000   ebp: 00000000   esp: ea1ecc78
ds: 007b   es: 007b   ss: 0068
Process khelper (pid: 20642, threadinfo=ea1ec000 task=f4b9ebb0)
Stack: 0c25961d c0144c52 c02f1397 0c25961d 000001d2 000001d2 00000000 c0144d82 
       c02f13e9 000001d2 00000000 00000002 c0337e20 c014c9f2 0000f6a6 ea1ecd28 
       00000000 000001c0 00000000 00000000 00000003 000000e0 00000000 00000000 
Call Trace:
 [<c0144c52>] oom_kill+0x56/0xd7
 [<c0144d82>] out_of_memory+0x97/0xcd
 [<c014c9f2>] try_to_free_pages+0x1c6/0x1ef
 [<c0145a9f>] __alloc_pages+0x1c7/0x2b1
 [<c01481af>] do_page_cache_readahead+0xe7/0x158
 [<c0148386>] page_cache_readahead+0x166/0x258
 [<c0142435>] do_generic_mapping_read+0x138/0x445
 [<c014298c>] __generic_file_aio_read+0x181/0x1b2
 [<c0142742>] file_read_actor+0x0/0xc9
 [<c01429fd>] generic_file_aio_read+0x40/0x47
 [<c015d318>] do_sync_read+0x9e/0xca
 [<c0120ef9>] autoremove_wake_function+0x0/0x2d
 [<c015d3fa>] vfs_read+0xb6/0xe2
 [<c01666c0>] kernel_read+0x31/0x3b
 [<c0167217>] prepare_binprm+0xbd/0xc6
 [<c016768e>] do_execve+0x10a/0x1fd
 [<c01049d5>] sys_execve+0x2b/0x8a
 [<c02dd8e3>] syscall_call+0x7/0xb
 [<c013172c>] ____exec_usermodehelper+0xa9/0xc3
 [<c0131774>] ____call_usermodehelper+0x25/0x2f
 [<c013174f>] ____call_usermodehelper+0x0/0x2f
 [<c01041f5>] kernel_thread_helper+0x5/0xb
Code: 42 c0 e8 27 43 0a 00 68 a0 58 42 c0 68 68 f5 2e c0 e8 21 08 00 00 83 c4 0c 83 3d ac 8f 44 c0 00 75 09 83 3d a8 8f 44 c0 00 74 08 <0f> 0b 4d 00 8b f5 2e c0 31 c0 e8 fb 86 ff ff 83 3d b0 8f 44 c0 

Version-Release number of selected component (if applicable):
kernel-smp-2.6.9-89.EL

How reproducible:
Regularly - about once a week.

Steps to Reproduce:
Unknown
  
Additional info:

Core is available at:
core-i386.gsslab.rdu.redhat.com/cores/20100502222022/work
Comment 2 Lachlan McIlroy 2010-06-08 02:07:36 EDT
The images show there is a definite shortage of memory in the HighMem zone with only 384kB free.  There's also no bounce buffer pages available.  The system says it's out of memory with no killable processes.

Let's have a look at the vmcore:

     KERNEL: /cores/20100502222022/work/vmlinux
   DUMPFILE: /cores/20100502222022/work/vmcore
       CPUS: 2
       DATE: Sat May  1 11:05:12 2010
     UPTIME: 22 days, 09:48:45
LOAD AVERAGE: 11.75, 7.29, 6.01
      TASKS: 50
   NODENAME: <hostname>
    RELEASE: 2.6.9-89.ELsmp
    VERSION: #1 SMP Mon Apr 20 10:34:33 EDT 2009
    MACHINE: i686  (3000 Mhz)
     MEMORY: 3 GB
      PANIC: "kernel BUG at kernel/panic.c:77!"
        PID: 20821
    COMMAND: "khelper"
       TASK: f63a85b0  [THREAD_INFO: f72a0000]
        CPU: 0
      STATE: TASK_RUNNING (PANIC)

kernel BUG at kernel/panic.c:77!
invalid operand: 0000 [#1]
SMP
Modules linked in: netconsole netdump vmxnet(U) vmmemctl(U) iptable_nat ip_conntrack iptable_mangle ip_tables nfs lockd nfs_acl sunrpc cpufreq_powersave dm_mirror dm_mod button battery ac pcnet32 mii floppy ata_piix libata ext3 jbd mptscsih mptsas mptspi mptfc mptscsi mptbase sd_mod scsi_mod
CPU:    0
EIP:    0060:[<c0122d0a>]    Tainted: P      VLI
EFLAGS: 00010286   (2.6.9-89.ELsmp)
EIP is at panic+0x47/0x166
eax: 0000004b   ebx: 7361b99f   ecx: f72a0c70   edx: c02ef568
esi: 000001d2   edi: 00000000   ebp: 00000000   esp: f72a0c78
ds: 007b   es: 007b   ss: 0068
Process khelper (pid: 20821, threadinfo=f72a0000 task=f63a85b0)
Stack: 7361b99f c0144c52 c02f1397 7361b99f 000001d2 000001d2 00000000 c0144d82
      c02f13e9 000001d2 00000000 00000002 c0337e20 c014c9f2 00013401 f72a0d28
      00000000 000001a0 00000000 00000000 00000014 000000c0 00000000 00000000
Call Trace:
[<c0144c52>] oom_kill+0x56/0xd7
[<c0144d82>] out_of_memory+0x97/0xcd
[<c014c9f2>] try_to_free_pages+0x1c6/0x1ef
[<c0145a9f>] __alloc_pages+0x1c7/0x2b1
[<c01481af>] do_page_cache_readahead+0xe7/0x158
[<c0148386>] page_cache_readahead+0x166/0x258
[<c0142435>] do_generic_mapping_read+0x138/0x445
[<c014298c>] __generic_file_aio_read+0x181/0x1b2
[<c0142742>] file_read_actor+0x0/0xc9
[<c01429fd>] generic_file_aio_read+0x40/0x47
[<c015d318>] do_sync_read+0x9e/0xca
[<c0120ef9>] autoremove_wake_function+0x0/0x2d
[<c015d3fa>] vfs_read+0xb6/0xe2
[<c01666c0>] kernel_read+0x31/0x3b
[<c0167217>] prepare_binprm+0xbd/0xc6
[<c016768e>] do_execve+0x10a/0x1fd
[<c01049d5>] sys_execve+0x2b/0x8a
[<c02dd8e3>] syscall_call+0x7/0xb
[<c013172c>] ____exec_usermodehelper+0xa9/0xc3
[<c0131774>] ____call_usermodehelper+0x25/0x2f
[<c013174f>] ____call_usermodehelper+0x0/0x2f
[<c01041f5>] kernel_thread_helper+0x5/0xb
Code: 42 c0 e8 27 43 0a 00 68 a0 58 42 c0 68 68 f5 2e c0 e8 21 08 00 00 83 c4 0c 83 3d ac 8f 44 c0 00 75 09 83 3d a8 8f 44 c0 00 74 08 <0f> 0b 4d 00 8b f5 2e c0 31 c0 e8 fb 86 ff ff 83 3d b0 8f 44 c0

The above process is calling the execve() system call and is trying to read in the new executable.  It's triggered a page cache readahead which needs to allocate some memory.  Nothing unusual about that.

crash> ps
  PID    PPID  CPU   TASK    ST  %MEM     VSZ    RSS  COMM
     0      0   0  c032da80  RU   0.0       0      0  [swapper]
>     0      1   1  f7e410b0  RU   0.0       0      0  [swapper]
     1      0   0  f7e41630  IN   0.0    3220    104  init
     2      1   0  f7e40b30  IN   0.0       0      0  [migration/0]
     3      1   0  f7e405b0  RU   0.0       0      0  [ksoftirqd/0]
     4      1   1  f7e40030  IN   0.0       0      0  [migration/1]
     5      1   1  f7e856b0  IN   0.0       0      0  [ksoftirqd/1]
     6      1   0  f7e85130  IN   0.0       0      0  [events/0]
     7      1   1  f7e84bb0  IN   0.0       0      0  [events/1]
     8      1   0  f7e84630  UN   0.0       0      0  [khelper]
     9      1   0  f7e840b0  IN   0.0       0      0  [kthread]
    10      9   0  f7cd7730  IN   0.0       0      0  [kacpid]
    23      9   0  f7cd66b0  IN   0.0       0      0  [kblockd/0]
    24      9   1  f7cd6c30  IN   0.0       0      0  [kblockd/1]
    25      1   0  f7cd71b0  IN   0.0       0      0  [khubd]
    44      1   1  f7d2d230  IN   0.0       0      0  [kswapd0]
    45      9   0  f7d2ccb0  IN   0.0       0      0  [aio/0]
    46      9   1  f7d2c730  IN   0.0       0      0  [aio/1]
   192      1   0  f7d2c1b0  IN   0.0       0      0  [kseriod]
   438      1   1  f7db27b0  IN   0.0       0      0  [scsi_eh_0]
   468      1   0  f7db3830  IN   0.0       0      0  [kjournald]
  1089      9   0  f7276b30  IN   0.0       0      0  [kauditd]
  1396      1   0  f7030db0  UN   0.0       0      0  udevd
  2386      9   0  f720f930  IN   0.0       0      0  [ata/0]
  2387      9   1  f73af3b0  IN   0.0       0      0  [ata/1]
  2388      9   0  f720e330  IN   0.0       0      0  [ata_aux]
  2599      1   0  f72770b0  IN   0.0       0      0  [kjournald]
  2600      1   0  f73ae8b0  IN   0.0       0      0  [kjournald]
  2601      1   0  f7076e30  IN   0.0       0      0  [kjournald]
  2602      1   0  f7276030  IN   0.0       0      0  [kjournald]
  2603      1   1  f72c19b0  IN   0.0       0      0  [kjournald]
  2604      1   1  c2b012b0  IN   0.0       0      0  [kjournald]
  3144      1   0  c2b007b0  UN   0.0       0      0  syslogd
  3148      1   0  f7030830  IN   0.0    3440     52  klogd
  3162      1   1  f720ee30  UN   0.0    1576      4  irqbalance
  3357      1   1  f7031330  IN   0.0       0      0  [rpciod]
  3358      1   0  f72e50b0  IN   0.0       0      0  [lockd]
  3633      1   1  f72423b0  UN   0.0    5344      4  hald
  3687      1   1  f72c0930  UN   0.0    9540     52  scopeux
  4078      1   1  f70773b0  UN   0.0       0      0  mingetty
  4079      1   1  f7161230  UN   0.0       0      0  mingetty
  4080      1   0  f63808b0  UN   0.0       0      0  mingetty
  4081      1   1  f63923b0  UN   0.0       0      0  mingetty
 10256      9   1  f3aa9730  UN   0.0       0      0  [pdflush]
 18083      9   1  e2167730  UN   0.0       0      0  [pdflush]
 19441      1   1  f5a20830  UN   0.0       0      0  [vmmemctl]
 19634      1   1  d79413b0  UN   0.0    2172      8  vmware-guestd
> 20821      8   0  f63a85b0  RU   0.0       0      0  [khelper]
 20822      1   0  f62de7b0  UN   0.0    3220    116  init
 20823      1   1  f63a90b0  UN   0.0    3220    116  init

Well there's not a lot of processes left running and none of them appear to be using a lot of memory so this might be a memory leak in the kernel.

crash> kmem -i
             PAGES        TOTAL      PERCENTAGE
TOTAL MEM   778795         3 GB         ----
     FREE    62970       246 MB    8% of TOTAL MEM
     USED   715825       2.7 GB   91% of TOTAL MEM
   SHARED    75085     293.3 MB    9% of TOTAL MEM
  BUFFERS    75032     293.1 MB    9% of TOTAL MEM
   CACHED     3813      14.9 MB    0% of TOTAL MEM
     SLAB     7746      30.3 MB    0% of TOTAL MEM

TOTAL HIGH   557040       2.1 GB   71% of TOTAL MEM
FREE HIGH      112       448 KB    0% of TOTAL HIGH
TOTAL LOW   221755     866.2 MB   28% of TOTAL MEM
 FREE LOW    62858     245.5 MB   28% of TOTAL LOW

TOTAL SWAP  1048231         4 GB         ----
SWAP USED     1358       5.3 MB    0% of TOTAL SWAP
SWAP FREE  1046873         4 GB   99% of TOTAL SWAP

Not a lot being used by the fscache or slab cache yet in the HighMem zone we only have 448KB left out of 2.1GB.

crash> kmem -z
NODE: 0  ZONE: 0  ADDR: c0334200  NAME: "DMA"
 SIZE: 4096  MIN/LOW/HIGH: 16/32/48
 NR_ACTIVE: 0  NR_INACTIVE: 0  FREE: 3088
 ALL_UNRECLAIMABLE: yes  PAGES_SCANNED: 0  

NODE: 0  ZONE: 1  ADDR: c0335600  NAME: "Normal"
 SIZE: 225280  MIN/LOW/HIGH: 932/1864/2796
 NR_ACTIVE: 73127  NR_INACTIVE: 5321  FREE: 59770
 ALL_UNRECLAIMABLE: no  PAGES_SCANNED: 0  

NODE: 0  ZONE: 2  ADDR: c0336a00  NAME: "HighMem"
 SIZE: 557056  MIN/LOW/HIGH: 128/256/384
 NR_ACTIVE: 191  NR_INACTIVE: 210  FREE: 112
 ALL_UNRECLAIMABLE: no  PAGES_SCANNED: 467181  

Seems to be related to enabling the hugepages setting.

$ cat proc/meminfo
MemTotal:      3895444 kB
MemFree:        287776 kB
Buffers:        322088 kB
Cached:         933676 kB
SwapCached:     862716 kB
Active:        1536808 kB
Inactive:       633056 kB
HighTotal:     3014592 kB
HighFree:        15488 kB
LowTotal:       880852 kB
LowFree:        272288 kB
SwapTotal:     2096472 kB
SwapFree:      1139008 kB
Dirty:            1456 kB
Writeback:           8 kB
Mapped:         886908 kB
Slab:            86644 kB
CommitLimit:   3378592 kB
Committed_AS:  2080716 kB
PageTables:       5112 kB
VmallocTotal:   106488 kB
VmallocUsed:      4392 kB
VmallocChunk:   101968 kB
HugePages_Total:   650
HugePages_Free:    250
Hugepagesize:     2048 kB

Huge page size is 2MB and there are 650 huge pages so that's a total of 1.3GB.  If all those huge pages are in HighMem then there should still be 800MB left.
Comment 4 Lachlan McIlroy 2010-06-08 02:40:03 EDT
Pulling some details off the stack:

crash> file f7e5ea80
struct file {
  f_list = {
    next = 0xf4e86080, 
    prev = 0xf7f2bc98
  }, 
  f_dentry = 0xedace804, 
  f_vfsmnt = 0xf7f17e00, 
  f_op = 0xf8939ba0, 
  f_count = {
    counter = 1
  }, 
  f_flags = 0, 
  f_mode = 13, 
  f_error = 0, 
  f_pos = 0, 
  f_owner = {
    lock = {
      lock = 16777216, 
      magic = 3736018669
    }, 
    pid = 0, 
    uid = 0, 
    euid = 0, 
    security = 0x0, 
    signum = 0
  }, 
  f_uid = 0, 
  f_gid = 0, 
  f_ra = {
    start = 0, 
    size = 0, 
    next_size = 0, 
    prev_page = 0, 
    ahead_start = 0, 
    ahead_size = 0, 
    currnt_wnd_hit = 0, 
    average = 16, 
    ra_pages = 32, 
    mmap_hit = 0, 
    mmap_miss = 0
  }, 
  f_version = 0, 
  f_security = 0x0, 
  private_data = 0x0, 
  f_ep_links = {
    next = 0xf7e5eb08, 
    prev = 0xf7e5eb08
  }, 
  f_ep_lock = {
    lock = 1, 
    magic = 3735899821
  }, 
  f_mapping = 0xf602dc70
}

crash> files -d 0xedace804
 DENTRY    INODE    SUPERBLK  TYPE  PATH
edace804  f602dbc0  f7f2bc00  REG   /sbin/hotplug

So we have khelper running hotplug.

crash> px *(struct address_space *)0xf602dc70
$2 = {
  host = 0xf602dbc0, 
  page_tree = {
    height = 0x0, 
    gfp_mask = 0x220, 
    rnode = 0x0
  }, 
  tree_lock = {
    lock = 0x1, 
    magic = 0xdead4ead
  }, 
  i_mmap_writable = 0x0, 
  i_mmap = {
    prio_tree_node = 0x0, 
    index_bits = 0x1
  }, 
  i_mmap_nonlinear = {
    next = 0xf602dc94, 
    prev = 0xf602dc94
  }, 
  i_mmap_lock = {
    lock = 0x1, 
    magic = 0xdead4ead
  }, 
  truncate_count = {
    counter = 0x0
  }, 
  nrpages = 0x0, 
  writeback_index = 0x0, 
  a_ops = 0xf8939c80, 
  flags = 0xd2, 
  backing_dev_info = 0xc2a05ce0, 
  private_lock = {
    lock = 0x1, 
    magic = 0xdead4ead
  }, 
  private_list = {
    next = 0xf602dcc4, 
    prev = 0xf602dcc4
  }, 
  assoc_mapping = 0x0
}

mapping flags for the allocation are __GFP_HIGHMEM, __GFP_FS, __GFP_IO and __GFP_WAIT.

The system does not appear to be running much now but it looks like it was running a few more things before the oom-killer went to work:

crash> log | grep "page allocation"
opcmsga: page allocation failure. order:0, mode:0xd2
opcmsga: page allocation failure. order:0, mode:0xd2
coda: page allocation failure. order:0, mode:0xd2
opcacta: page allocation failure. order:0, mode:0xd2
opcmsgi: page allocation failure. order:0, mode:0xd2
opcle: page allocation failure. order:0, mode:0xd2
perfalarm: page allocation failure. order:0, mode:0xd2
sendmail: page allocation failure. order:0, mode:0xd2
rpc.idmapd: page allocation failure. order:0, mode:0xd2
klogd: page allocation failure. order:0, mode:0xd2
init: page allocation failure. order:0, mode:0x1d2
hotplug: page allocation failure. order:0, mode:0x4d2
hotplug: page allocation failure. order:0, mode:0xd2
hotplug: page allocation failure. order:0, mode:0xd2
hotplug: page allocation failure. order:0, mode:0x1d2
syslogd: page allocation failure. order:0, mode:0xd2
hald: page allocation failure. order:0, mode:0x1d2
irqbalance: page allocation failure. order:0, mode:0xd2
scopeux: page allocation failure. order:0, mode:0xd2
vmware-guestd: page allocation failure. order:0, mode:0x1d2
Comment 5 Lachlan McIlroy 2010-06-10 22:19:20 EDT
The second core is at core-i386:/cores/20100511185045.

      KERNEL: vmlinux                           
    DUMPFILE: vmcore
        CPUS: 2
        DATE: Mon May 10 20:21:38 2010
      UPTIME: 2 days, 08:42:08
LOAD AVERAGE: 3.70, 0.94, 0.31
       TASKS: 47
    NODENAME: vcmdevappl001.optus.com.au
     RELEASE: 2.6.9-89.ELsmp
     VERSION: #1 SMP Mon Apr 20 10:34:33 EDT 2009
     MACHINE: i686  (3002 Mhz)
      MEMORY: 3 GB
       PANIC: "kernel BUG at kernel/panic.c:77!"
         PID: 20642
     COMMAND: "khelper"
        TASK: f4b9ebb0  [THREAD_INFO: ea1ec000]
         CPU: 1
       STATE: TASK_RUNNING (PANIC)

crash> bt
PID: 20642  TASK: f4b9ebb0  CPU: 1   COMMAND: "khelper"
 #0 [ea1ecb34] netpoll_start_netdump at f8962570
 #1 [ea1ecb54] die at c0106049
 #2 [ea1ecb88] do_invalid_op at c0106424
 #3 [ea1ecc38] error_code (via invalid_op) at c02de3d9
    EAX: 0000004b  EBX: 0c25961d  ECX: ea1ecc70  EDX: c02ef568  EBP: 00000000 
    DS:  007b      ESI: 000001d2  ES:  007b      EDI: 00000000
    CS:  0060      EIP: c0122d0a  ERR: ffffffff  EFLAGS: 00010286 
 #4 [ea1ecc74] panic at c0122d0a
 #5 [ea1ecc7c] oom_kill at c0144c4d
 #6 [ea1ecc94] out_of_memory at c0144d7d
 #7 [ea1eccac] try_to_free_pages at c014c9ed
 #8 [ea1ecd08] __alloc_pages at c0145a9a
 #9 [ea1ecd3c] do_page_cache_readahead at c01481aa
#10 [ea1ecd6c] page_cache_readahead at c0148381
#11 [ea1ecd94] do_generic_mapping_read at c0142430
#12 [ea1ece10] __generic_file_aio_read at c0142987
#13 [ea1ece58] generic_file_aio_read at c01429f8
#14 [ea1ece74] do_sync_read at c015d315
#15 [ea1ecf10] vfs_read at c015d3f7
#16 [ea1ecf2c] kernel_read at c01666bb
#17 [ea1ecf48] prepare_binprm at c0167212
#18 [ea1ecf5c] do_execve at c0167689
#19 [ea1ecf80] sys_execve at c01049d0
#20 [ea1ecf94] system_call at c02dd8dc
    EAX: 0000000b  EBX: c0333300  ECX: f60e1d60  EDX: c2a60580  EBP: c2a60580 
    DS:  007b      ESI: 00000000  ES:  007b      EDI: 00000000
    CS:  0060      EIP: c013172c  ERR: 0000000b  EFLAGS: 00000282 

crash> file f7e5ea80
struct file {
  f_list = {
    next = 0xf4e86080, 
    prev = 0xf7f2bc98
  }, 
  f_dentry = 0xedace804, 
  f_vfsmnt = 0xf7f17e00, 
  f_op = 0xf8939ba0, 
  f_count = {
    counter = 1
  }, 
...

crash> files -d 0xedace804
 DENTRY    INODE    SUPERBLK  TYPE  PATH
edace804  f602dbc0  f7f2bc00  REG   /sbin/hotplug

It's running hotplug too.
Comment 6 Lachlan McIlroy 2010-06-11 02:24:16 EDT
None of the hugepages were actually in use when the system panicked.  This is to be expected though given that no job was running.

crash> p nr_huge_pages
nr_huge_pages = $1 = 650
crash> p free_huge_pages
free_huge_pages = $2 = 650

Note You need to log in before you can comment on or make changes to this bug.