Kernel Crash Dump Analysis Guide#

 

소개#

 

커널 크래쉬(패닉) 혹은 Hangup 상태에서의 매직키 ( sysrq + m, t ) 등을 통한 코어덤프 생성후,

그 덤프파일을 분석하는 과정을 설명하는 문서이다.

 

Document Ver. - 2.1

Version History : 2009/5/5 - 1.0, 2009/12/16 - 2.0,2010/03/04 - 2.1

Written by Mirr at LDS ( Linuxdata system.co.ltd )

Test Enviroment - RedHat Enterprise Linux 계열

 

Tools#

필요한 툴 : crash ( crash 패키지 ), kernel-debug 패키지, kernel-devel 혹은 kernel-source 패키지. (코드분석을 위함)

햄버거 + 콜라 혹은 감자칩 + Beer.

 

 

Crash 소개#

커널 디버깅을 쉽게 할 수 있도록 제작된 레드햇에서 제공하는 툴.

기본명령어#

sys - 시스템의 일반적인 정보를 출력해 준다.

bt - Backtrace 명령. 스택의 내용들을 순차적으로 출력해준다.

ps - Process list 출력.

free - Memory 및 스왑 상태 출력.

mount - 마운트 상태 출력

irq - 각 장치의 ( irq ) 상태를 출력.

kmem - 메모리 상태 출력 ( kmalloc, valloc 등 메모리 할당 상태도 보여줌 )

log - dmesg 의 내용을 출력.

mod - 로딩된 모듈 리스트 출력.

net - Network 상태 출력.

runq - 실행중인 task 리스트 출력.

task - 작업목록 출력.

rd - 메모리 번지수에 대한 상세정보 출력.

foreach - 모든 task, process 등 디버깅 정보에 대한 상세한 출력이 가능함.

set - 설정된 주소 및 PID 등을 기본 컨텍스트로 설정.

struct - 구조화된 메모리 내부의 변수들을 출력해 준다.

files - task 가 열고있는 파일디스크립터들을 출력해준다.

 

사용방법#
  1. Usage: crash {namelist} {dumpfile}

    [root@Test DUMP]# crash vmlinux vmcore

 

Crash 로 코어덤프를 분석하기 위해선 Debug 모드가 활성화 된 상태의 커널이 필요하다. ( kernel-debug )

실제론 동일 버젼의 커널 디버그패키지의 vmlinuz 를 합축해제한 vmlinux 파일을 필요로 한다.

 

debug 커널의 vmlinux 추출 방법은 다음과 같다.

 

  1. [root@Test DUMP]# rpm2cpio kernel-debug-{version}.rpm | cpio -idh

  2. [root@Test DUMP]# cd boot && od -A d -t x1 vmlinuz | grep '1f 8b 08 00'

  3. 0019296 40 db 20 00 18 00 00 00 42 e1 0f 00 1f 8b 08 00
    [root@Test boot]# dd if=vmlinuz bs=1 skip=19308 | zcat > vmlinux

 

간단히 설명하자면 rpm2cpio 로 rpm 의 내용을 추출 후,

vmlinuz 파일을 dd 명령으로 압축 해제 하는 것이다.

od 명령은 octaldump 로 file 을 특정 진법으로 덤프시켜주는 툴인데,

이것을 통해 압축코드 (1f 8b 08 00) 가 시작되는 주소를 찾아내어

압축되지 않은 vmlinux 를 추출하기 위한 작업이며, dd 명령을 통해 압축코드시작주소 ((0019296 + 12 ) 부터

덤프를 뜬뒤, zcat 으로 추출하는 과정이다. ( 역시 풀어설명하는게 더 복잡하다 그냥 명령어 코드 보자 )

 

실행화면#
  1.  

    [root@Test boot]$ crash vmlinux vmcore

    crash 4.0-7
    Copyright (C) 2002, 2003, 2004, 2005, 2006, 2007, 2008  Red Hat, Inc.
    Copyright (C) 2004, 2005, 2006  IBM Corporation
    Copyright (C) 1999-2006  Hewlett-Packard Co
    Copyright (C) 2005, 2006  Fujitsu Limited
    Copyright (C) 2006, 2007  VA Linux Systems Japan K.K.
    Copyright (C) 2005  NEC Corporation
    Copyright (C) 1999, 2002, 2007  Silicon Graphics, Inc.
    Copyright (C) 1999, 2000, 2001, 2002  Mission Critical Linux, Inc.
    This program is free software, covered by the GNU General Public License,
    and you are welcome to change it and/or distribute copies of it under
    certain conditions.  Enter "help copying" to see the conditions.
    This program has absolutely no warranty.  Enter "help warranty" for details.
     
    GNU gdb 6.1
    Copyright 2004 Free Software Foundation, Inc.
    GDB is free software, covered by the GNU General Public License, and you are
    welcome to change it and/or distribute copies of it under certain conditions.
    Type "show copying" to see the conditions.
    There is absolutely no warranty for GDB.  Type "show warranty" for details.
    This GDB was configured as "i686-pc-linux-gnu"...

    WARNING: kernels compiled by different gcc versions:
      vmlinux: 3.4.6
      vmcore kernel: 3.4.4

    KERNEL: vmlinux

  2. DUMPFILE: vmcore
    CPUS: 4
    DATE: Sun Apr 19 00:01:01 2009
    UPTIME: 171 days, 10:40:23
    LOAD AVERAGE: 0.07, 0.15, 0.11
    TASKS: 252
    NODENAME: node1
    RELEASE: 2.6.9-22.ELsmp
    VERSION: #1 SMP Mon Sep 19 18:32:14 EDT 2005
    MACHINE: i686  (3392 Mhz)
    MEMORY: 12.5 GB
    PANIC: "kernel BUG at include/asm/spinlock.h:146!"
    PID: 12339
    COMMAND: "run-parts"
    TASK: f3f02c30  [THREAD_INFO: cd001000]
    CPU: 0
    STATE: TASK_RUNNING (PANIC)

    crash>

 

Coredump Analysis 1#

실제 코어분석중 주로 사용하게 되는 명령어들과 그것들에 대한 실제 사용법을 Case 별로 보여준다.

상황#

커널 패닉 혹은 Hangup 이 잦은 서버로써, 대부분의 스펙은 동일한 서버이나,

지역적으로 서로 떨어져 있으며, 산발적으로 일어나는 현상이라며 고객이 징징대고 있는 상황이다..... ㅜ.,ㅜ

OS : RedHat Enterprise Linux 4 Update 2 ( Kernel Ver. 2.6.9-22.ELsmp )

 

분석과정#
  1. KERNEL: vmlinux

  2. DUMPFILE: vmcore
    CPUS: 4
    DATE: Sun Apr 19 00:01:01 2009
    UPTIME: 171 days, 10:40:23
    LOAD AVERAGE: 0.07, 0.15, 0.11
    TASKS: 252
    NODENAME: node1
    RELEASE: 2.6.9-22.ELsmp
    VERSION: #1 SMP Mon Sep 19 18:32:14 EDT 2005
    MACHINE: i686  (3392 Mhz)
    MEMORY: 12.5 GB
    PANIC: "kernel BUG at include/asm/spinlock.h:146!"
    PID: 12339
    COMMAND: "run-parts"
    TASK: f3f02c30  [THREAD_INFO: cd001000]
    CPU: 0
    STATE: TASK_RUNNING (PANIC)

    crash> bt -t

  3. PID: 12339  TASK: f3f02c30  CPU: 0   COMMAND: "run-parts"
    bt: cannot resolve stack trace:
     #0 [cd001ddc] netpoll_start_netdump at f8d97570
     #1 [cd001dfc] die at c0106015
     #2 [cd001e30] do_invalid_op at c01063f0
     #3 [cd001ee0] irq_entries_start at c02d1ba9
     #4 [cd001fa8] do_group_exit at c0124482
    bt: text symbols on stack:
        [cd001df4] try_crashdump at c013403d
        [cd001dfc] die at c010601a
  4.  
  5. .................. 중략

  6.     [cd001fa8] do_group_exit at c0124487
        [cd001fc0] iret_exc at c02d10cf
    bt: possible exception frames:
      KERNEL-MODE EXCEPTION FRAME AT cd001eec:
        EAX: c011e5a3  EBX: 00000206  ECX: c02e36fd  EDX: c02e36fd  EBP: cd001f40
        DS:  007b      ESI: f7143e00  ES:  007b      EDI: 00000001
        CS:  0060      EIP: c02cfd09  ERR: ffffffff  EFLAGS: 00010016
      USER-MODE EXCEPTION FRAME AT cd001fc4:
        EAX: 000000fc  EBX: 00000000  ECX: 00000000  EDX: 00000000
        DS:  007b      ESI: 00000000  ES:  007b      EDI: 007a765c
        SS:  007b      ESP: bff8b358  EBP: bff8b378
        CS:  0073      EIP: 0066b7a2  ERR: 000000fc  EFLAGS: 00000246
  7.  
  8. crash> kmem -S inode_cache
    CACHE    NAME                 OBJSIZE  ALLOCATED     TOTAL  SLABS  SSIZE
    f7f47e80 inode_cache              344        697      1056     96     4k
    SLAB      MEMORY    TOTAL  ALLOCATED  FREE
    f7afe080  f7afe0b0     11          3     8
    FREE / [ALLOCATED]
       f7afe0b0  (cpu 2 cache)
       f7afe208  (cpu 2 cache)
       f7afe360  (cpu 2 cache)
       f7afe4b8  (cpu 2 cache)
       f7afe610  (cpu 2 cache)
      [f7afe768]
       f7afe8c0  (cpu 2 cache)
       f7afea18
       f7afeb70  (cpu 2 cache)
      [f7afecc8]
      [f7afee20]
    SLAB      MEMORY    TOTAL  ALLOCATED  FREE
    f6cc2080  f6cc20b0     11          6     5
    FREE / [ALLOCATED]
      [f6cc20b0]
       f6cc2208
    .......... 중략
  9. SLAB      MEMORY    TOTAL  ALLOCATED  FREE
    f7f4f000  f7f4f030     11         11     0
    FREE / [ALLOCATED]
      [f7f4f030]
      [f7f4f188]
      [f7f4f2e0]
      [f7f4f438]
      [f7f4f590]
      [f7f4f6e8]
  10. crash> inode.i_mem f7f4f030
  11.   i_sem = {
        count = {
          counter = 1
        },
        sleepers = 0,
        wait = {
          lock = {
            lock = 1,
            magic = 0xdead4ead
          },
          task_list = {
            next = 0xf7f4f0b0,
            prev = 0xf7f4f0b0
          }
        }
      },

    crash> foreach bt
    PID: 0      TASK: c031ea80  CPU: 0   COMMAND: "swapper"
     #0 [c038ff88] schedule at c02cf361
     #1 [c038ffe8] cpu_idle at c01040ab

    PID: 0      TASK: f7f210b0  CPU: 1   COMMAND: "swapper"
     #0 [c7666f7c] smp_call_function_interrupt at c0116c4a
     #1 [c7666f84] irq_entries_start at c02d1ae9
     #2 [c7666fc0] cpu_idle at c010409b

    PID: 0      TASK: f7f20b30  CPU: 2   COMMAND: "swapper"
     #0 [c7668f7c] smp_call_function_interrupt at c0116c4a
     #1 [c7668f84] irq_entries_start at c02d1ae9
     #2 [c7668fc0] cpu_idle at c010409b

    PID: 0      TASK: f7f205b0  CPU: 3   COMMAND: "swapper"
     #0 [c7669f7c] smp_call_function_interrupt at c0116c4a
     #1 [c7669f84] irq_entries_start at c02d1ae9
     #2 [c7669fc0] cpu_idle at c010409b

    PID: 1      TASK: f7f21630  CPU: 3   COMMAND: "init"
    bt: cannot resolve stack trace:
     #0 [c7663e68] schedule at c02cf361
     #1 [c7663e84] buffered_rmqueue at c014304b
  12. ........... 중략
    crash>

 

위의 과정들을 거친 끝에 우리는 irq_balance 등이 이루어져 cpu 자원의 (멀티코어 및 멀티CPUs) 할당이 이루어지는 도중

spinlock 의 문제로 커널패닉이 떨어졌음을 확인 할 수 있다.

위 문제에 대한 해답은 뚜렷하게 얻지 못했지만, SMP 커널의 spinlock 문제라는 것을 알았으므로,

kernel.org 혹은 redhat 에서 버그를 찾아 볼 힌트가 생겼으며, 커널의 업데이트를 고객에게 권고할 수 있게 되었다.

kernel.org 등에서 리포팅되어있는 버그로 보여지며, 완전한 해결책은 나와있지 않았으나,

RHEL 이므로 RedHat 의 패치가 이루어 졌을 수도 있으니, 정식 update 를 권장하였다.

 

Coredump Analysis 2#

상황#

Mailserver 가 자꾸 뻗습니다... 라는 고객의 다소 황망스러운 요청....

결국 히스토리나 기타 정보들이 없다보니 덤프분석뿐이라는 결론으로 덤프 분석에 들어간다.

OS : RHEL 3 Update 8 ( Kernel Ver. 2.4.21-47.ELhugemem

분석과정#
  1. KERNEL: vmlinux­2.4.21­47.ELhugemem
    DEBUGINFO: ./vmlinux­2.4.21­47.ELhugemem.debug
    DUMPFILE: vmcore
    CPUS: 8
    DATE: Wed Apr 16 06:52:58 2008
    UPTIME: 14:34:12
    LOAD AVERAGE: 0.48, 0.21, 0.13
    TASKS: 206
    NODENAME: ***min02.*****.co.kr
    RELEASE: 2.4.21­47.ELhugemem
    VERSION: #1 SMP Wed Jul 5 20:30:35 EDT 2006
    MACHINE: i686  (3669 Mhz)
    MEMORY: 16.8 GB
    PANIC: ""
    PID: 20093
    COMMAND: "save"
    TASK: bd0c0000
    CPU: 1
    STATE: TASK_RUNNING (PANIC)

  2. crash> bt

  3. PID: 20093  TASK: bd0c0000  CPU: 1   COMMAND: "save"
    #0 [bd0c1cf0] netconsole_netdump at f9384783
    #1 [bd0c1d04] try_crashdump at 2129783
    #2 [bd0c1d14] die at 210cdc2
    #3 [bd0c1d28] do_invalid_op at 210cfd2
    #4 [bd0c1dc8] error_code (via invalid_op) at 22ad29d
     EAX: 00000053  EBX: 00000010  ECX: 000f6000  EDX: 0015b8f0  EBP: 0817586c
     DS:  0068      ESI: 023a9408  ES:  0068      EDI: 023a8200
     CS:  0060      EIP: 02159f7d  ERR: ffffffff  EFLAGS: 00010006
    #5 [bd0c1e04] rmqueue at 2159f7d
    #6 [bd0c1e40] __alloc_pages_limit at 215a268
    #7 [bd0c1e58] __alloc_pages at 215a36f
    ........ 중략 ............

  4. #14 [bd0c1fc0] system_call at 22ad091
     EAX: 00000003  EBX: 0000000e  ECX: 08324000  EDX: 00010000
     DS:  002b      ESI: 0814c790  ES:  002b      EDI: fefff440
     SS:  002b      ESP: feff10c8  EBP: 00000000
     CS:  0023      EIP: f65deb7e  ERR: 00000003  EFLAGS: 00000246
    crash> rd 08175860 40

  5.   175860:  44445320 362e3120 302e322e 3220312d    SDD 1.6.2.0­1 2
     8175870:  322e342e 37342d31 634c452e 6f747375   .4.21­47.ELcusto
     8175880:  4d53206d 53202050 31207065 30322032   m SMP  Sep 12 20
     8175890:  32203630 37313a30 2037323a 20294328   06 20:17:27 (C)
     81758a0:  204d4249 70726f43 00000a2e 00000000   IBM Corp........
     81758b0:  00000000 00000000 00000000 00000000   ................
     81758c0:  02001000 00000000 00000000 00000000   ................
     81758d0:  00000000 00000000 00000000 00000000   ................
     81758e0:  00000000 00000000 00000000 00000000   ................
     81758f0:  00000000 00000000 00000000 02001000   ................
    crash>

 

사실 이번 케이스는 과정을 매우 중략시켰다. 왜?? 사실 이 케이스는 내가 직접 코어분석을 한 부분이아니고,

다른 사람의 분석자료를 긁어다 붙혔기때문이랄까...(먼산 ㅡ.,ㅡ:: )

아무튼 이 분석의 결과는 IBM sdd 드라이버의 문제로 추정되었고, 고객에게 IBM sdd 드라이버를 업데이트

하는 것으로 마무리 되었다.

뭐 자세한 이유를 설명하자면 위에서 bt 과정에서 rmqueue 부분에서 시스템 패닉이 발생되었음을

알 수 있었고, rmqueue 는 장치(block)를 해제(free)시켜주는 시스템 콜인데, 정상적으로 해제 하지 못한 장치가

있었다는 의미며, 이때당시의 EBP 메모리 주소의 내용을 넓은 범위로 까보니 ( rd 08175860 40 )

SDD 드라이버의 버젼정보가 남아있는 것으로 보아, 커널에서 이 드라이버와 관계된 작업을 정상적으로

Page 재할당 혹은 해제 하지 못했음을 추정 할 수 있었던 게다.....

 

Coredump Analysis 3#

상황#

기존 1번 상황과 같은 엔드유저.

상황은 저번과 다르나 nfs 관련된 서버들이 이상하게 자꾸 뻗는 현상 발생.

역시 그냥 뻗었다면서 sysreport 와 커널덤프파일만 보내온상황..

 

시스템 (OS) : RedHat Enterprise Linux 4 WS

Kernel Ver.  : 2.6.9-22.ELsmp

Machine      : i686

Memory       : 2G

분석과정#
  1. [root@LDS-Mirr debuginfo]# crash 2.6.9-22.ELsmp/vmlinux vmcore
     
    crash 4.0-8.7.2.fc11
    Copyright (C) 2002, 2003, 2004, 2005, 2006, 2007, 2008, 2009  Red Hat, Inc.
    Copyright (C) 2004, 2005, 2006  IBM Corporation
    중략...
    WARNING: kernels compiled by different gcc versions:
      2.6.9-22.ELsmp/vmlinux: 3.4.6
      vmcore kernel: 3.4.4
     
     please wait... (gathering kmem slab cache data)                    
  2.  please wait... (gathering module symbol data)
  3.  please wait... (gathering task table data)                                                  
  4.  please wait... (determining panic task)                                                       
  5.    KERNEL: 2.6.9-22.ELsmp/vmlinux
       DUMPFILE: vmcore
       CPUS: 2
  6.    DATE: Fri Nov  6 05:38:14 2009
       UPTIME: 1478 days, 15:46:30
       LOAD AVERAGE: 2.60, 2.44, 2.25
       TASKS: 126
       NODENAME: *******3
       RELEASE: 2.6.9-22.ELsmp
       VERSION: #1 SMP Mon Sep 19 18:32:14 EDT 2005
       MACHINE: i686  (2993 Mhz)
       MEMORY: 2 GB
       PANIC: "Oops: 0002 [#1]" (check log for details)
       PID: 21797
       COMMAND: "nodemon"
       TASK: db976d30  [THREAD_INFO: d0b03000]
       CPU: 0
       STATE: TASK_RUNNING (PANIC)
     
    crash> bt
  7. PID: 21797  TASK: db976d30  CPU: 0   COMMAND: "nodemon"
     #0 [c03c7e60] netpoll_start_netdump at f89ac570
     #1 [c03c7e80] die at c0106015
    --- <soft IRQ> ---
    bt: cannot resolve stack trace:
    bt: text symbols on stack:
        [d0b03e78] try_crashdump at c013403d
        [d0b03e80] die at c010601a
        [d0b03e98] vprintk at c0122459
        [d0b03eac] __is_prefetch at c011ac2d
        [d0b03eb4] do_page_fault at c011b01d
        [d0b03ec4] process_backlog at c027e357
        [d0b03ef8] tcp_v4_hnd_req at c02aba3e
        [d0b03f08] tcp_v4_rcv at c02abfff
        [d0b03f30] sk_common_release at c0278b71
        [d0b03f48] e1000_alloc_rx_buffers at f890b4b9
        [d0b03f50] ip_rcv at c02947a8
        [d0b03f78] e1000_clean_rx_irq at f890b08f
        [d0b03f8c] __is_prefetch at c011ac2d
        [d0b03f94] irq_entries_start at c02d1bab
        [d0b03fc8] process_backlog at c027e357
        [d0b03fe8] __do_softirq at c0126424
        [d0b03ffc] do_softirq at c010812f
    bt: possible exception frame:
      KERNEL-MODE EXCEPTION FRAME AT d0b03fa0:
        EAX: 00100100  EBX: f76ac100  ECX: f76ac3d0  EDX: 00200200  EBP: bed4a876 
        DS:  007b      ESI: f76ac000  ES:  007b      EDI: c201fc80
        CS:  0060      EIP: c027e357  ERR: ffffffff  EFLAGS: 00010002 
    crash> log
  8. t_r:unlabeled_t tcontext=system_u:object_r:netif_eth0_t tclass=netif
    audit(1256135118.410:55140): avc:  denied  { rawip_recv } for  pid=5672 comm="nodemon" saddr=100.100.1.94 daddr=100.100.1.15 netif=eth0 scontext=system_u:object_r:unlabeled_t tcontext=system_u:object_r:netif_eth0_t tclass=netif
    audit(1256135118.410:55141): avc:  denied  { rawip_recv } for  pid=23125 comm="rrd_ipnms" saddr=100.100.1.94 daddr=100.100.1.15 netif=eth0 scontext=system_u:object_r:unlabeled_t tcontext=system_u:object_r:netif_eth0_t tclass=netif
    audit(1256135118.410:55142): avc:  denied  { rawip_recv } for  pid=5684 comm="nodemon" saddr=119.68.77.13 daddr=58.78.0.216 netif=eth1 scontext=system_u:object_r:unlabeled_t tcontext=system_u:object_r:netif_eth1_t tclass=netif
    audit(1256135118.410:55143): avc:  denied  { rawip_recv } for  pid=5672 comm="nodemon" saddr=100.100.1.94 daddr=100.100.1.15 netif=eth0 scontext=system_u:object_r:unlabeled_t tcontext=system_u:object_r:netif_eth0_t tclass=netif
  9. ...중략...
  10. audit(1257432919.050:55697): avc:  denied  { rawip_recv } for  pid=5537 comm="fping" saddr=116.40.65.2 daddr=58.78.0.216 netif=eth1 scontext=system_u:object_r:unlabeled_t tcontext=system_u:object_r:netif_eth1_t tclass=netif
    audit(1257447387.260:55698): avc:  denied  { rawip_recv } for  pid=7068 comm="fping" saddr=124.48.76.138 daddr=58.78.0.216 netif=eth1 scontext=system_u:object_r:unlabeled_t tcontext=system_u:object_r:netif_eth1_t tclass=netif
    audit(1257453494.395:55699): avc:  denied  { rawip_recv } for  pid=21796 comm="fping" saddr=122.33.123.169 daddr=58.78.0.216 netif=eth1 scontext=system_u:object_r:unlabeled_t tcontext=system_u:object_r:netif_eth1_t tclass=netif
    Unable to handle kernel paging request at virtual address 00100104
     -- MORE --  forward: <SPACE>, <ENTER> or j  backward: b or k  quit: q  printing eip:
    c027e357
    *pde = 29f2a001
    Oops: 0002 [#1]
    SMP 
    Modules linked in: netconsole netdump ipmi_poweroff ipmi_si ipmi_devintf ipmi_msghandler md5 ipv6 parport_pc lp parport autofs4 i2c_dev i2c_core nfs lockd sunrpc dm_mod button battery ac uhci_hcd ehci_hcd hw_random e1000 floppy ext3 jbd gdth sd_mod scsi_mod
    CPU:    0
    EIP:    0060:[<c027e357>]    Not tainted VLI
    EFLAGS: 00010002   (2.6.9-22.ELsmp) 
    EIP is at net_rx_action+0x6b/0xd8
    eax: 00100100   ebx: f76ac100   ecx: f76ac3d0   edx: 00200200
    esi: f76ac000   edi: c201fc80   ebp: bed4a876   esp: c03c7fd4
    ds: 007b   es: 007b   ss: 0068
    Process nodemon (pid: 21797, threadinfo=c03c7000 task=db976d30)
    Stack: 00000129 00000001 c038db98 0000000a 00000000 c0126424 d0b03e18 00000046 
           c038a880 d0b03000 c010812f 
    Call Trace:
     [<c0126424>] __do_softirq+0x4c/0xb1
     [<c010812f>] do_softirq+0x4f/0x56
     =======================
     [<c0107a44>] do_IRQ+0x1a2/0x1ae
     [<c02d1a8c>] common_interrupt+0x18/0x20
     [<c014c747>] do_wp_page+0x1af/0x371
     [<c014d562>] handle_mm_fault+0x11c/0x175
     [<c011addb>] do_page_fault+0x1ae/0x5c6
     [<c011cbba>] recalc_task_prio+0x128/0x133
     [<c011d3d5>] finish_task_switch+0x30/0x66
     [<c02cf368>] schedule+0x844/0x87a
     [<c0107a44>] do_IRQ+0x1a2/0x1ae
     [<c011ac2d>] do_page_fault+0x0/0x5c6
     [<c02d1bab>] error_code+0x2f/0x38
     [<c02d007b>] __lock_text_end+0x11a/0x100f
     -- MORE --  forward: <SPACE>, <ENTER> or j  backward: b or k  quit: q Code: f8 01 77 6c fb 8b 5f 20 8d b3 00 ff ff ff 83 be 08 01 00 00 00 7e 0e 89 e2 89 f0 ff 96 7c 01 00 00 85 c0 74 3d fa 8b 53 04 8b 03 <89> 50 04 89 02 8d 47 20 c7 43 04 00 02 20 00 8b 50 04 89 03 89 

 

길다. 대략 요즘 보면 RedHat 에스컬레이션 시 분석엔지니어가 log 명령을 통해 상세한 로그를 얻어서 분석하던데,

나도 따라해 봤다. 일반 sysreport 에서 남겨지는 message 로그와는 확연히 다른 상세 로그가 남았다.

 

  1. crash> runq
     RUNQUEUES[0]: c201dd60
     ACTIVE PRIO_ARRAY: c201dd9c
      [117] PID: 21797  TASK: db976d30  CPU: 0   COMMAND: "nodemon"
      [134] PID: 3      TASK: f7e005b0  CPU: 0   COMMAND: "ksoftirqd/0"
     EXPIRED PRIO_ARRAY: c201e214
     RUNQUEUES[1]: c2025d60
     ACTIVE PRIO_ARRAY: c2026214
     EXPIRED PRIO_ARRAY: c2025d9c

 

역시 가장 마지막 실행된 데몬 혹은 명령은 nodemon 이라는 녀석이다.

 

  1. crash> ps
        PID    PPID  CPU   TASK    ST  %MEM     VSZ    RSS  COMM
          0      0   0  c031ea80  RU   0.0       0      0  [swapper]
    >     0      1   1  f7e010b0  RU   0.0       0      0  [swapper]
          1      0   1  f7e01630  IN   0.0    3164    560  init
          2      1   0  f7e00b30  IN   0.0       0      0  [migration/0]
          3      1   0  f7e005b0  RU   0.0       0      0  [ksoftirqd/0]
          4      1   1  f7e00030  IN   0.0       0      0  [migration/1]
          5      1   1  f7e456b0  IN   0.0       0      0  [ksoftirqd/1]
          6      1   0  f7e45130  IN   0.0       0      0  [events/0]
          7      1   1  f7e44bb0  IN   0.0       0      0  [events/1]
          8      6   0  f7e44630  IN   0.0       0      0  [khelper]
          9      6   0  f7e440b0  IN   0.0       0      0  [kacpid]
         35      6   0  f7cd5730  IN   0.0       0      0  [kblockd/0]
         36      6   1  f7cd51b0  IN   0.0       0      0  [kblockd/1]
  2. ....중략.....

  3.   21795  21788   1  c2348db0  IN   0.0    1496    512  fping
      21796  21789   1  f54e4cb0  IN   0.0    1496    512  fping
    > 21797  21790   0  db976d30  RU   0.5 1915760  11156  nodemon
      21798  21791   1  f6725430  UN   0.5 1915760  11156  nodemon
      22557      1   1  e148c830  IN   0.0       0      0  [rpciod]
      22558      1   1  c27e63b0  IN   0.0       0      0  [lockd]
      23100   2522   1  f3716330  IN   0.1    4364   1104  crond
      23101  23100   0  f37173b0  DE   0.0       0      0  perfmgr_all.sh
      23114      1   1  f5ca23b0  IN   0.1    6736   1144  perfmgr_all.sh
      23117  23114   1  f5ca2930  IN   0.1    5708   1156  perfmgr
      23125  23117   1  f37168b0  UN   0.1    4228   2632  rrd_ipnms
      24432      1   1  f67259b0  IN   0.0    2672    808  neoctrld
      24433  24432   0  f6724930  IN   0.0    2008    944  neozmond
      24434  24432   0  f47b2030  IN   0.0    3576    884  neopmond
      24435  24432   1  f3acb930  IN   0.0    2304    772  neosmond
      24436  24432   0  f3acae30  IN   0.0    2420    756  neormond
      24437  24432   1  f634cc30  IN   0.0    3212    648  neocmond
      24438  24432   1  f634d1b0  IN   0.0    2800    732  neoemond
      24865   2377   0  ee47ebb0  IN   0.0    3296    652  in.telnetd
      24870  24865   1  f76728b0  DE   0.0       0      0  login
      27098      1   0  c27e6eb0  IN   1.4   42536  29200  poller
      27152      1   1  e7a76930  IN   1.8   51732  37544  poller
      28254      1   0  f75e46b0  IN   0.2   10404   3696  cupsd

 

ps 로 확인 해 보았을 때 역시 표시가 있고,

 

  1. crash> bt 21797
     PID: 21797  TASK: db976d30  CPU: 0   COMMAND: "nodemon"
     #0 [c03c7e60] netpoll_start_netdump at f89ac570
     #1 [c03c7e80] die at c0106015
    --- <soft IRQ> ---
    bt: cannot resolve stack trace:
    bt: text symbols on stack:
        [d0b03e78] try_crashdump at c013403d
        [d0b03e80] die at c010601a
        [d0b03e98] vprintk at c0122459
        [d0b03eac] __is_prefetch at c011ac2d
        [d0b03eb4] do_page_fault at c011b01d
        [d0b03ec4] process_backlog at c027e357
        [d0b03ef8] tcp_v4_hnd_req at c02aba3e
        [d0b03f08] tcp_v4_rcv at c02abfff
        [d0b03f30] sk_common_release at c0278b71
        [d0b03f48] e1000_alloc_rx_buffers at f890b4b9
        [d0b03f50] ip_rcv at c02947a8
        [d0b03f78] e1000_clean_rx_irq at f890b08f
        [d0b03f8c] __is_prefetch at c011ac2d
        [d0b03f94] irq_entries_start at c02d1bab
        [d0b03fc8] process_backlog at c027e357
        [d0b03fe8] __do_softirq at c0126424
        [d0b03ffc] do_softirq at c010812f
    bt: possible exception frame:
      KERNEL-MODE EXCEPTION FRAME AT d0b03fa0:
        EAX: 00100100  EBX: f76ac100  ECX: f76ac3d0  EDX: 00200200  EBP: bed4a876 
        DS:  007b      ESI: f76ac000  ES:  007b      EDI: c201fc80
        CS:  0060      EIP: c027e357  ERR: ffffffff  EFLAGS: 00010002 

 

backtrace 로 찍어 보았다. 잘 보면 스택부분에 크게 의심될만한 호출은 없는 것 같다.

한가지 있다면 backlog 부분과 page_fault ... 약간 의심이 가기 시작한다.

 

  1. crash> task
     PID: 21797  TASK: db976d30  CPU: 0   COMMAND: "nodemon"
    struct task_struct {
      state = 0, 
      thread_info = 0xd0b03000, 
      usage = {
        counter = 2
      }, 
      flags = 64, 
      ptrace = 0, 
      lock_depth = -1, 
      prio = 117, 
      static_prio = 120, 
      run_list = {
        next = 0xc201e15c, 
        prev = 0xc201e15c
      }, 
      array = 0xc201dd9c, 
      sleep_avg = 797645007, 
      interactive_credit = 0, 
      timestamp = 1565221201025565, 
      last_ran = 1565221200988322,
  2. ... 중략 ...

  3.   rlim = {{
          rlim_cur = 4294967295, 
          rlim_max = 4294967295

  4. .... 생략 ...

 

task 를 찍어보았더니 너무 길다. 저번과 같이 deadbeef 같은 번지수는 찾아지지 않았다.

다만 rlim 값이 current 와 max 가 동일한 듯한 느낌이 든다.

 

  1. crash> timer
     TVEC_BASES[0]: c201e760
      JIFFIES  
     3201639042
      EXPIRES    TIMER_LIST  FUNCTION
     3201607813   f759d8b4   c0257180  <rh_call_control+611>
     3201607813   f755a228   f887fa6d  <stall_callback>
     3201607824   e4818c7c   c02a81df  <tcp_out_of_resources+352>
     3201607836   d7286c7c   c02a81df  <tcp_out_of_resources+352>
     3201607838   e585b57c   c02a81df  <tcp_out_of_resources+352>
     3201607846   f7670a28   f887fa6d  <stall_callback>
     3201607887   f76708b4   c0257180  <rh_call_control+611>
     3201607892   efb0df64   c0129fba  <sys_getegid+4>
  2.   ... 중략 ...
  3.  3201715193   e07adecc   c0129fba  <sys_getegid+4>
     3201863941   f6c9bf64   c0129fba  <sys_getegid+4>
     3202207798   c0447ba0   c020a242  <do_blank_screen+476>
     3202500736   f686cef0   c01258b3  <sys_getitimer+102>
     3202531229   f757f7f0   c01258b3  <sys_getitimer+102>
     -- MORE --  forward: <SPACE>, <ENTER> or j  backward: b or k  quit: q 
  4.  3207355798   f2d37390   c02a8a54  <tcp_synack_timer+200>

 

잘모르겠는데 타이머를 한번 찍어보았다.

역시 대략 특이한 점은 찾을 수 없었다.

 

bt 로 나왔던 몇몇 주소들을 dis 명령으로 disassembler 해본다.

 

  1. crash> dis c027e357 100
     0xc027e357 <process_backlog+44>:        mov    %edx,0x4(%eax)
    0xc027e35a <process_backlog+47>:        mov    %eax,(%edx)
    0xc027e35c <process_backlog+49>:        lea    0x20(%edi),%eax
    0xc027e35f <process_backlog+52>:        movl   $0x200200,0x4(%ebx)
    0xc027e366 <process_backlog+59>:        mov    0x4(%eax),%edx
    0xc027e369 <process_backlog+62>:        mov    %eax,(%ebx)
    0xc027e36b <process_backlog+64>:        mov    %ebx,0x4(%eax)
  2. ... 중략 ...
  3. 0xc027e40d <process_backlog+226>:       test   %eax,%eax
    0xc027e40f <process_backlog+228>:       je     0xc027e423 <process_backlog+248>
    0xc027e411 <process_backlog+230>:       xor    %eax,%eax
    0xc027e413 <process_backlog+232>:       mov    $0x8,%ecx
    0xc027e418 <process_backlog+237>:       lea    0x0(%esp),%edi
     -- MORE --  forward: <SPACE>, <ENTER> or j  backward: b or k  quit: q 0xc027e41c <process_backlog+241>:       repz stos %eax,%es:(%edi)
    0xc027e41e <process_backlog+243>:       jmp    0xc027e4b2 <net_rx_action+138>
    0xc027e423 <process_backlog+248>:       mov    $0x20,%ecx
    0xc027e428 <net_rx_action>:     mov    %ebx,%edx
    0xc027e42a <net_rx_action+2>:   lea    0x0(%esp),%eax
    0xc027e42e <net_rx_action+6>:   call   0xc01c1ca0 <__copy_user_zeroing_intel+46>
    0xc027e433 <net_rx_action+11>:  test   %eax,%eax
    0xc027e435 <net_rx_action+13>:  jne    0xc027e4b2 <net_rx_action+138>
    0xc027e437 <net_rx_action+15>:  mov    $0xc034824c,%eax
    0xc027e43c <net_rx_action+20>:  call   0xc02cfc99 <rwsem_down_write_failed+153>
    0xc027e441 <net_rx_action+25>:  mov    0x10(%esp),%eax
    0xc027e445 <net_rx_action+29>:  call   0xc027d197 <netdev_boot_setup_check+141>
    0xc027e44a <net_rx_action+34>:  test   %eax,%eax
    0xc027e44c <net_rx_action+36>:  mov    %eax,%esi
    0xc027e44e <net_rx_action+38>:  jne    0xc027e461 <net_rx_action+57>
    0xc027e450 <net_rx_action+40>:  mov    $0xc034824c,%eax
    0xc027e455 <net_rx_action+45>:  call   0xc02cfce5 <rwsem_down_write_failed+229>
    0xc027e45a <net_rx_action+50>:  mov    $0xffffffed,%edx
    0xc027e45f <net_rx_action+55>:  jmp    0xc027e4b7 <net_rx_action+143>
    0xc027e461 <net_rx_action+57>:  lea    0x0(%esp),%edi
    0xc027e465 <net_rx_action+61>:  lods   %ds:(%esi),%al
    0xc027e466 <net_rx_action+62>:  stos   %al,%es:(%edi)
    0xc027e467 <net_rx_action+63>:  test   %al,%al
    0xc027e469 <net_rx_action+65>:  jne    0xc027e465 <net_rx_action+61>
    0xc027e46b <net_rx_action+67>:  mov    $0xc034824c,%eax
    0xc027e470 <net_rx_action+72>:  call   0xc02cfce5 <rwsem_down_write_failed+229>
    0xc027e475 <net_rx_action+77>:  xor    %ecx,%ecx
    0xc027e477 <net_rx_action+79>:  mov    $0x213,%edx
    0xc027e47c <net_rx_action+84>:  mov    $0xc02dae65,%eax
    0xc027e481 <net_rx_action+89>:  call   0xc011fc54 <in_sched_functions+33>
    0xc027e486 <net_rx_action+94>:  call   0xc02cf6cf <interruptible_sleep_on_timeout+88>
    0xc027e48b <net_rx_action+99>:  mov    %ebx,%edx
    0xc027e48d <net_rx_action+101>: add    $0x20,%edx
     -- MORE --  forward: <SPACE>, <ENTER> or j  backward: b or k  quit: q
  4. 0xc027e490 <net_rx_action+104>: sbb    %eax,%eax

 

딱히 이상해 보이는 어셈부분은 없었다.

 

이번 사례는 아직 에스컬레이션 진행중이고 답은 아직 멀었지만 R 모사의 분석이 나오기 전에

케이스 연습삼아 작성 해 보았다.

일단 내가 예상하는 원인으로는 일단 selinux 가 동작중이며,

nodemon 이라는 녀석이 selinux 로 인해 네트워크쪽 오버헤드를 일으키는 부분이 있는 것 같고,

그로 인한 백로그 상승등이 시스템 Hang Up 상황을 만들지 않았을까 하는데,

어플리케이션의 버그 일수도 있지 않나 싶다.

일단 어떤 해결안에 대한 권고를 해야한다면 selinux 를 꺼보시고 커널파라메터튜닝등을 통해

백로그를 조금 더 잡아주는 것을 권고 해 봐야 겠지...

레드햇 답변 나오면 확인해봐야겠다.. 이렇게 커널분석부분도 케이스를 모아놓으면 도움이 되지 않을까 한다.

-> 레드햇 답변으로는 버그질라 477202 와 동일상황으로 보았다. ( net_rx_action 함수의 race condition 버그 )

즉 커널 업데이트를 권고하는데 4.8 이상으로 음....EIP 에서 나온 함수를 버그질라에서 검색한건가 보네...

미처 생각 못했던 건데....아무튼 대단하긴 하다 ㅡ,.ㅡ::

 

Coredump Analysis 4#

상황#

이번 엔드유저는 다른 엔드유저. 64G, 64비트 환경의 오라클 디비 서버란다.

한달사이에 세번이나 연속되서 리부팅이 이루어 졌다.

 

시스템 (OS) : RedHat Enterprise Linux 5 Server update 3

Kernel Ver.  : 2.6.18-128.ELsmp

Machine      : x86_64

Memory       : 64G

분석과정#
  1.       KERNEL: /usr/lib/debug/lib/modules/2.6.18-128.el5/vmlinux
        DUMPFILE: vmcore
            CPUS: 24
            DATE: Thu Dec 10 22:26:28 2009
          UPTIME: 34 days, 09:18:38
    LOAD AVERAGE: 0.18, 0.12, 0.03
           TASKS: 476
        NODENAME: *******
         RELEASE: 2.6.18-128.el5
         VERSION: #1 SMP Wed Dec 17 11:41:38 EST 2008
         MACHINE: x86_64  (2665 Mhz)
          MEMORY: 63.1 GB
           PANIC: ""
             PID: 29298
         COMMAND: "oracle"
            TASK: ffff8110760ea040  [THREAD_INFO: ffff810f2965a000]
             CPU: 0
           STATE: TASK_RUNNING (PANIC)

  2. crash> bt
    PID: 29298  TASK: ffff8110760ea040  CPU: 0   COMMAND: "oracle"
     #0 [ffffffff804259a0] crash_kexec at ffffffff800aaa0c
     #1 [ffffffff80425a60] __die at ffffffff8006520f
     #2 [ffffffff80425aa0] die at ffffffff8006bc17
     #3 [ffffffff80425ad0] do_invalid_op at ffffffff8006c1d7
     #4 [ffffffff80425b90] error_exit at ffffffff8005dde9
        [exception RIP: end_page_writeback+36]
        RIP: ffffffff80039b4c  RSP: ffffffff80425c40  RFLAGS: 00010246
        RAX: 0000000000000000  RBX: ffff8101393e8690  RCX: 0000000000000034
        RDX: ffff81105b1d02b0  RSI: 0000000000000286  RDI: ffff81105fa99868
        RBP: ffff81105b1d02b0   R8: ffff8108120495b0   R9: ffff81107ef0b000
        R10: ffff810743c7f540  R11: ffffffff800419ac  R12: 0000000000000202
        R13: ffff8101393e8690  R14: 00000001b11317db  R15: 0000000000003000
        ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
     #5 [ffffffff80425c48] end_buffer_async_write at ffffffff80045431
     #6 [ffffffff80425c98] end_bio_bh_io_sync at ffffffff800419db
     #7 [ffffffff80425ca8] dec_pending at ffffffff88182386
     #8 [ffffffff80425cd8] clone_endio at ffffffff8818255a
     #9 [ffffffff80425d08] dec_pending at ffffffff88182386
    #10 [ffffffff80425d38] clone_endio at ffffffff8818255a
    #11 [ffffffff80425d68] dec_pending at ffffffff88182386
    #12 [ffffffff80425d98] clone_endio at ffffffff8818255a
    #13 [ffffffff80425dc8] __end_that_request_first at ffffffff8002ca64
    #14 [ffffffff80425e58] scsi_io_completion at ffffffff8807a1a8
    #15 [ffffffff80425eb8] sd_rw_intr at ffffffff880a67cd
    #16 [ffffffff80425f18] blk_done_softirq at ffffffff800376ff
    #17 [ffffffff80425f38] __do_softirq at ffffffff80011fbc
    #18 [ffffffff80425f68] call_softirq at ffffffff8005e2fc
    #19 [ffffffff80425f80] do_softirq at ffffffff8006cada
    #20 [ffffffff80425f90] do_IRQ at ffffffff8006c962
    --- <IRQ stack> ---
    #21 [ffff810f2965b818] ret_from_intr at ffffffff8005d615
        [exception RIP: dm_table_put+20]
        RIP: ffffffff88183d5b  RSP: ffff810f2965b8c8  RFLAGS: 00000202
        RAX: 0000000000000000  RBX: ffff81107a9c8800  RCX: c000000000000000
        RDX: 0000000000000000  RSI: 0000000000000000  RDI: ffff810139ea4e00
        RBP: ffff810742b09a08   R8: ffff81107bbcd800   R9: ffff810776208b08
        R10: ffff81107ef0b000  R11: ffffffff80146083  R12: ffff81107a9c8800
        R13: 0000000000000000  R14: ffffffff88182465  R15: 000000000fd00001
        ORIG_RAX: ffffffffffffffcd  CS: 0010  SS: 0018
    #22 [ffff810f2965b8e0] dm_request at ffffffff8818394c
    ..... 중략
  3. #37 [ffff810f2965bde0] ext3_file_write at ffffffff8804c18e
    #38 [ffff810f2965be00] do_sync_write at ffffffff80017d2d
    #39 [ffff810f2965bf10] vfs_write at ffffffff8001659e
    #40 [ffff810f2965bf40] sys_pwrite64 at ffffffff80043876
    #41 [ffff810f2965bf80] system_call at ffffffff8005d116
        RIP: 00000037eda0de33  RSP: 00007fffc74a15c0  RFLAGS: 00000206
        RAX: 0000000000000012  RBX: ffffffff8005d116  RCX: 0000000000000371
        RDX: 0000000000100000  RSI: 0000000060bcbc00  RDI: 0000000000000013
        RBP: 0000000000000200   R8: 00000000bc67e0f0   R9: 0000000060bcbc00
        R10: 00000000024fb800  R11: 0000000000000246  R12: 00000000000127db
        R13: 00007fffc74a1160  R14: 00002b24e53e45a8  R15: 00000000c74a1310
        ORIG_RAX: 0000000000000012  CS: 0033  SS: 002b
    crash>

 

더럽게 길다. 게다가 자꾸 I/O 및 파일시스템 관련 시스템콜만 더럽게 불러대끼고 있으며,

우리가 원하는 EIP 등은 눈을 씻고 찾아봐도 나오질 않는다.

그렇다 이건 64비트..확장된 레지스터를 사용하기 때문에 기존 E 자들은 R 자로 변경되었다 (쉽게쉽게~)

자 RIP 가 보인다. 보면 page_writeback 시스템콜등 디스크에 기록하는 부분들에서 멈춰댔다.

실제 이 것들만 보면 리부팅의 원인은 페이지 기록 즉 디스크에 기록하는 작업에서 문제가 발생한것으로

생각할 수 있다. 로그를 보자.

  1. usb-storage: device scan complete
    usb 1-7: USB disconnect, address 4
    ----------- [cut here ] --------- [please bite here ] ---------
    Kernel BUG at mm/filemap.c:568
    invalid opcode: 0000 [1] SMP
    last sysfs file: /devices/pci0000:00/0000:00:1c.0/resource
    CPU 0
    Modules linked in: vfat fat usb_storage iptable_mangle iptable_nat ip_nat ip_con
    ntrack nfnetlink iptable_filter ip_tables x_tables ipv6 xfrm_nalgo crypto_api au
    tofs4 sunrpc ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp
    libiscsi scsi_transport_iscsi dm_mirror dm_round_robin dm_multipath scsi_dh vide
    o hwmon backlight sbs i2c_ec i2c_core button battery asus_acpi acpi_memhotplug a
    c parport_pc lp parport joydev sg shpchp ide_cd cdrom e1000e bnx2 pcspkr dm_raid
    45 dm_message dm_region_hash dm_log dm_mod dm_mem_cache lpfc scsi_transport_fc a
    ta_piix libata megaraid_sas sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd
    Pid: 29298, comm: oracle Not tainted 2.6.18-128.el5 #1
    RIP: 0010:[<ffffffff80039b4c>]  [<ffffffff80039b4c>] end_page_writeback+0x24/0x4
    7
    RSP: 0018:ffffffff80425c40  EFLAGS: 00010246
    RAX: 0000000000000000 RBX: ffff8101393e8690 RCX: 0000000000000034
    RDX: ffff81105b1d02b0 RSI: 0000000000000286 RDI: ffff81105fa99868
    RBP: ffff81105b1d02b0 R08: ffff8108120495b0 R09: ffff81107ef0b000
    R10: ffff810743c7f540 R11: ffffffff800419ac R12: 0000000000000202
    R13: ffff8101393e8690 R14: 00000001b11317db R15: 0000000000003000
    FS:  00002b24e5219c40(0000) GS:ffffffff803ac000(0000) knlGS:0000000000000000
    CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
    CR2: 0000000071009fac CR3: 0000000f29821000 CR4: 00000000000006e0
    Process oracle (pid: 29298, threadinfo ffff810f2965a000, task ffff8110760ea040)
    Stack:  ffff81105b1d02b0 ffffffff80045431 ffff810743c7f340 0000000000000246
     0000000000000001 ffff810743c7f340 ffff810743c7f340 ffff8107343965c0
     ffff810752d02ec0 0000000000000001 0000000000000001 ffffffff800419db
    Call Trace:
     <IRQ>  [<ffffffff80045431>] end_buffer_async_write+0xff/0x126
     [<ffffffff800419db>] end_bio_bh_io_sync+0x2f/0x3b
     [<ffffffff88182386>] :dm_mod:dec_pending+0x170/0x194
     [<ffffffff8818255a>] :dm_mod:clone_endio+0x97/0xc5
     [<ffffffff88182386>] :dm_mod:dec_pending+0x170/0x194
     [<ffffffff8818255a>] :dm_mod:clone_endio+0x97/0xc5
     [<ffffffff88182386>] :dm_mod:dec_pending+0x170/0x194
     [<ffffffff8818255a>] :dm_mod:clone_endio+0x97/0xc5
     [<ffffffff8002ca64>] __end_that_request_first+0x265/0x5df
     [<ffffffff8005bd2f>] blk_run_queue+0x28/0x72
     [<ffffffff88079fb4>] :scsi_mod:scsi_end_request+0x27/0xcd
     [<ffffffff8807a1a8>] :scsi_mod:scsi_io_completion+0x14e/0x324
     [<ffffffff880a67cd>] :sd_mod:sd_rw_intr+0x21d/0x257
     [<ffffffff88125117>] :lpfc:lpfc_intr_handler+0x53d/0x580
     [<ffffffff8807a43d>] :scsi_mod:scsi_device_unbusy+0x67/0x81
     [<ffffffff800376ff>] blk_done_softirq+0x5f/0x6d
     [<ffffffff80011fbc>] __do_softirq+0x89/0x133
     [<ffffffff8005e2fc>] call_softirq+0x1c/0x28
     [<ffffffff8006cada>] do_softirq+0x2c/0x85
     [<ffffffff8006c962>] do_IRQ+0xec/0xf5
     [<ffffffff8005d615>] ret_from_intr+0x0/0xa
     <EOI>  [<ffffffff80146083>] cfq_latter_request+0x0/0x1d
     [<ffffffff88183d5b>] :dm_mod:dm_table_put+0x14/0xc5
     [<ffffffff8818394c>] :dm_mod:dm_request+0x115/0x124
     [<ffffffff8001bd3d>] generic_make_request+0x1d2/0x1e9
     [<ffffffff88182465>] :dm_mod:__map_bio+0xbb/0x119
     [<ffffffff88182f3c>] :dm_mod:__split_bio+0x188/0x3be
     [<ffffffff8818394c>] :dm_mod:dm_request+0x115/0x124
     [<ffffffff8001bd3d>] generic_make_request+0x1d2/0x1e9
     [<ffffffff80022ba3>] mempool_alloc+0x31/0xe7
     [<ffffffff80032e58>] submit_bio+0xcd/0xd4
     [<ffffffff8001a357>] submit_bh+0xf1/0x111
     [<ffffffff8001bf4a>] __block_write_full_page+0x1f6/0x301
     [<ffffffff8804eca5>] :ext3:ext3_get_block+0x0/0xf9
     [<ffffffff88050457>] :ext3:ext3_ordered_writepage+0xf1/0x198
     [<ffffffff8001cab3>] mpage_writepages+0x1ab/0x34d
     [<ffffffff88050366>] :ext3:ext3_ordered_writepage+0x0/0x198
     [<ffffffff8005a795>] do_writepages+0x29/0x2f
     [<ffffffff8004f4f0>] __filemap_fdatawrite_range+0x50/0x5b
     [<ffffffff800c29b8>] sync_page_range+0x3d/0xa1
     [<ffffffff8002117e>] generic_file_aio_write+0xa6/0xc1
     [<ffffffff8804c18e>] :ext3:ext3_file_write+0x16/0x91
     [<ffffffff80017d2d>] do_sync_write+0xc7/0x104
     [<ffffffff8009db21>] autoremove_wake_function+0x0/0x2e
     [<ffffffff80063097>] thread_return+0x62/0xfe
     [<ffffffff8001659e>] vfs_write+0xce/0x174
     [<ffffffff80043876>] sys_pwrite64+0x50/0x70
     [<ffffffff8005d116>] system_call+0x7e/0x83


    Code: 0f 0b 68 af b7 29 80 c2 38 02 48 89 df e8 f1 0b fe ff 48 89
    RIP  [<ffffffff80039b4c>] end_page_writeback+0x24/0x47
     RSP <ffffffff80425c40>
    crash>

다 생략하고 끝에 컷 히얼~ 여기만 붙혔다.

역시나 end_page_writeback 즉 page 기록 중에 생긴 문제란다.

결국 dm 사용이 되고 있는지, 벤더 제공 디스크관련 모듈을 사용하고 있지 않은지 확인해 봐야 겠다.

  1. crash> mod
         MODULE       NAME                    SIZE  OBJECT FILE
    ffffffff88007e80  ehci_hcd               65741  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88017800  ohci_hcd               55925  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88026e00  uhci_hcd               57433  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8803fd80  jbd                    94257  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8806ae00  ext3                  168017  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8809ca80  scsi_mod              196569  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff880aba00  sd_mod                 56385  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff880bc880  megaraid_sas           72445  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff880f2c80  libata                208721  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88101c00  ata_piix               56901  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88114e00  scsi_transport_fc      73801  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8816ce00  lpfc                  352909  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88178600  dm_mem_cache           38977  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88191d80  dm_mod                100369  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8819ed00  dm_log                 44865  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff881ab200  dm_region_hash         46145  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff881b5b00  dm_message             36161  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff881cf080  dm_raid45              99025  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff881d9b80  pcspkr                 36289  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8820e300  bnx2                  210249  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8821a900  joydev                 43969  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88242700  e1000e                145809  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88256600  cdrom                  68713  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88269a00  ide_cd                 73825  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8827d200  shpchp                 70765  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8828ff00  sg                     69993  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff882a3b00  parport                73165  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff882b0080  lp                     47121  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff882c1000  parport_pc             62312  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff882cc500  ac                     38729  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff882d7a80  acpi_memhotplug        40133  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff882e5480  asus_acpi              50917  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff882f1900  battery                43849  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff882fcc00  button                 40545  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8830b900  i2c_core               56129  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88316480  i2c_ec                 38593  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88324080  sbs                    49921  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8832f980  backlight              39873  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88339c80  hwmon                  36553  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88347d80  video                  53197  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88353080  scsi_dh                41665  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88362580  dm_multipath           55257  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8836cd80  dm_round_robin         36801  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8837ad80  dm_mirror              53193  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8838c400  scsi_transport_iscsi   67153  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8839d600  libiscsi               63553  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff883ad200  iscsi_tcp              58433  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff883b9180  ib_addr                41929  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff883d1b80  ib_core                93637  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff883e4180  ib_mad                 70629  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff883f7f80  ib_sa                  74441  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88404780  iw_cm                  43465  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88416400  ib_cm                  67305  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88428380  rdma_cm                67157  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8843a280  ib_iser                66873  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88468800  sunrpc                197897  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8847bc80  autofs4                57033  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88487580  crypto_api             42945  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88493700  xfrm_nalgo             43333  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff884f9f80  ipv6                  424609  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8850a280  x_tables               50377  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88518d80  ip_tables              55329  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88523b00  iptable_filter         36161  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8852eb80  nfnetlink              40457  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88545800  ip_conntrack           91109  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88554400  ip_nat                 52845  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8855fd00  iptable_nat            40773  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88569a80  iptable_mangle         36033  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff88587100  usb_storage           116641  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff8859dd00  fat                    85873  (not loaded)  [CONFIG_KALLSYMS]
    ffffffff885aa300  vfat                   46401  (not loaded)  [CONFIG_KALLSYMS]
    crash>

그래. 멀티패스 사용한다. HP 스토리지이며 lpfc 모듈이 올라가 있다.

자 lpfc 모듈등을 점검해 보자고 하자.

sosreport  에서 보여지는 module 정보에선 lpfc의 버젼은 8.2.0.33.3p 로 나온다.

이 모듈의 버그 혹은 업데이트 버젼이 있는지 확인해 보라고 해야한다.

일단 디스크가 떨어지는 버그는 버그질라에 보고되고 있다.

 ( https://bugzilla.redhat.com/show_bug.cgi?id=470610 )

그런데 큰일이 생겼다.

한참 분석중인상태에서 다시 리부팅이 이루어졌다.

보여진 메시지는 다음과 같다고 한다.

  1. Dec 15 11:38:22 udb kernel: Bad page state in process 'oracle'
    Dec 15 11:38:22 udb kernel: page:ffff810126fed270 flags:0x0b20100000000008 mapping:ffff811038016598 mapcount:0 count:0 (Tainted: G    B)
    Dec 15 11:38:22 udb kernel: Trying to fix it up, but a reboot is needed
    Dec 15 11:38:22 udb kernel: Backtrace:
    Dec 15 11:38:22 udb kernel:
    Dec 15 11:38:22 udb kernel: Call Trace:
    Dec 15 11:38:22 udb kernel:  [<ffffffff800c4570>] bad_page+0x69/0x91
    Dec 15 11:38:22 udb kernel:  [<ffffffff8000a76a>] get_page_from_freelist+0x262/0x3fa
    Dec 15 11:38:22 udb kernel:  [<ffffffff8000f10b>] __alloc_pages+0x65/0x2ce
    Dec 15 11:38:22 udb kernel:  [<ffffffff80010e8c>] do_wp_page+0x2fa/0x6b5
    Dec 15 11:38:22 udb kernel:  [<ffffffff80009406>] __handle_mm_fault+0xd9b/0xe5c
    Dec 15 11:38:22 udb kernel:  [<ffffffff80066b9a>] do_page_fault+0x4cb/0x830
    Dec 15 11:38:22 udb kernel:  [<ffffffff8001c8db>] vma_link+0xd0/0xfd
    Dec 15 11:38:22 udb kernel:  [<ffffffff8000de64>] do_mmap_pgoff+0x66c/0x7d7
    Dec 15 11:38:22 udb kernel:  [<ffffffff8002fd5e>] __up_write+0x27/0xf2
    Dec 15 11:38:22 udb kernel:  [<ffffffff8005dde9>] error_exit+0x0/0x84
    Dec 15 11:38:22 udb kernel:
    Dec 15 11:38:22 udb kernel: Bad page state in process 'oracle'
    Dec 15 11:38:22 udb kernel: page:ffff810126fed2a8 flags:0x0b2010000000002c mapping:0000000000000000 mapcount:0 count:1 (Tainted: G    B)
    Dec 15 11:38:22 udb kernel: Trying to fix it up, but a reboot is needed
    Dec 15 11:38:22 udb kernel: Backtrace:
    Dec 15 11:38:22 udb kernel:
    Dec 15 11:38:22 udb kernel: Call Trace:
    Dec 15 11:38:22 udb kernel:  [<ffffffff800c4570>] bad_page+0x69/0x91
    Dec 15 11:38:22 udb kernel:  [<ffffffff8000a76a>] get_page_from_freelist+0x262/0x3fa
    Dec 15 11:38:22 udb kernel:  [<ffffffff8000f10b>] __alloc_pages+0x65/0x2ce
    Dec 15 11:38:22 udb kernel:  [<ffffffff80010e8c>] do_wp_page+0x2fa/0x6b5
    Dec 15 11:38:22 udb kernel:  [<ffffffff80009406>] __handle_mm_fault+0xd9b/0xe5c
    Dec 15 11:38:22 udb kernel:  [<ffffffff80066b9a>] do_page_fault+0x4cb/0x830
    Dec 15 11:38:22 udb kernel:  [<ffffffff8001c8db>] vma_link+0xd0/0xfd
    Dec 15 11:38:22 udb kernel:  [<ffffffff8000de64>] do_mmap_pgoff+0x66c/0x7d7
    Dec 15 11:38:23 udb kernel:  [<ffffffff8002fd5e>] __up_write+0x27/0xf2
    Dec 15 11:38:23 udb kernel:  [<ffffffff8005dde9>] error_exit+0x0/0x84

멋지다. 커널 개발자들도 눈을 씻고 봐야 한다는 Bad Page state 라는 에러가 보인다.

커널 개발의 수많은 부분중 메모리 관련된 mm 을 패칭하는 mm guy 들은 꼼꼼하기로 소문이 자자한데,

가장 많이 신경 쓰는 것이 Bad Page 부분이다.

lkml.org 를 보면 리누즈와 Gene 이란 사람의 bad page 관련 주고받는 내용이 있다.

(  http://lkml.org/lkml/2009/8/1/66    http://lkml.org/lkml/2009/8/2/300  )

거기서 리누즈는 몇번의 테스트 요청 끝에 커널 버그가 아니라고 선언했다.

왜냐면 항상 동일 메모리 번지에 문제가 생겼기 때문이다. 그는 메모리 테스트를 해야하고,

Gene 은 메모리 테스트를 통해 메모리 문제를 확인 하였다. 이부분에 대한 메일링리스트도 있었던걸로

기억하는데 지금 찾아보니 없다. 8월 25일경이였는데.......

어쨋든 이 메시지를 받은 순간 고민하였으나,

바로 오늘만 다시 저 메시지와함께 세번의 리부팅이 있었다.

역시 거기서 나오는 Page 주소는 page:ffff810126fed270.

처음 호출시 tainted 라고 뿌려지며 오늘 보내준 메시지 역시 다음과 같다.

  1. oracle@udb.kpetro.or.kr:/oracle>
    Message from syslogd@ at Thu Dec 17 16:00:55 2009 ...
    udb kernel: Bad page state in process 'tar'
    Message from syslogd@ at Thu Dec 17 16:00:56 2009 ...
    udb kernel: page:ffff810137c95e70 flags:0x0ff0100000000008 mapping:ffff81104fedc850 mapcount:0 count:0 (Not tainted)
    Message from syslogd@ at Thu Dec 17 16:00:58 2009 ...
    udb kernel: Trying to fix it up, but a reboot is needed
    Message from syslogd@ at Thu Dec 17 16:01:00 2009 ...
    udb kernel: Backtrace:
    Message from syslogd@ at Thu Dec 17 16:01:01 2009 ...
    udb kernel: Bad page state in process 'tar'
    Message from syslogd@ at Thu Dec 17 16:01:01 2009 ...
    udb kernel: page:ffff810137c95ea8 flags:0x0ff010000000082c mapping:0000000000000000 mapcount:0 count:2 (Tainted: G    B)
    Message from syslogd@ at Thu Dec 17 16:01:01 2009 ...
    udb kernel: Trying to fix it up, but a reboot is needed
    Message from syslogd@ at Thu Dec 17 16:01:01 2009 ...
    udb kernel: Backtrace:

잘 봐라 역시 동일한 주소며 첫번째는 Tainted 가 없었지만 같은 buddy 에 있는 38번째 비트의 메모리번지에서

tainted 가 표시되고 있다.

이 경우는 분명히 메모리의 물리적 오류가 있다는 것을 알 수 있었다.

하지만 역시 Core 분석시 보여주던 부분도 있기 때문에 일단 memtest 를 해보고,

lpfc 관련 드라이버역시 최신 업데이트를 확인해 보라고 하였다.

디스크쪽과 메모리쪽의 중복된 문제들이 발견된 이상 하드웨어의 전반적인 점검또한 고객에게 권고 할 수 있을 것이다.

 

원래 처음엔 코어분석을 먼저 하지 않고 상기 Bad page 관련 메시지만 보았고,

백프로 메모리 테스트를 장담하였는데, Redhat 사의 커널 분석엔지니어역시 메모리 테스트를 동일하게 권고하였다.

 

Coredump Analysis 5#

상황#

VMware 에 올라가 있는 RHEL 4.7 Oracle Was 서버이다.

오전에 갑작스러운 셧다운이 일어났고, 덤프를 떴으나 덤프는 incompletement 라는 메시지와 함께

정상적으로 떨어지지 않았다.

이번엔 이럴 경우에 대해서 살펴 보기로 한다.

 

시스템 (OS) : RedHat Enterprise Linux 4 AS update 7

Kernel Ver.  : 2.6.9-78.ELsmp

Machine      : i686

Memory       : 6G

분석과정#

일단 VMware 상에서의 넷덤프 및 디스크 덤프는 약간 정상적으로 작동하지 못하는 것 같다.

이 경우엔 Crash 툴을 통한 접근이 어렵다.

하지만 포기하지 말자. incompletement 코어를 가지고도 할 수 있는 일이 있으니,

그것은 바로 크래쉬 로그 뽑기이다.

strings 를 통해 문자열들을 뽑아보면 커널 크래쉬 로그가 남는다.

 

  1. # ] strings vmcore-incomplement > core_strings

 

7.1G 정도 쌓여있던 코어파일에서 약 260메가 정도 되는 파일이 생성되었다.

이제 이 스트링파일을 열어보자. 이 용량역시 엄청나 VI 로 열기 버거울 수 도 있겠지만

어쩌겠냐...열어봐야지

 

앞에 막 들어가있는 가비지문자들은 전부버리자. 아마 케이스마다 다르겠지만,

난 앞의 약 5만줄을 날렸더니 그럭저럭 다음과 같은 볼만한 문자가 보이더라.

  1. cpu_mask_to_apicid
    cpu_mask_to_apicid
    smp_call_function
    wakeup_secondary_cpu
    check_nmi_watchdog
    timer_irq_works
    unlock_ExtINT_logic
    follow_hugetlb_page
    load_balance
    context_switch
    interruptible_sleep_on
    interruptible_sleep_on_timeout
    sleep_on_timeout
    migration_thread
    __put_task_struct

 

자 좀 더 내리면 중간에 역시 마치 binary 스트링 뽑아냈을때 처럼 printf 포맷스트링들이 즐비해 있다.

다 무시하고 쭈~~~욱 내려가다보면 다음과 같은 눈에 확 들어오게 되는 문자열이 보이게 된다.

  1. -------------[ cut here ]------------

 

많이 보던 문자 아닌가?

그렇다. crash 툴에서 찍어보던 log 를 나타내주는 문자열이였다.

자 이제 이 문자열을 검색해보자.

  1. :/cut here

  2. <4>------------[ cut here ]------------
    <1>kernel BUG at kernel/exit.c:904!
    <1>invalid operand: 0000 [#1]
    <4>SMP
    <4>Modules linked in: loop seos(U) eAC_mini(U) md5 ipv6 i2c_dev i2c_core vsock(U) vmmemctl(U) pvscsi(U) sunrpc cpufreq_powersave ide_dump scsi_dump diskdump zlib_deflate dm_mirror dm_mod button battery ac vmci(U) acpiphp pcnet32 mii floppy vmxnet(U) ext3 jbd ata_piix libata mptscsih mptsas mptspi mptscsi mptbase sd_mod scsi_mod
    <4>CPU:    0
    <4>EIP:    0060:[<c0124cc5>]    Tainted: P      VLI
    <4>EFLAGS: 00010046   (2.6.9-78.ELsmp)
    <4>EIP is at next_thread+0xc/0x3f
    <4>eax: 00000000   ebx: ca340db0   ecx: 00717ff4   edx: dd4378f0
    <4>esi: 000080aa   edi: 00008551   ebp: b3a5c198   esp: e03d9f8c
    <4>ds: 007b   es: 007b   ss: 0068
    <4>Process emagent (pid: 27221, threadinfo=e03d9000 task=ca340db0)
    <4>Stack: c012f536 00000246 00000000 b3a5c174 00000000 e03d9fa8 00000000 00000000
    <4>       c01265f5 b3a5c198 b7f98c34 b3a5c200 e03d9000 c02e09db b3a5c198 00717ff4
    <4>       b7f98c34 b7f98c34 b3a5c200 b3a5c1a8 0000002b c02e007b 0000007b 0000002b

 

위대한 탐험가들이여. 보이는가? 마치 crash 를 실행시켜 bt 나 log 를 찍었을 때와 동일한

EIP 와 콜 트레이스 및 스택의 위용이 느껴지는가?

 

emagent 프로세스에서 걸리는 저 문제는 명백히 예전에 있던 이슈였고,

Oracle 측에서 2.6.9-78.0.22 커널로 올리는것을 권고했었던 적이 있는 사이트였다.

업무담당자는 emagent 가 안올라갔다고 했었으나, sysreport 와 코어 스트링, 그리고

재부팅된 서버에 접속하여 확인 해 본 결과로는 emagent 가 떡! 하니 돌아가고 있었다.

녀석의 야욕을 빠르게 읽어내어 승자의 미소를 띄우며 담당자에게 보고가 가능했고,

담당자는 크게 만족하며 고개를 끄덕였다.

깨진 코어파일을 R사에 보내봤자, 완벽한 파일만 요구받을 뿐이라는 교훈을 명심하기 바란다.

 

 

Coredump Analysis 6#

상황#

이번엔 매우 난감한 경우였다. 무려 한달이 넘도록 길게 끌어오던 이슈였으니까...

역시 VMware 에 올라가 있는 서버이며, WAS + Java APP 가 돌아가는 시스템이다.

OS 는 올 10월 EOS 가 되는 RHEL3 이다.

이슈는 원래 Hugemem 에 작동 되던 시스템을 VMware 지원 문제로 인하여 SMP 로 돌린다는것... ( Ram 16G )

자. 일단 살펴보자

.

시스템 (OS) : RedHat Enterprise Linux 3 AS update 6 ( 커널은 3.9 커널 )

Kernel Ver.  : 2.6.21-50.ELsmp

Machine      : i686

Memory       : 16G

분석과정#

문제는 실제 장애상황에서도 좀체로 덤프를 뜰수가 없었던 상황이였다.

결국 다시 장애상황 발생하여 sysrq 로 덤프를 떴다. 자 중요하다 sysrq 다

RHEL 3버젼의 경우 다음과 같이 crash 실행을 해야 한다.

 

  1. crash /boot/vmlinux-2.4.21-50.ELsmp vmlinux-2.4.21-50.ELsmp.debug /vmcore/vmcore

 

  1. KERNEL: /boot/vmlinux-2.4.21-50.ELsmp 
  2. DEBUGINFO: vmlinux-2.4.21-50.ELsmp.debug
  3. DUMPFILE: /vmcore/vmcore
  4. CPUS: 4        
  5. DATE: Tue Mar  2 00:10:38 2010      
  6. UPTIME: 20 days, 17:24:55
  7. LOAD AVERAGE: 37.56, 37.62, 33.58       
  8. TASKS: 1679    
  9. NODENAME: pil*****.*****.co.kr     
  10. RELEASE: 2.4.21-50.ELsmp     
  11. VERSION: #1 SMP Tue May 8 17:18:29 EDT 2007     
  12. MACHINE: i686  (2664 Mhz)      
  13. MEMORY: 17 GB       
  14. PANIC: "Oops: 0002" (check log for details)         
  15. PID: 3444     
  16. COMMAND: "crond"        
  17. TASK: efbe8000           
  18. CPU: 3       
  19. STATE: TASK_RUNNING (SYSRQ)

 

STAE 를 보면 재밌게도 TASK_RUNNING (SYSRQ) 라고 써져 있는 것을 볼 수 있다.

시스템 행업상태는 아니지만 SYSRQ 로 덤프를 떴다는 의미이다.

 

늘 R 사에서 하듯 log 부터 찍어보자.

 

  1. Linux version 2.4.21-50.ELsmp (brewbuilder@hs20-bc1-6.build.redhat.com) (gcc version 3.2.3 20030502 (Red Hat Linux 3.2.3-58))
     #1 SMP Tue May 8 17:18:29 EDT 2007
    ********************************************************
    * This system has more than 16 Gigabyte of memory.     *
    * It is recommended that you read the release notes    *
    * that accompany your copy of Red Hat Enterprise Linux *
    * about the recommended kernel for such configurations *
    ********************************************************

 

오옹... 여기 경고가 떡 하니 뜬다. Hugemem 을 권장하라는 얘기이다.

16기가라고 했는데,  실상 보니 약간 더 넘게 설정되어 있어 17G 로 인식한다 서버에서는...

  1. SysRq : Crashing the kernel by request
    Unable to handle kernel NULL pointer dereference at virtual address 00000000
     printing eip:
    c01d1620
    *pde = 1dff1001
    *pte = 00000000
    Oops: 0002
    netconsole audit vsock vmci vmmemctl nfs lockd sunrpc vmxnet microcode ext3 jbd mptscsih mptbase diskdumplib sd_mod scsi_mod
     
    CPU:    3
    EIP:    0060:[<c01d1620>]    Tainted: GF
    EFLAGS: 00210086

    EIP is at sysrq_handle_crash [kernel] 0x0 (2.4.21-50.ELsmp/i686)
    eax: efbe9e58   ebx: c03b9ec0   ecx: 00000001   edx: c0388e98
    esi: 00000063   edi: 00000006   ebp: 00000063   esp: efbe9d84
    ds: 0068   es: 0068   ss: 0068
    Process crond (pid: 3444, stackpage=efbe9000)
    Stack: c01d1caa 00000063 efbe9e58 c04fe544 f7fe0000 f7fe0000 c04fe544 efbe9e58
           c01d1c0d 00000063 efbe9e58 c04fe544 f7fe0000 0000002e 00000002 00000003
           efbe9e58 c01cf74b 00000063 efbe9e58 c04fe544 f7fe0000 2e00004d 0000002e
    Call Trace:   [<c01d1caa>] __handle_sysrq_nolock [kernel] 0x7a (0xefbe9d84)
    [<c01d1c0d>] handle_sysrq [kernel] 0x5d (0xefbe9da4)
    [<c01cf74b>] handle_scancode [kernel] 0x2ab (0xefbe9dc8)
    [<c01d092d>] handle_kbd_event [kernel] 0xbd (0xefbe9df0)
    [<c01d094c>] keyboard_interrupt [kernel] 0x1c (0xefbe9e08)
    [<c010ddb9>] handle_IRQ_event [kernel] 0x69 (0xefbe9e0c)
    [<c010dff9>] do_IRQ [kernel] 0xb9 (0xefbe9e2c)
    [<c010df40>] do_IRQ [kernel] 0x0 (0xefbe9e50)
    [<c02b0324>] call_do_IRQ [kernel] 0x7 (0xefbe9e54)
    [<c0158f8f>] .text.lock.vmscan [kernel] 0xb7 (0xefbe9e80)
    [<c01575fb>] rebalance_dirty_zone [kernel] 0xab (0xefbe9eac)
    [<c015a1a9>] __alloc_pages [kernel] 0x399 (0xefbe9ed4)
    [<c015a26c>] __get_free_pages [kernel] 0x1c (0xefbe9f1c)
    [<c0126b1f>] dup_task_struct [kernel] 0x5f (0xefbe9f20)
    [<c01274c7>] copy_process [kernel] 0x87 (0xefbe9f34)
    [<c012805f>] do_fork [kernel] 0x4f (0xefbe9f64)
    [<c016fb2c>] sys_stat64 [kernel] 0x5c (0xefbe9f84)
    [<c0109d49>] sys_clone [kernel] 0x49 (0xefbe9fa0)
    [<c02b006f>] no_timing [kernel] 0x7 (0xefbe9fc0)

    Code: c6 05 00 00 00 00 00 c3 90 8d b4 26 00 00 00 00 0f b6 54 24

    CPU#0 is frozen.
    CPU#1 is frozen.
    CPU#2 is frozen.
    CPU#3 is executing netdump.
    < netdump activated - performing handshake with the server. >

 

자 재밌게 netdump 동작한 부분까지 나온다. crond 에서 걸려있다.

bt 를 걸어봐 봤자 crond 에 대한 것만 나올테니 이번엔 대체 왜 문제가 생겼는지 부터 보자.

핵심은 행업상태인줄 알고 있었다는것 ( 서버 무반응 ). 일단 프로세스부터 보자.

 

  1. crash> last
    [179069506]  PID: 1096   TASK: d7304000  CPU: 0   COMMAND: "syslogd"
    [179069505]  PID: 1927   TASK: e7856000  CPU: 0   COMMAND: "java"
    [179069505]  PID: 1935   TASK: de4f2000  CPU: 0   COMMAND: "java"
    [179069505]  PID: 1939   TASK: f5b5c000  CPU: 0   COMMAND: "java"
    [179069504]  PID: 1100   TASK: d7308000  CPU: 2   COMMAND: "klogd"
    [179069504]  PID: 1270   TASK: f6fee000  CPU: 1   COMMAND: "python"
    [179069504]  PID: 1444   TASK: f6eb0000  CPU: 1   COMMAND: "vmware-guestd"
    [179069504]  PID: 1782   TASK: f6a20000  CPU: 2   COMMAND: "login"
    [179069504]  PID: 1902   TASK: db52e000  CPU: 0   COMMAND: "java"
    [179069504]  PID: 27189  TASK: defe4000  CPU: 0   COMMAND: "nohup"
    [179069504]  PID: 30763  TASK: dd5f8000  CPU: 2   COMMAND: "httpd"
    [179069503]  PID: 1460   TASK: f6e78000  CPU: 2   COMMAND: "sshd"
    [179069503]  PID: 2048   TASK: efdd2000  CPU: 0   COMMAND: "java"
    [179069503]  PID: 2260   TASK: f405c000  CPU: 1   COMMAND: "java"
    [179069503]  PID: 15783  TASK: ecbde000  CPU: 0   COMMAND: "tecad_logfile"
    [179069503]  PID: 24013  TASK: e8aa0000  CPU: 1   COMMAND: "java"
    [179069503]  PID: 30944  TASK: dd4a0000  CPU: 2   COMMAND: "httpd"
    [179069502]  PID: 6      TASK: f7fa0000  CPU: 3   COMMAND: "keventd"
    [179069502]  PID: 1852   TASK: e5526000  CPU: 3   COMMAND: "opmn"
    [179069502]  PID: 32156  TASK: f608e000  CPU: 3   COMMAND: "httpd"
    [179069501]  PID: 24026  TASK: e8b80000  CPU: 0   COMMAND: "java"
    [179069501]  PID: 30481  TASK: df774000  CPU: 0   COMMAND: "httpd"
    [179069500]  PID: 12     TASK: d703c000  CPU: 2   COMMAND: "kscand"
    [179069500]  PID: 1894   TASK: e72be000  CPU: 3   COMMAND: "java"
    [179069500]  PID: 1896   TASK: e71ca000  CPU: 2   COMMAND: "java"
    [179069500]  PID: 2314   TASK: de6b8000  CPU: 1   COMMAND: "java"
  2.    .............. 중략 ................
  3. [179069480]  PID: 1799   TASK: f698a000  CPU: 3   COMMAND: "bash"
    [179069478]  PID: 1726   TASK: f6af2000  CPU: 3   COMMAND: "ovcd"
    [179069468]  PID: 1723   TASK: f6bea000  CPU: 0   COMMAND: "ovcd"
    [179069464]  PID: 24017  TASK: ec11c000  CPU: 3   COMMAND: "java"
    [179069460]  PID: 11     TASK: d703e000  CPU: 2   COMMAND: "kswapd"
    [179069443]  PID: 2043   TASK: ebad0000  CPU: 0   COMMAND: "java"
    [179069442]  PID: 1345   TASK: f6ed8000  CPU: 2   COMMAND: "vmmemctl"
    [179069436]  PID: 1932   TASK: ebf20000  CPU: 3   COMMAND: "java"
    [179069434]  PID: 2426   TASK: eac56000  CPU: 2   COMMAND: "java"
    [179069433]  PID: 24030  TASK: dc280000  CPU: 2   COMMAND: "java"
  4.     .............. 중략 ................
  5. [178831011]  PID: 30867  TASK: efcc2000  CPU: 3   COMMAND: "java"
    [178831002]  PID: 31762  TASK: e6964000  CPU: 3   COMMAND: "java"
    [178830993]  PID: 0      TASK: d8ad4000  CPU: 2   COMMAND: "swapper"
    [178830986]  PID: 32013  TASK: dfe80000  CPU: 2   COMMAND: "java"
    [178830972]  PID: 0      TASK: c03f8000  CPU: 0   COMMAND: "swapper"
    [178830969]  PID: 0      TASK: d8ad6000  CPU: 1   COMMAND: "swapper"
    [178830912]  PID: 30585  TASK: eacd8000  CPU: 0   COMMAND: "java"
    [178830907]  PID: 30586  TASK: dc32c000  CPU: 0   COMMAND: "java"
    [178830905]  PID: 20559  TASK: e5dee000  CPU: 0   COMMAND: "java"
  6.     .............. 중략 ................
  7. [179067620]  PID: 31240  TASK: ef326000  CPU: 3   COMMAND: "httpd"
    [179067560]  PID: 31210  TASK: f001e000  CPU: 0   COMMAND: "httpd"
    [179067550]  PID: 31205  TASK: d76a6000  CPU: 0   COMMAND: "httpd"
    [179067533]  PID: 31192  TASK: d76e0000  CPU: 3   COMMAND: "httpd"
    [179067533]  PID: 31194  TASK: d76bc000  CPU: 3   COMMAND: "httpd"
    [179067533]  PID: 31208  TASK: d76a0000  CPU: 1   COMMAND: "httpd"
    [179067519]  PID: 31189  TASK: d76e6000  CPU: 2   COMMAND: "httpd"
    [179067517]  PID: 31184  TASK: d76ee000  CPU: 0   COMMAND: "httpd"
    [179067505]  PID: 31186  TASK: ef16a000  CPU: 3   COMMAND: "httpd"
    [179067493]  PID: 31174  TASK: d76fc000  CPU: 2   COMMAND: "httpd"
    [179067493]  PID: 31177  TASK: d76f6000  CPU: 2   COMMAND: "httpd"
    [179067492]  PID: 31181  TASK: d87f6000  CPU: 0   COMMAND: "httpd"
    [179067467]  PID: 31171  TASK: ef2b2000  CPU: 3   COMMAND: "httpd"
    [179067461]  PID: 31168  TASK: ef2b8000  CPU: 2   COMMAND: "httpd"
    [179067455]  PID: 31164  TASK: ef2be000  CPU: 0   COMMAND: "httpd"
    [179067449]  PID: 31161  TASK: ef464000  CPU: 1   COMMAND: "httpd"
    [179067442]  PID: 31156  TASK: ef46e000  CPU: 3   COMMAND: "httpd"

 

뭐 TASK 가 1600개 넘어가니 짜증이 난다. 대략 kscand 와 kswapd 가 보인다.

음... 이건 뭐 메모리부족인가? 하여 결국 bt 를 찍어보기로 한다. 여기서는 crond 에 걸려 그것만 나오기때문에,

foreach bt 를 사용하여 전체를 잘 살펴봐야 한다. ( 눈빠진다..하지만 걱정마라 금방 원인이 추정되어 나온다. )

 

  1. foreach kernel bt
    PID: 0      TASK: c03f8000  CPU: 0   COMMAND: "swapper"
     #0 [c03f9f90] schedule at c0124280
     #1 [c03f9fd4] cpu_idle at c01091e9

    PID: 0      TASK: d8ad6000  CPU: 1   COMMAND: "swapper"
     #0 [d8ad7f6c] schedule at c0124280
     #1 [d8ad7fb0] cpu_idle at c01091e9

    PID: 0      TASK: d8ad4000  CPU: 2   COMMAND: "swapper"
     #0 [d8ad5f6c] schedule at c0124280
     #1 [d8ad5fb0] cpu_idle at c01091e9

    PID: 0      TASK: d7036000  CPU: 3   COMMAND: "swapper"
  2. ........... 중략 .............

 

커널  프로세스 위주로 Backtrace 해봤다. swapper 가 동작하는것 외에 특별한 스택을 볼순 없었다.

다시 이제 user 영역을 찍어보자

 

  1. crash> foreach user bt
  2. .......... 중략 .............
    PID: 1210   TASK: f7200000  CPU: 1   COMMAND: "python"
     #0 [f7201ea0] schedule at c0124280 
     #1 [f7201ee4] schedule_timeout at c01356f0
     #2 [f7201f1c] do_select at c017aab6
     #3 [f7201f60] sys_select at c017af59
     #4 [f7201fc0] system_call at c02b0068
        EAX: 0000008e  EBX: 00000000  ECX: 00000000  EDX: 00000000
        DS:  002b      ESI: 00000000  ES:  002b      EDI: bf7e7720
        SS:  002b      ESP: bf7e76ec  EBP: bf7e7748 
        CS:  0023      EIP: 00be2067  ERR: 0000008e  EFLAGS: 00000246
  3. .......... 중략 .............
  4. PID: 30481  TASK: df774000  CPU: 0   COMMAND: "httpd"
     #0 [df775c18] schedule at c0124280
     #1 [df775c5c] schedule_timeout at c01356f0
     #2 [df775c94] wait_on_page_timeout at c0149545
     #3 [df775cf0] rebalance_laundry_zone at c0156db5
     #4 [df775d24] __alloc_pages at c015a119
     #5 [df775d6c] __get_free_pages at c015a267
     #6 [df775d70] kmem_cache_grow at c0152cc4
     #7 [df775d98] __kmem_cache_alloc at c0153b2a
     #8 [df775db8] alloc_skb at c022ad2f
     #9 [df775dd0] tcp_sendmsg at c0257760
    #10 [df775e40] inet_sendmsg at c027a15f
    #11 [df775e54] sock_sendmsg at c0226f05
    #12 [df775e98] sys_sendto at c02281ae
    #13 [df775f64] sys_send at c0228202
    #14 [df775f80] sys_socketcall at c0228ac2
    #15 [df775fc0] system_call at c02b0068
        EAX: 00000066  EBX: 00000009  ECX: bfffe910  EDX: b6038fdc
        DS:  002b      ESI: 00000000  ES:  002b      EDI: 00000000
        SS:  002b      ESP: bfffe908  EBP: bfffe938 
        CS:  0023      EIP: b75b7fce  ERR: 00000066  EFLAGS: 00200293
  5. .......... 중략 .............

 

자 전반적으로다가 의심스러운 스택들이 튀어나와있다.

 

  1.  #0 [df775c18] schedule at c0124280
     #1 [df775c5c] schedule_timeout at c01356f0
     #2 [df775c94] wait_on_page_timeout at c0149545
     #3 [df775cf0] rebalance_laundry_zone at c0156db5
     #4 [df775d24] __alloc_pages at c015a119
     #5 [df775d6c] __get_free_pages at c015a267
     #6 [df775d70] kmem_cache_grow at c0152cc4
     #7 [df775d98] __kmem_cache_alloc at c0153b2a

 

바로 위의 것들인데, 왜 의심스러운거냐 하면, 바로 메모리 관련하여 작업을 하고 있다는 것이기 때문이다.

전반적으로 많은 프로세스들에 rebalance_laundry_zone 과 kmem_cache_grow 등이 보이는데

이것들이 하는것은 메모리 사용량이 많아, 할당 가능한 메모리가 존재 하는지 안하는지 확인하는 것들이다.

결과적으로 전반적인 메모리 부족을 뜻하는 것인데, 할당 가능한 page 가 있는지 없는지 살펴보는 과정에서

wait_on_page_timeout 이 발생하여 page 를 기다리고, schedule_timeout 이 되어 프로세스가 계속

대기하게 되는 것이다.

 

이것이 장애와 어떤 연관이 있냐 하면, RHEL 3 의 경우 2.4 커널을 사용하며, 2.4 커널에서는

기본적으로 budy 알고리즘 만을 사용하도록 되어 있다. ( 알고리즘 설명은 따로 LDP 에서 뒤져봐라 )

이것은 연속된 특정 page 영역을 계속 찾고 검색하게 되있고. 이것은 곧 오버헤드를 발생시키는 것이 된다.

즉 위 상황에서 OS ( 커널 ) 는 메모리 할당을 위해 재사용할 메모리를 검색하는데 집중하느라 외부에서는

Hang-up 상태로 의심할만한 반응이 없는 상태가 되는것이다.

 

좀 더 찾아보니 다음과 같은 것도 있었다.

  1. PID: 32154  TASK: efde0000  CPU: 2   COMMAND: "httpd"
     #0 [efde1c9c] smp_call_function_interrupt at c011cc4f
     #1 [efde1ca4] call_call_function_interrupt at c02b0ca8
        EAX: c03f4dd0  EBX: c16b348c  ECX: c16b348c  EDX: 00000000  EBP: c03acf00
        DS:  0068      ESI: 00000000  ES:  0068      EDI: 00000000
        CS:  0060      EIP: c0158f86  ERR: fffffffb  EFLAGS: 00000282
     #2 [efde1cd8] .text.lock.vmscan (via launder_page) at c0158f86
     #3 [efde1cfc] rebalance_dirty_zone at c01575f6
     #4 [efde1d24] __alloc_pages at c015a1a4
     #5 [efde1d6c] __get_free_pages at c015a267
     #6 [efde1d70] kmem_cache_grow at c0152cc4
     #7 [efde1d98] __kmem_cache_alloc at c0153b2a
     #8 [efde1db8] alloc_skb at c022ad2f
     #9 [efde1dd0] tcp_sendmsg at c0257760
    #10 [efde1e40] inet_sendmsg at c027a15f
    #11 [efde1e54] sock_sendmsg at c0226f05
    #12 [efde1e98] sys_sendto at c02281ae
    #13 [efde1f64] sys_send at c0228202
    #14 [efde1f80] sys_socketcall at c0228ac2
    #15 [efde1fc0] system_call at c02b0068
        EAX: 00000066  EBX: 00000009  ECX: bfffe910  EDX: b6038fdc
        DS:  002b      ESI: 00000000  ES:  002b      EDI: 00000000
        SS:  002b      ESP: bfffe908  EBP: bfffe938 
        CS:  0023      EIP: b75b7fce  ERR: 00000066  EFLAGS: 00200293

 

결국 위 httpd 프로세스는 메모리 확보를 하는 과정에 빠져있었다는 것인데,

아니 왜 이렇게 메모리를 많이써? 왜 할당을 안해? 스왑은 뭐한데? 라고 할수 있으므로 다시 좀 더 보자.

 

다음은 kmem 을 통해 메모리 정보들을 확인 해 보는 것이다. -f 는 프리 page 갯수를 나타낸다.

  1. crash> kmem -f
    NODE
      0
    ZONE  NAME        SIZE    FREE  MEM_MAP   START_PADDR  START_MAPNR
      0   DMA         4096    2776  c100002c       0            0    
    AREA    SIZE  FREE_AREA_STRUCT  BLOCKS  PAGES
      0       4k      c03acdd8           2      2
      1       8k      c03acde4           1      2
      2      16k      c03acdf0           1      4
      3      32k      c03acdfc           0      0
      4      64k      c03ace08           1     16
      5     128k      c03ace14           0      0
      6     256k      c03ace20           1     64
      7     512k      c03ace2c           1    128
      8    1024k      c03ace38           0      0
      9    2048k      c03ace44           1    512
     10    4096k      c03ace50           2   2048

    ZONE  NAME        SIZE    FREE  MEM_MAP   START_PADDR  START_MAPNR
      1   Normal    225280   10372  c103c02c    1000000        4096  
    AREA    SIZE  FREE_AREA_STRUCT  BLOCKS  PAGES
      0       4k      c03ae0d8       10372  10372
      1       8k      c03ae0e4           0      0
      2      16k      c03ae0f0           0      0
      3      32k      c03ae0fc           0      0
      4      64k      c03ae108           0      0
      5     128k      c03ae114           0      0
      6     256k      c03ae120           0      0
      7     512k      c03ae12c           0      0
      8    1024k      c03ae138           0      0
      9    2048k      c03ae144           0      0
     10    4096k      c03ae150           0      0

    ZONE  NAME        SIZE    FREE  MEM_MAP   START_PADDR  START_MAPNR
      2   HighMem   4227072  841406  c1d2002c    38000000      229376 
    AREA    SIZE  FREE_AREA_STRUCT  BLOCKS  PAGES
      0       4k      c03af3d8           0      0
      1       8k      c03af3e4           1      2
      2      16k      c03af3f0           1      4
      3      32k      c03af3fc           1      8
      4      64k      c03af408           1     16
      5     128k      c03af414           1     32
      6     256k      c03af420           0      0
      7     512k      c03af42c           1    128
      8    1024k      c03af438           0      0
      9    2048k      c03af444           1    512
     10    4096k      c03af450         821 840704

    nr_free_pages: 854554  (verified)

 

신기한가? 멀었다. 잘 보면 DMA 영역으로 16메가가 할당되어 있고,

Normal 즉 lowmem table ( kernel 영역 ) 에 4k 짜리 페이지 외에 다른 크기의 메모리 block 들은

하나도 존재하지 않은 상태다. 즉 다 할당해 주고 더이상 연속된 8k 이상 페이지를 갖고 있지 않다는 얘기이다.

  1. crash> kmem -i
                  PAGES        TOTAL      PERCENTAGE
     TOTAL MEM  4102986      15.7 GB         ----
          FREE   854554       3.3 GB   20% of TOTAL MEM
          USED  3248432      12.4 GB   79% of TOTAL MEM
        SHARED   789017         3 GB   19% of TOTAL MEM
       BUFFERS    22633      88.4 MB    0% of TOTAL MEM
        CACHED  2437875       9.3 GB   59% of TOTAL MEM
          SLAB    93293     364.4 MB    2% of TOTAL MEM

    TOTAL HIGH  3964912      15.1 GB   96% of TOTAL MEM
     FREE HIGH   841406       3.2 GB   21% of TOTAL HIGH
     TOTAL LOW   138074     539.4 MB    3% of TOTAL MEM
      FREE LOW    13148      51.4 MB    9% of TOTAL LOW

    kmem: swap_info[0].swap_map at f8878000 is unaccessible

 

자 SLAB 영역이 무려 364메가 이상이고, LOW 영역이 고작 539 정도에 51메가밖에 남아있지 않는다.

결과적으로 LOW 멤에서 메모리 관련 작업은 불가능한 상태라는 것이다.

 

자 그래, 그럼 SLAB 갯수가 얼마나 되는지 확인해 보자.

  1. crash> kmem -s> slab.txt

    CACHE    NAME                 OBJSIZE  ALLOCATED     TOTAL  SLABS  SSIZE
    c03ab900 kmem_cache               244         74        96      6     4k
    f7592914 nfs_write_data           384          0         0      0     4k
    f7592a08 nfs_read_data            384          0         0      0     4k
    f7592afc nfs_page                 128          0         0      0     4k
    f7592bf0 ip_fib_hash               32         10       336      3     4k
    d8982ce4 ext3_xattr                44          0         0      0     4k
    f7592ce4 journal_head              48        196     22869    297     4k
    f7592dd8 revoke_table              12         11       500      2     4k
    f7592ecc revoke_record             32          0      1792     16     4k
    d8982dd8 clip_arp_cache           256          0         0      0     4k
    d8982ecc ip_mrt_cache             128          0         0      0     4k
    d8a0b080 tcp_tw_bucket            128          0     25380    846     4k
    d8a0b174 tcp_bind_bucket           32        627      2800     25     4k
    d8a0b268 tcp_open_request         128        303      3150    105     4k
    d8a0b35c inet_peer_cache           64          4       116      2     4k
    d8a0b450 secpath_cache            128          0         0      0     4k
    d8a0b544 xfrm_dst_cache           256          0         0      0     4k
    d8a0b638 ip_dst_cache             256        252      4350    290     4k
    d8a0b72c arp_cache                256          6       435     29     4k
    d8a0b820 flow_cache               128          0         0      0     4k
    d8a0b914 blkdev_requests          128       3072      4140    138     4k
    d8a0ba08 kioctx                   128          0         0      0     4k
    d8a0bafc kiocb                    128          0         0      0     4k
    d8a0bbf0 dnotify_cache             20          0         0      0     4k
    d8a0bce4 file_lock_cache           96         17      2920     73     4k

  2. ........ 중략 ..........

 

뭐, 간단히 SLAB 이란 원래 Solaris 계열에서 나온 정책인데, 쉽게 메모리 할당 후 혹시 쓰일지 모른다는 생각에

바로 폐기하지 않고, 남겨둔다는 것이다.

결국 커널은 동일한 크기의 연속된 메모리 (page) 를 요청하는 경향이 있기 때문에,

잦은 호출을 줄이기 위해 캐쉬 영역에 SLAB 을 둔다는 것이다.

결국 CACHE 에 SLAB 이 많이 존재 하게 되면 ( budy 를 자주 호출하게 되면 ) 직접적인 메모리 엑세스 타임에는

매우 큰 손실을 주게 되는 것이다. ( 캐쉬안에 존제된 연속된 채워진 혹은 비어있는 동일 크기의 페이지이므로 )

 

다시 한번 SLAB 부분 확인해 보고 결론을 들어가 보자.

  1. [root@localhost root]# grep -E "sock|tcp" slab.txt
    d8a0b080 tcp_tw_bucket            128          0     25380    846     4k
    d8a0b174 tcp_bind_bucket           32        627      2800     25     4k
    d8a0b268 tcp_open_request         128        303      3150    105     4k
    d8acfce4 sock                    1408       1805      2402   1201     4k

 

결과적으로 위 장애는 lowmem 의 부족으로 lowmem 영역 확보를 위해 캐쉬되있는 메모리를 검색하고,

반환하며, 또한 새로 할당하기 위해 일련의 과정들을 격는 중이였다는 것이며,

( 그러나 실제 캐쉬에서 사용가능한 부분은 없어 Lowmem 확보에 어려움이 있었던 것으로 판단. )

httpd 및 java 프로세스는 TCP 통신을 하기 때문에 Lowmem 을 많이 사용하였을 것이라는 결론.

특히 .text.lock.vmscan 은 HTTP 에서만 발생하였다.

Hugemem 으로 간다면 모르겠지만 그럴 수 있는 상황이 아니므로 ( VMware not support Hugemem )

즉 위의 문제는 장애가 아닌 튜닝이나 부하분산에 촛점을 맞춰야 한다는 것이다.

 

아래는 R 사의 답변 요약이다.

실제 Cached  메모리 자체 및 사용량은 12G 에 불과하므로 메모리를 줄이는것이 오히려 메모리 확보과정에

오버헤드를 줄일 수 있다는 내용인데. 큰 의미는 없다고 보여 진다.... ㅡ.,ㅡ::

@ 결론
- 시스템에서 실행 중인 프로세스가 많으며 대부분의 프로세스들이 비슷한 동작 즉,

지속적으로 lowmem을 요구하고 있습니다.

(CPU 4개 중 3개에서 httpd 프로세스가 TCP 통신을 위해 lowmem에서 buffer를 요청하고 있었습니다.)
- 커널에서는 분주히 lowmem 메모리 확보를 위한 작업을 수행하고 있습니다. (lowmem 영역은 swap 될 수 없습니다.)
- 이 때문에 시스템의 반응 속도가 현저히 줄어드는 것(Hang 상태이거나 Crash된 것이 아님)이며,

다시 말하면 시스템이 수용할 수 있는 한계보다 높은 부하로 인해 동작이 원활히 이루어지지 않는 것 입니다.,
- 이는 정상적인 반응이고 Red Hat Enterprise Linux 또는 커널의 문제가 아닙니다.
특별한 이슈가 없는 한, 이 이슈는 시스템 문제가 아닌 성능 튜닝이나 부하 관리 차원에서

다뤄져야 할 것으로 판단됩니다.

@ 권고 사항
- 현재 조건에서는 시스템 로드를 줄여주는 방법밖에는 없습니다.
- 현재 시스템 메모리가 17GB으로 보여집니다. 16GB 이하로 줄이시기 바랍니다.
- 현재 상황에서는 16GB는 다 사용하지도 못하고 있으므로, 8GB 또는 12GB 정도로 줄여 lowmem에서

physical memory mapping에 사용되는 공간(mem_map[])을 줄일 수 있을 것으로 생각됩니다.

 

 

Coredump Analysis 7#

상황#

이미 예전에 한번 CPU timer interrupt 방식 문제로 이슈가 발생 되었던 시스템이다.

문제는 약 6개월만에 또다시 터졌다는건데...

 

시스템 (OS) : RedHat Enterprise Linux 4 AS update 5 ( 커널은 4.8 커널 )   

Kernel Ver.  : 2.6.9-89.ELsmp

Machine      : x86_64

Memory       : 8G

 

분석과정#

간단하게 코어 바로 열고 log 찍어보았다.

 

  1.            KERNEL: vmlinux-2.6.9-89.ELsmp.x86_64   
              DUMPFILE: var/crash/127.0.0.1-2010-05-11-09:51/vmcore
                  CPUS: 8
                  DATE: Tue May 11 09:51:17 2010
                UPTIME: 205 days, 20:36:24
          LOAD AVERAGE: 0.22, 0.13, 0.07
                 TASKS: 342
              NODENAME: ******02
               RELEASE: 2.6.9-89.ELsmp
               VERSION: #1 SMP Mon Apr 20 10:33:05 EDT 2009
               MACHINE: x86_64  (3169 Mhz)
                MEMORY: 8 GB
                 PANIC: "Kernel panic - not syncing: nmi watchdog"
                   PID: 15652
               COMMAND: "scopeux"
                  TASK: 1006b7de7f0  [THREAD_INFO: 1000eef4000]
                   CPU: 0
                 STATE: TASK_RUNNING (NMI)

          crash >

 

로그 보자....

 

  1. crash > log

    warning: many lost ticks

          Your time source seems to be instable or some driver is hogging interupts
          rip __do_softirq+0x4d/0xd0
          Falling back to HPET
          NMI Watchdog detected LOCKUP, CPU=0, registers:
          CPU 0
          Modules linked in: snapapi26(U) i2c_dev i2c_core md5 ipv6 ide_dump scsi_dump diskdump zlib_deflate

    dm_mirror dm_mod emcpvlumd(U) emcpxcrypt(U) emcpdm(U) emcpgpx(U) emcpmpx(U) emcp(U) button

    battery ac ohci_hcd ehci_hcd tg3 e1000 bonding(U) sg ext3 jbd qla2300 aacraid qla2xxx scsi_transport_fc sd_mod scsi_mod

    Pid: 15652, comm: scopeux Tainted: P      2.6.9-89.ELsmp

          RIP: 0010:[<ffffffff80141400>] <ffffffff80141400>{do_timer+197}
          RSP: 0018:ffffffff8046dce0  EFLAGS: 00000012
          RAX: 000000000001e7fc RBX: 000000006b1833d6 RCX: 000000000001e7fc
          RDX: 0000000000000000 RSI: 00000000000f41a8 RDI: ffffffff8046ddc8
          RBP: 0000000072a55f4d R08: 0000000000000008 R09: 0000000000000000
          R10: 0000000000000000 R11: 0000000000000008 R12: 00000000d73c7987
          R13: 0000000072a55f4b R14: ffffffff8046ddc8 R15: 000000000000c3f0
          FS:  0000000000000000(0000) GS:ffffffff80504500(005b) knlGS:00000000f7d7c6c0
          CS:  0010 DS: 002b ES: 002b CR0: 0000000080050033
          CR2: 00000000f7ad8000 CR3: 0000000000101000 CR4: 00000000000006e0
          Process scopeux (pid: 15652, threadinfo 000001000eef4000, task 000001006b7de7f0)
          Stack: 00000005241efada 0000000000000000 000000000000037d ffffffff801167ee
                 ffffffff8046dd60 ffffffff801340e4 0000000000000044 00000004b1799b8e
                 000000018046ddc8 0000000000000000
          Call Trace:<IRQ> <ffffffff801167ee>{timer_interrupt+587} <ffffffff801340e4>{rebalance_tick+133}
                 <ffffffff80112ff6>{handle_IRQ_event+41} <ffffffff80113270>{do_IRQ+197}
                 <ffffffff801108c3>{ret_from_intr+0} <ffffffff8013d859>{__do_softirq+77}
                 <ffffffff8013d90d>{do_softirq+49} <ffffffff80110c85>{apic_timer_interrupt+133}
                  <EOI> <ffffffff801656ca>{s_show+515} <ffffffff801656ca>{s_show+515}
                 <ffffffff80199fae>{seq_read+445} <ffffffff8017c2ec>{vfs_read+207}
                 <ffffffff8017c548>{sys_read+69} <ffffffff801266fc>{sysenter_do_call+27}
               

          Code: 81 e1 ff 0f 00 00 48 c1 f8 0c 48 89 0d 37 0a 36 00 48 01 c6
          Kernel panic - not syncing: nmi watchdog
          ----------- [cut here ] --------- [please bite here ] ---------
          Kernel BUG at panic:77
          invalid operand: 0000 [1] SMP
          CPU 0
          Modules linked in: snapapi26(U) i2c_dev i2c_core md5 ipv6 ide_dump scsi_dump diskdump zlib_deflate

    dm_mirror dm_mod emcpvlumd(U) emcpxcrypt(U) emcpdm(U) emcpgpx(U) emcpmpx(U) emcp(U) button

    battery ac ohci_hcd ehci_hcd tg3 e1000 bonding(U) sg ext3 jbd qla2300 aacraid qla2xxx scsi_transport_fc sd_mod scsi_mod

          Pid: 15652, comm: scopeux Tainted: P      2.6.9-89.ELsmp
          RIP: 0010:[<ffffffff80138992>] <ffffffff80138992>{panic+211}
          RSP: 0018:ffffffff80470ca8  EFLAGS: 00010082
          RAX: 000000000000002c RBX: ffffffff803287ce RCX: 0000000000000046
          RDX: 00000000000121c3 RSI: 0000000000000046 RDI: ffffffff803f6700
          RBP: ffffffff80470e58 R08: 0000000000000002 R09: ffffffff803287ce
          R10: 0000000000000000 R11: 0000ffff80411b20 R12: 0000000000000000
          R13: 0000000072a55f4b R14: ffffffff8046ddc8 R15: 000000000000c3f0
          FS:  0000000000000000(0000) GS:ffffffff80504500(005b) knlGS:00000000f7d7c6c0
          CS:  0010 DS: 002b ES: 002b CR0: 0000000080050033
          CR2: 00000000f7ad8000 CR3: 0000000000101000 CR4: 00000000000006e0
          Process scopeux (pid: 15652, threadinfo 000001000eef4000, task 000001006b7de7f0)
          Stack: 0000003000000008 ffffffff80470d88 ffffffff80470cc8 0000000000000013
                 0000000000000000 0000000000000046 0000000000012197 0000000000000046
                 0000000000000002 ffffffff8032af27
          Call Trace:<ffffffff801118f4>{show_stack+241} <ffffffff80111a1e>{show_registers+277}
          <ffffffff80111d25>{die_nmi+130} <ffffffff8011de1b>{nmi_watchdog_tick+276}
          <ffffffff801125f6>{default_do_nmi+116} <ffffffff8011df05>{do_nmi+115}
          <ffffffff80111203>{paranoid_exit+0} <ffffffff80141400>{do_timer+197}
           <EOE> <IRQ> <ffffffff801167ee>{timer_interrupt+587}
                 <ffffffff801340e4>{rebalance_tick+133} <ffffffff80112ff6>{handle_IRQ_event+41}
                 <ffffffff80113270>{do_IRQ+197} <ffffffff801108c3>{ret_from_intr+0}
                 <ffffffff8013d859>{__do_softirq+77} <ffffffff8013d90d>{do_softirq+49}
                 <ffffffff80110c85>{apic_timer_interrupt+133}  <EOI> <ffffffff801656ca>{s_show+515}
                 <ffffffff801656ca>{s_show+515} <ffffffff80199fae>{seq_read+445}
                 <ffffffff8017c2ec>{vfs_read+207} <ffffffff8017c548>{sys_read+69}
                 <ffffffff801266fc>{sysenter_do_call+27}

          Code: 0f 0b 4e 8d 32 80 ff ff ff ff 4d 00 31 ff e8 2f bb fe ff 83
          RIP <ffffffff80138992>{panic+211} RSP <ffffffff80470ca8>

     

 

 

이번 분석은 여기서 끝난다. 간단하게 로그에 나오듯이 TSC 를 기본 인터럽트 방식으로 사용하고 있는 Linux 에서
정상적으로 CPU time 을 인터럽트 하지 못했을 경우에는 HPET 라는 방식으로 자동 전환하여
CPU  time 을 가져오려고 한다.

그런데 여기선 HPET 방식으로의 전환이 불가능 했고, 그로 인해 30초 이상의 CPU time 을 얻어오지 못함으로,
NMI_Watchdog 에서 커널 패닉으로 감지 한 것이다.

 

@결론
일전에 Redhat 에서 이 이슈가 있었을때 grub.conf 에 clocksource=hpet 을 커맨드라인에 넣어주어,
시작시부터 HPET 타이머를 이용하도록 하라는 권고가 있었고 적용 된 줄 알았었다...
하지만 clocksource 는 RHEL5 에서 적용 가능한 커맨드라인이였고, 보시다시피 이 시스템은 RHEL4
결국 고객에게 죄송하다는 말과 함께 clock=hpet 으로 수정..적용은 아직 안되고 있다 (리부팅해야하므로)
왜 RHEL5 에 적용되는걸 알려줘서 난감하게 만든겁니까~? ㅠㅠ

 

Coredump Analysis 8#

 

상황#

오랜만인데...SCTP 프로토콜 관련 문제로 이미 예전부터 RedHat 과 함께 공조하여 패치를 만들어오던

상황이다...패치적용된 테스트 커널을 만들어 레드햇에서 고객에 전달해 준 뒤, 사용 후 문제가 생기는지에대한

피드백을 요청하는등 작업이 이루어 졌었다가, 이번에 다시 커널패닉이 발생한 부분이다.

 

시스템 (OS) : RedHat Enterprise Linux 5

Kernel Ver.  : 2.6.18-194.3.1.el5.it801213

Machine      : x86_64

Memory       : 12G

 

분석과정#

간단하게 코어 바로 열고 log 찍어보았다.

 

  1. root@~]# crash /usr/lib/debug/lib/modules/2.6.18-194.3.1.el5/vmlinux vmcore20110128

  2. .............생략................

          KERNEL: /usr/lib/debug/lib/modules/2.6.18-194.3.1.el5/vmlinux
        DUMPFILE: vmcore20110128
            CPUS: 16
            DATE: Fri Jan 28 10:39:19 2011
          UPTIME: 35 days, 21:31:59
    LOAD AVERAGE: 0.00, 0.09, 0.18
           TASKS: 368
        NODENAME: C**F2
         RELEASE: 2.6.18-194.3.1.el5.it801213
         VERSION: #1 SMP Mon May 31 04:01:01 EDT 2010
         MACHINE: x86_64  (2666 Mhz)
          MEMORY: 11.8 GB
           PANIC: "Oops: 0000 [1] SMP " (check log for details)
             PID: 21246
         COMMAND: "MUXD"
            TASK: ffff81016fb5b100  [THREAD_INFO: ffff810123b10000]
             CPU: 2
           STATE: TASK_RUNNING (PANIC)
          crash >

 

Backtrace 부터 찍어보자..

 

  1. crash> bt
    PID: 21246  TASK: ffff81016fb5b100  CPU: 2   COMMAND: "MUXD"
     #0 [ffff810123b11a00] crash_kexec at ffffffff800ada85
     #1 [ffff810123b11ac0] __die at ffffffff80065157
     #2 [ffff810123b11b00] do_page_fault at ffffffff80066dd7
     #3 [ffff810123b11bf0] error_exit at ffffffff8005dde9
        [exception RIP: list_del+8]
        RIP: ffffffff80153f77  RSP: ffff810123b11ca8  RFLAGS: 00010246
        RAX: 0000000000200200  RBX: ffff81028b3220d0  RCX: ffff810123b11c88
        RDX: ffff8100a4597380  RSI: ffff81031f03d222  RDI: ffff81028b3220d0
        RBP: ffff8101fd7fe140   R8: ffff81019c550680   R9: ffff81028b322000
        R10: ffff8103077f4880  R11: 00000000000000c8  R12: ffff8101fd7fe140
        R13: ffff8100a4597380  R14: 0000000000000000  R15: ffff8100a4597380
        ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
     #4 [ffff810123b11cb0] sctp_association_free at ffffffff885133cd
     #5 [ffff810123b11cd0] sctp_do_sm at ffffffff885106ae
     #6 [ffff810123b11e30] sctp_primitive_ABORT at ffffffff8851f0e3
     #7 [ffff810123b11e50] sctp_close at ffffffff8851de4c
     #8 [ffff810123b11eb0] inet_release at ffffffff80263694
     #9 [ffff810123b11ed0] sock_release at ffffffff800553a1
    #10 [ffff810123b11ef0] sock_close at ffffffff80055592
    #11 [ffff810123b11f00] __fput at ffffffff80012a96
    #12 [ffff810123b11f40] filp_close at ffffffff80023b84
    #13 [ffff810123b11f60] sys_close at ffffffff8001dfa6
    #14 [ffff810123b11f80] tracesys at ffffffff8005d28d (via system_call)
        RIP: 00000039a040d637  RSP: 00007fff077d4e80  RFLAGS: 00000206
        RAX: ffffffffffffffda  RBX: ffffffff8005d28d  RCX: ffffffffffffffff
        RDX: 0000000000000002  RSI: 0000000000000000  RDI: 0000000000000004
        RBP: 0000000000000000   R8: 00002ac6ddf1ceb0   R9: 000000399f919840
        R10: 203a4e4e4f435349  R11: 0000000000000206  R12: 00007fff077d4ec0
        R13: 00000000013e2360  R14: ffffffff8001dfa6  R15: ffff8100245eb680
        ORIG_RAX: 0000000000000003  CS: 0033  SS: 002b
    crash>

 

이번엔 로그 확인은 안할것이다. 어차피 모듈관련 로그만 떨어져있다...백트레이스와 비슷하게 나온다.

즉 Tainted 된 모듈은 없으며, 위에 BT 에서 보듯 SCTP 프로토콜의 Closing 후 Socket Descriptor 나 모듈을 해제할때

linked list 에서 엔트리제거과정에 오류가 발생하여 커널패닉이 떨어진 것 같다.

 

가장 마지막 스택들에 들어가있는 시스템콜을 보자면, sctp_association_free 인데, 이 이후에 list_del 에서

RIP 가 떨어져 있다... 즉 sctp_association_free 함수 호출 후, list 정리 함수에서 RIP 를 남기고 error_exit 를 호출한 것이므로,

list_del 에서 떨어진 패닉으로 확정 할 수 있겠다...

 

일단 RedHat bugzilla 에서 sctp 를 통한 검색을 해보았을땐 특별한 버그리포트를 찾을 수 없었다. ( 치사하게시리 ㅠㅠ )

 

분석 자체는 좀 많이 했는데 ( 대략 4시간가량 ) 실제 문서에서는 귀찮아서 간단하게 정리하겠다.

list_del+8 위치의 메모리번지에서 뻗은것이기 때문에, disassemble 을통해 살짝 살펴보자.

그래도 일단 list_del 이전의 호출되는 함수인 sctp_association_free 부분도 디스어셈코드를 보도록 하자 :)

 

  1. crash> dis sctp_association_free
    0xffffffff885133ad <sctp_association_free>:     push   %r12
    0xffffffff885133af <sctp_association_free+2>:   push   %rbp
    0xffffffff885133b0 <sctp_association_free+3>:   push   %rbx
    0xffffffff885133b1 <sctp_association_free+4>:   cmpb   $0x0,0x169d(%rdi)
    0xffffffff885133b8 <sctp_association_free+11>:  mov    %rdi,%rbx
    0xffffffff885133bb <sctp_association_free+14>:  mov    0x20(%rdi),%rbp
    0xffffffff885133bf <sctp_association_free+18>:  jne    0xffffffff885133e4
    0xffffffff885133c1 <sctp_association_free+20>:  lea    0xd0(%rdi),%rdi
    0xffffffff885133c8 <sctp_association_free+27>:  callq  0xffffffff80153f6f <list_del>
    0xffffffff885133cd <sctp_association_free+32>:  cmpl   $0x2,0x2d8(%rbp)
    0xffffffff885133d4 <sctp_association_free+39>:  jne    0xffffffff885133e4
    0xffffffff885133d6 <sctp_association_free+41>:  mov    0x2(%rbp),%al
    0xffffffff885133d9 <sctp_association_free+44>:  cmp    $0xa,%al
    0xffffffff885133db <sctp_association_free+46>:  jne    0xffffffff885133e4
    0xffffffff885133dd <sctp_association_free+48>:  decw   0x14c(%rbp)
    0xffffffff885133e4 <sctp_association_free+55>:  lea    0x15c0(%rbx),%rdi
    0xffffffff885133eb <sctp_association_free+62>:  movb   $0x1,0x1c(%rbx)
    0xffffffff885133ef <sctp_association_free+66>:  lea    0x1358(%rbx),%rbp
    0xffffffff885133f6 <sctp_association_free+73>:  xor    %r12d,%r12d
    0xffffffff885133f9 <sctp_association_free+76>:  callq  0xffffffff8851861f <sctp_outq_free>
    0xffffffff885133fe <sctp_association_free+81>:  lea    0x1628(%rbx),%rdi
    0xffffffff88513405 <sctp_association_free+88>:  callq  0xffffffff8851961f <sctp_ulpq_free>
    0xffffffff8851340a <sctp_association_free+93>:  lea    0x28(%rbx),%rdi
    0xffffffff8851340e <sctp_association_free+97>:  callq  0xffffffff88517491 <sctp_inq_free>
    0xffffffff88513413 <sctp_association_free+102>: mov    0x15b8(%rbx),%rdi
    0xffffffff8851341a <sctp_association_free+109>: callq  0xffffffff88520900 <sctp_ssnmap_free>
    0xffffffff8851341f <sctp_association_free+114>: lea    0xa8(%rbx),%rdi
    0xffffffff88513426 <sctp_association_free+121>: callq  0xffffffff88519d06 <sctp_bind_addr_free>
    0xffffffff8851342b <sctp_association_free+126>: cmpq   $0x0,0x1358(%rbx,%r12,1)
    0xffffffff88513434 <sctp_association_free+135>: je     0xffffffff8851344a
    0xffffffff88513436 <sctp_association_free+137>: mov    %rbp,%rdi
    0xffffffff88513439 <sctp_association_free+140>: callq  0xffffffff8003228e <del_timer>
    0xffffffff8851343e <sctp_association_free+145>: test   %eax,%eax
    0xffffffff88513440 <sctp_association_free+147>: je     0xffffffff8851344a
    0xffffffff88513442 <sctp_association_free+149>: mov    %rbx,%rdi
    0xffffffff88513445 <sctp_association_free+152>: callq  0xffffffff8851255a <sctp_association_put>
    0xffffffff8851344a <sctp_association_free+157>: add    $0x30,%r12
    0xffffffff8851344e <sctp_association_free+161>: add    $0x30,%rbp
    0xffffffff88513452 <sctp_association_free+165>: cmp    $0x1e0,%r12
    0xffffffff88513459 <sctp_association_free+172>: jne    0xffffffff8851342b
    0xffffffff8851345b <sctp_association_free+174>: mov    0x1288(%rbx),%rdi
    0xffffffff88513462 <sctp_association_free+181>: callq  0xffffffff8000b3de <kfree>
    0xffffffff88513467 <sctp_association_free+186>: mov    0x148(%rbx),%rbp
    0xffffffff8851346e <sctp_association_free+193>: mov    0x0(%rbp),%r12
    0xffffffff88513472 <sctp_association_free+197>: jmp    0xffffffff8851348b
    0xffffffff88513474 <sctp_association_free+199>: mov    %rbp,%rdi
    0xffffffff88513477 <sctp_association_free+202>: callq  0xffffffff80153f6f <list_del>
    0xffffffff8851347c <sctp_association_free+207>: mov    %rbp,%rdi
    0xffffffff8851347f <sctp_association_free+210>: mov    %r12,%rbp
    0xffffffff88513482 <sctp_association_free+213>: callq  0xffffffff88513afe <sctp_transport_free>
    0xffffffff88513487 <sctp_association_free+218>: mov    (%r12),%r12
    0xffffffff8851348b <sctp_association_free+222>: lea    0x148(%rbx),%rax
    0xffffffff88513492 <sctp_association_free+229>: cmp    %rax,%rbp
    0xffffffff88513495 <sctp_association_free+232>: jne    0xffffffff88513474
    0xffffffff88513497 <sctp_association_free+234>: mov    0x1680(%rbx),%rdi
    0xffffffff8851349e <sctp_association_free+241>: movw   $0x0,0x158(%rbx)
    0xffffffff885134a7 <sctp_association_free+250>: test   %rdi,%rdi
    0xffffffff885134aa <sctp_association_free+253>: je     0xffffffff885134b1
    0xffffffff885134ac <sctp_association_free+255>: callq  0xffffffff88514798 <sctp_chunk_free>
    0xffffffff885134b1 <sctp_association_free+260>: mov    0x1678(%rbx),%rdi
    0xffffffff885134b8 <sctp_association_free+267>: test   %rdi,%rdi
    0xffffffff885134bb <sctp_association_free+270>: je     0xffffffff885134c2
    0xffffffff885134bd <sctp_association_free+272>: callq  0xffffffff88514798 <sctp_chunk_free>
    0xffffffff885134c2 <sctp_association_free+277>: mov    %rbx,%rdi
    0xffffffff885134c5 <sctp_association_free+280>: pop    %rbx
    0xffffffff885134c6 <sctp_association_free+281>: pop    %rbp
    0xffffffff885134c7 <sctp_association_free+282>: pop    %r12
    0xffffffff885134c9 <sctp_association_free+284>: jmpq   0xffffffff8851255a
    crash>

 

특별히 배드스테이터스라고 할만한 코드는 보이지 않는데... 좀 이상한게 list_del 부분이 두번이나 호출된다는 점이다...

이건 sctp 모듈의 코드를 봐야 할것 같으나, 이 문서에서 그부분은 숙제로 남겨놓겠다.

chunk_free 도 두번이나 하는걸 보면 어쩌면 Double Chunk Free 버그일수도 있겠는데.......... :P

( 사실 소스를 난 봤는데 sctp 쪽을 잘 몰라서 모르겠더라 )

 

자..그럼 이제 list_del 의 디스어셈코드를 확인 해 보자.

 

  1. crash> dis ffffffff80153f77 10
    0xffffffff80153f77 <list_del+8>:        mov    (%rax),%rdx
    0xffffffff80153f7a <list_del+11>:       cmp    %rdi,%rdx
    0xffffffff80153f7d <list_del+14>:       je     0xffffffff80153f9a <list_del+43>
    0xffffffff80153f7f <list_del+16>:       mov    %rdi,%rsi
    0xffffffff80153f82 <list_del+19>:       xor    %eax,%eax
    0xffffffff80153f84 <list_del+21>:       mov    $0xffffffff802bbae9,%rdi
    0xffffffff80153f8b <list_del+28>:       callq  0xffffffff800924f7 <printk>
    0xffffffff80153f90 <list_del+33>:       ud2a   
    0xffffffff80153f9a <list_del+43>:       mov    (%rbx),%rax
    0xffffffff80153f9d <list_del+46>:       mov    0x8(%rax),%rdx
  2. 0xffffffff80153fa1 <list_del+50>:       cmp    %rbx,%rdx
    0xffffffff80153fa4 <list_del+53>:       je     0xffffffff80153fc1 <list_del+82>
    0xffffffff80153fa6 <list_del+55>:       mov    %rbx,%rsi
    0xffffffff80153fa9 <list_del+58>:       mov    $0xffffffff802bbb37,%rdi
    0xffffffff80153fb0 <list_del+65>:       xor    %eax,%eax
    0xffffffff80153fb2 <list_del+67>:       callq  0xffffffff800924f7 <printk>
    0xffffffff80153fb7 <list_del+72>:       ud2a   
    0xffffffff80153fc1 <list_del+82>:       mov    (%rbx),%rdx
    0xffffffff80153fc4 <list_del+85>:       mov    0x8(%rbx),%rax
    0xffffffff80153fc8 <list_del+89>:       mov    %rax,0x8(%rdx)
    0xffffffff80153fcc <list_del+93>:       mov    %rdx,(%rax)
    0xffffffff80153fcf <list_del+96>:       movq   $0x200200,0x8(%rbx)
    0xffffffff80153fd7 <list_del+104>:      movq   $0x100100,(%rbx)
    0xffffffff80153fde <list_del+111>:      pop    %rbx
    0xffffffff80153fdf <list_del+112>:      retq
    crash>

 

길게 볼 필요는 없다. 사실 list_del 의 함수호출주소는 0xffffffff80153f68 이지만, +8 되는 오프셋 주소에서 문제가 생긴것이니,

0xffffffff80153f77 에서 찍어본 것이다. ( 앞쪽은 void 함수선언영역부분이 다이다. )

참고로 단순하게 dis list_del 이라고 해도 쭈욱 나온다. :)

 

자..list+8 부분에서 뻗은걸 기억해라.

그 아래부터 rd 명령으로 쭉 뿌려보면 16진수와 Ascii 문자들이 뿌려지는데 의미없는 문자들이 대부분이다.

 

printk 부분 메모리 영역을 자꾸 찍어보면 의미가 있는 소스구문이 발견된다.

(printk 는 kernel 에 문자를 출력하는 시스템콜인거 설명해야되나 ㅡ.,ㅡ:: )

 

  1. crash> rd 0xffffffff802bbb37 40
    ffffffff802bbb37:  5f7473696c3e333c 72726f63206c6564   <3>list_del corr
    ffffffff802bbb47:  202e6e6f69747075 72703e2d7478656e   uption. next->pr
    ffffffff802bbb57:  6c756f6873207665 2c70252065622064   ev should be %p,
    ffffffff802bbb67:  7361772074756220 3e333c000a702520    but was %p..<3>
    ffffffff802bbb77:  6464615f7473696c 74707572726f6320   list_add corrupt
    ffffffff802bbb87:  78656e202e6e6f69 20766572703e2d74   ion. next->prev
    ffffffff802bbb97:  6220646c756f6873 7562202c70252065   should be %p, bu
    ffffffff802bbba7:  7025207361772074 73696c3e333c000a   t was %p..<3>lis
    ffffffff802bbbb7:  6f63206464615f74 6e6f697470757272   t_add corruption
    ffffffff802bbbc7:  3e2d76657270202e 6f6873207478656e   . prev->next sho
    ffffffff802bbbd7:  2520656220646c75 7720747562202c70   uld be %p, but w
    ffffffff802bbbe7:  6c000a7025207361 70616d6f692f6269   as %p..lib/iomap
    ffffffff802bbbf7:  672f62696c00632e 2e636f6c6c616e65   .c.lib/genalloc.
    ffffffff802bbc07:  696c61766e690063 6e61747369642064   c.invalid distan
    ffffffff802bbc17:  66206f6f74206563 006b636162207261   ce too far back.
    ffffffff802bbc27:  2064696c61766e69 65636e6174736964   invalid distance
    ffffffff802bbc37:  6e690065646f6320 696c2064696c6176    code.invalid li
    ffffffff802bbc47:  656c2f6c61726574 646f63206874676e   teral/length cod
    ffffffff802bbc57:  72726f636e690065 6461656820746365   e.incorrect head
    ffffffff802bbc67:  6b63656863207265 6e776f6e6b6e7500   er check.unknown

 

자 잘보면 next->prev  의 구문등이 보일것이다.

 

list_del 의 소스를 확인해 보자. (소스위치등이랑 struct 등의 확인은 직접 해보아라 재밌다.. )

일단 list 라는 명령을 사용해 메모리상에서 list_del 함수의 Linked List 상태를 확인 할 수 있다.

 

  1. crash> list list_del
    ffffffff80153f6f
    fb894808478b4853
    list: invalid kernel virtual address: fb894808478b4853  type: "list entry"
    crash> p list_del
    list_del = $2 = 
     {void (struct list_head *)} 0xffffffff80153f6f <list_del>
    crash> list list_del 0xffffffff80153f6f
    list: read error: kernel virtual address: ffffffff002a7ede  type: "first list entry"
    crash> list list_head 0xffffffff80153f6f
    list: invalid argument: list_head
    crash> list -s list_head 0xffffffff80153f6f
    ffffffff80153f6f
    struct list_head {
      next = 0xfb894808478b4853, 
      prev = 0x1b74fa3948108b48
    }
    fb894808478b4853
    struct list_head Cannot access memory at address 0xfb894808478b4853
    crash>
    crash> gdb list list_del
    56       * @entry: the element to delete from the list.
    57       * Note: list_empty on entry does not return true after this, the entry is
    58       * in an undefined state.
    59       */
    60      void list_del(struct list_head *entry)
    61      {
    62              if (unlikely(entry->prev->next != entry)) {
    63                      printk(KERN_ERR "list_del corruption. prev->next should be %p, but was %p\n",
    64                              entry, entry->prev->next);
    65                      BUG();
    crash>
    crash> gdb list *0xffffffff80153f77
    0xffffffff80153f77 is in list_del (lib/list_debug.c:62).
    57       * Note: list_empty on entry does not return true after this, the entry is
    58       * in an undefined state.
    59       */
    60      void list_del(struct list_head *entry)
    61      {
    62              if (unlikely(entry->prev->next != entry)) {
    63                      printk(KERN_ERR "list_del corruption. prev->next should be %p, but was %p\n",
    64                              entry, entry->prev->next);
    65                      BUG();
    66              }
    crash>

 

짜잔~ 여기선 gdb 의 명령이 나오게 된다. crash 툴에서 gdb 명령을 추가호출하여 사용이 가능한데.

gdb 에서 소스코드를 보여주는 명령은 list 이다.

Linked List 상태를 보여주는 명령과 동일하므로 gdb 명령을 이용해야한다.. :)

 

gdb list list_del 을 하면 안타깝게도 10줄만 딸랑 보여준다.. 원래는 인자를 넣어서 몇줄씩 볼 수 있으나,

crash 에서 제공하는 gdb 는 인자를 안먹는다 샹샹바...어쨋든 대신 그러면 아까 list_del+8 이 가르치는 주소가 어떤소스인지

확인을 해보도록 한다.

 

주소를 입력하면 저렇게 몇재쭐의 코드를 가르키는 메모리주소인지 알려준다! :)

역시 커널버그일때의 코드를 가르키고있다.

간단히 설명하자면, list_head 스트럭쳐에 있는 entry 중 prev->next 영역이 엔트리에서 참조되지 않고 있는것 같을때

list 해제에 대한 버그임을 뿌려주라는 것이다.

 

* unlikely 는 커널 매크로로 (함수아님) True 가능성이 높은지, False 가능성이 높은지 러프하게 추정하여 동작 할 수 있게

하는 일종의 확률매크로라고 볼 수 있다. 즉 조건문에 대해서 false 가 떨어질 가능성이 높다면 이라는 조건분기라고 할 수 있다.

 

빨간색 표시된 부분중 첫번째인 메모리 접근이 불가능하다는 것을 보았을때, 메모리 해제과정에서 더블프리버그 혹은,

메모리 참조포인터를 잃어서 정상적인 링크드리스트 처리가 되지 않아 커널패닉이 떨어진 것으로 확정 할 수 있다.

 

자 여기까지 분석했으니 이제 남은건 모듈개발자 혹은 커널 개발자가 패치해줘야 하는것이겠지.....

너무 많은걸 바라진 말자..나에게.. 힘이들다... ㅠㅠ

레드햇 답변 올때까지 기다려 봐야지뭐... 언젠간 나도 내공을 충분히 쌓아 실제 문제가 되는 모듈코드도 찾아서 수정하고

할 수 있겠지!!!! :)

 

 

 

Coredump Analysis 9#

 

상황#

이번엔 페도라 14 사용중인 내 노트북에서 발생한 커널 패닉이다.

자세한 상황설명은 GFS 테스트를 위해 KVM 을 이용하여 RHEL 5 노드 2개를 생성 후, 노트북에 iscsi 바인딩데몬을 올렸고,

각 노드에서 이것을 활용 할 수 있게끔 iscsi initiator 를 설정하던중 발생한 패닉이다.

정확하게 노트북 (편의상 Host 라고 하겠다.) 에서 작동하는 iptables 에 3260 포트가 오픈되지 않아, 

포트오픈 룰을 추가 후  iptables restart 명령을 내리자 갑자기 패닉되며 코어덤프를 떠버리던 상황이다.

 

 

시스템 (OS) : Fedora 14 ( Laughlin)

Kernel Ver.  : 2.6.35.12-88.fc14

Machine      : x86_64

Memory       : 4G

 

 

분석과정#

 

  1.       KERNEL: /usr/lib/debug/lib/modules/2.6.35.12-88.fc14.x86_64/vmlinux

  2.     DUMPFILE: /var/crash/127.0.0.1-2011-04-21-19:37:30/vmcore
  3.         CPUS: 4
  4.         DATE: Thu Apr 21 19:37:24 2011
  5.       UPTIME: 02:32:32
  6. LOAD AVERAGE: 0.26, 0.56, 0.85
  7.        TASKS: 509
  8.     NODENAME: Mirr
  9.      RELEASE: 2.6.35.12-88.fc14.x86_64
  10.      VERSION: #1 SMP Thu Mar 31 21:21:57 UTC 2011
  11.      MACHINE: x86_64  (2394 Mhz)
  12.       MEMORY: 3.8 GB
  13.        PANIC: "[ 9137.459831] Kernel panic - not syncing: stack-protector: Kernel stack is corrupted in: ffffffff81417249"
  14.          PID: 8762
  15.      COMMAND: "qemu-kvm"
  16.         TASK: ffff88012e0f5d00  [THREAD_INFO: ffff88008ca78000]
  17.          CPU: 2
  18.        STATE: TASK_RUNNING (PANIC)

 

자.. 일단 여기서 보여주는 정보..매우 좋다.

PANIC 의 원인은 일단 PID 8762 를 할당받은 qemu-kvm 커맨드에서 kernel stack 이 잘못된 주소를 참조하여 stack-protector 가 동작해 싱크가 불가했다는 얘기이다.

어렵나? 일단 BT 찍어보자. 로그먼저 찍어보아도 좋다.

 

  1.  

    [ 9137.459831] Kernel panic - not syncing: stack-protector: Kernel stack is corrupted in: ffffffff81417249

    [ 9137.459836] 

    [ 9137.459846] Pid: 8762, comm: qemu-kvm Not tainted 2.6.35.12-88.fc14.x86_64 #1

    [ 9137.459852] Call Trace:

    [ 9137.459857]  <IRQ>  [<ffffffff81468e1f>] panic+0x8b/0x10d

    [ 9137.459877]  [<ffffffff81417249>] ? icmp_send+0x50a/0x51c

    [ 9137.459885]  [<ffffffff8104de59>] get_taint+0x0/0x12

    [ 9137.459890]  [<ffffffff81417249>] icmp_send+0x50a/0x51c

    [ 9137.459899]  [<ffffffff81039d8f>] ? __wake_up_common+0x4e/0x84

    [ 9137.459908]  [<ffffffff81053a38>] ? local_bh_enable+0xe/0x10

    [ 9137.459916]  [<ffffffff8142bcfd>] ? ipt_do_table+0x590/0x6e7

    [ 9137.459930]  [<ffffffffa046821d>] ? br_dev_queue_push_xmit+0x82/0x88 [bridge]

    [ 9137.459943]  [<ffffffffa046d27e>] ? br_nf_dev_queue_xmit+0x0/0x83 [bridge]

    [ 9137.459954]  [<ffffffffa046d2ff>] ? br_nf_dev_queue_xmit+0x81/0x83 [bridge]

    [ 9137.459965]  [<ffffffffa046d277>] ? NF_HOOK_THRESH+0x4b/0x52 [bridge]

    [ 9137.459973]  [<ffffffff811e2f7b>] ? selinux_ip_forward+0x60/0x1c5

    [ 9137.459982]  [<ffffffff8142d8d0>] ? iptable_filter_hook+0x5c/0x60

    [ 9137.459989]  [<ffffffff813e1b8d>] ? nf_iterate+0x46/0x89

    [ 9137.460001]  [<ffffffffa046d5a1>] ? br_nf_forward_finish+0x0/0xa9 [bridge]

    [ 9137.460006]  [<ffffffff813e1c3a>] ? nf_hook_slow+0x6a/0xd0

    [ 9137.460017]  [<ffffffffa046d5a1>] ? br_nf_forward_finish+0x0/0xa9 [bridge]

    [ 9137.460029]  [<ffffffffa046d5a1>] ? br_nf_forward_finish+0x0/0xa9 [bridge]

    [ 9137.460040]  [<ffffffffa046d26d>] ? NF_HOOK_THRESH+0x41/0x52 [bridge]

    [ 9137.460051]  [<ffffffffa046d46c>] ? nf_bridge_pull_encap_header+0x25/0x31 [bridge]

    [ 9137.460063]  [<ffffffffa046ded1>] ? br_nf_forward_ip+0x1e0/0x1f4 [bridge]

    [ 9137.460069]  [<ffffffff813e3c5c>] ? __nf_conntrack_find+0x8d/0xea

    [ 9137.460078]  [<ffffffff813e1b8d>] ? nf_iterate+0x46/0x89

    [ 9137.460087]  [<ffffffffa046827c>] ? br_forward_finish+0x0/0x25 [bridge]

    [ 9137.460093]  [<ffffffff813e1c3a>] ? nf_hook_slow+0x6a/0xd0

    [ 9137.460101]  [<ffffffffa046827c>] ? br_forward_finish+0x0/0x25 [bridge]

    [ 9137.460111]  [<ffffffffa046827c>] ? br_forward_finish+0x0/0x25 [bridge]

    [ 9137.460119]  [<ffffffffa0468269>] ? NF_HOOK.clone.2+0x46/0x59 [bridge]

    [ 9137.460128]  [<ffffffffa046833a>] ? __br_forward+0x73/0x75 [bridge]

    [ 9137.460137]  [<ffffffffa04683a9>] ? br_forward+0x3a/0x4d [bridge]

    [ 9137.460146]  [<ffffffffa046906e>] ? br_handle_frame_finish+0x155/0x1c7 [bridge]

    [ 9137.460156]  [<ffffffffa0468f19>] ? br_handle_frame_finish+0x0/0x1c7 [bridge]

    [ 9137.460168]  [<ffffffffa046d277>] ? NF_HOOK_THRESH+0x4b/0x52 [bridge]

    [ 9137.460179]  [<ffffffffa046d49d>] ? nf_bridge_push_encap_header+0x25/0x31 [bridge]

    [ 9137.460191]  [<ffffffffa046d908>] ? br_nf_pre_routing_finish+0x205/0x228 [bridge]

    [ 9137.460197]  [<ffffffff813e1c3a>] ? nf_hook_slow+0x6a/0xd0

    [ 9137.460207]  [<ffffffffa046d703>] ? br_nf_pre_routing_finish+0x0/0x228 [bridge]

    [ 9137.460219]  [<ffffffffa046d703>] ? br_nf_pre_routing_finish+0x0/0x228 [bridge]

    [ 9137.460231]  [<ffffffffa046d277>] ? NF_HOOK_THRESH+0x4b/0x52 [bridge]

    [ 9137.460242]  [<ffffffffa046d9c0>] ? setup_pre_routing+0x4b/0x76 [bridge]

    [ 9137.460254]  [<ffffffffa046e369>] ? br_nf_pre_routing+0x484/0x494 [bridge]

    [ 9137.460259]  [<ffffffff813e1b8d>] ? nf_iterate+0x46/0x89

    [ 9137.460266]  [<ffffffff81066a45>] ? autoremove_wake_function+0x16/0x39

    [ 9137.460276]  [<ffffffffa0468f19>] ? br_handle_frame_finish+0x0/0x1c7 [bridge]

    [ 9137.460282]  [<ffffffff813e1c3a>] ? nf_hook_slow+0x6a/0xd0

    [ 9137.460291]  [<ffffffffa0468f19>] ? br_handle_frame_finish+0x0/0x1c7 [bridge]

    [ 9137.460299]  [<ffffffff8103d102>] ? __wake_up+0x44/0x4d

    [ 9137.460308]  [<ffffffffa0468f19>] ? br_handle_frame_finish+0x0/0x1c7 [bridge]

    [ 9137.460318]  [<ffffffffa0468f07>] ? NF_HOOK.clone.3+0x46/0x58 [bridge]

    [ 9137.460327]  [<ffffffffa0469251>] ? br_handle_frame+0x171/0x18c [bridge]

    [ 9137.460336]  [<ffffffff813bedd0>] ? __netif_receive_skb+0x2cd/0x412

    [ 9137.460344]  [<ffffffff810a9d8d>] ? check_for_new_grace_period.clone.19+0x8b/0x97

    [ 9137.460352]  [<ffffffff813c0742>] ? process_backlog+0x87/0x15d

    [ 9137.460371]  [<ffffffff8106b8d8>] ? sched_clock_cpu+0x42/0xc6

    [ 9137.460379]  [<ffffffff813c08c4>] ? net_rx_action+0xac/0x1bb

    [ 9137.460385]  [<ffffffff8106b8d8>] ? sched_clock_cpu+0x42/0xc6

    [ 9137.460393]  [<ffffffff81053dc9>] ? __do_softirq+0xf0/0x1bf

    [ 9137.460401]  [<ffffffff8100abdc>] ? call_softirq+0x1c/0x30

    [ 9137.460407]  [<ffffffff8100abdc>] ? call_softirq+0x1c/0x30

    [ 9137.460411]  <EOI>  [<ffffffff8100c338>] ? do_softirq+0x46/0x82

    [ 9137.460423]  [<ffffffff813bfced>] ? netif_rx_ni+0x26/0x2b

    [ 9137.460431]  [<ffffffffa005d888>] ? tun_get_user+0x3e0/0x421 [tun]

    [ 9137.460439]  [<ffffffffa005ded1>] ? tun_chr_aio_write+0x0/0x84 [tun]

    [ 9137.460447]  [<ffffffffa005df3a>] ? tun_chr_aio_write+0x69/0x84 [tun]

    [ 9137.460456]  [<ffffffff81117d22>] ? do_sync_readv_writev+0xc1/0x100

    [ 9137.460464]  [<ffffffff811e4452>] ? selinux_file_permission+0xa7/0xb9

    [ 9137.460474]  [<ffffffff811dce11>] ? security_file_permission+0x16/0x18

    [ 9137.460481]  [<ffffffff81117f78>] ? do_readv_writev+0xa7/0x127

    [ 9137.460488]  [<ffffffff81125194>] ? do_vfs_ioctl+0x468/0x49b

    [ 9137.460495]  [<ffffffff81118941>] ? fput+0x22/0x1ed

    [ 9137.460502]  [<ffffffff8111803d>] ? vfs_writev+0x45/0x47

    [ 9137.460508]  [<ffffffff81118160>] ? sys_writev+0x4a/0x93

    [ 9137.460515]  [<ffffffff81009cf2>] ? system_call_fastpath+0x16/0x1b

 

  1.  

    crash> bt

    PID: 8762   TASK: ffff88012e0f5d00  CPU: 2   COMMAND: "qemu-kvm"

     #0 [ffff88000e303400] machine_kexec at ffffffff81027dc3

     #1 [ffff88000e303480] crash_kexec at ffffffff81084ffa

     #2 [ffff88000e303550] panic at ffffffff81468e26

     #3 [ffff88000e3035d0] icmp_send at ffffffff81417249

     #4 [ffff88000e303790] local_bh_enable at ffffffff81053a38

     #5 [ffff88000e3037d0] ipt_do_table at ffffffff8142bcfd

     #6 [ffff88000e303920] iptable_filter_hook at ffffffff8142d8d0

     #7 [ffff88000e303930] nf_iterate at ffffffff813e1b8d

     #8 [ffff88000e303980] nf_hook_slow at ffffffff813e1c3a

     #9 [ffff88000e3039f0] NF_HOOK_THRESH at ffffffffa046d26d

    #10 [ffff88000e303a20] br_nf_forward_ip at ffffffffa046ded1

    #11 [ffff88000e303a60] nf_iterate at ffffffff813e1b8d

    #12 [ffff88000e303ab0] nf_hook_slow at ffffffff813e1c3a

    #13 [ffff88000e303b20] NF_HOOK.clone.2 at ffffffffa0468269

    #14 [ffff88000e303b50] __br_forward at ffffffffa046833a

    #15 [ffff88000e303b70] br_forward at ffffffffa04683a9

    #16 [ffff88000e303b80] br_handle_frame_finish at ffffffffa046906e

    #17 [ffff88000e303bc0] NF_HOOK_THRESH at ffffffffa046d277

    #18 [ffff88000e303bf0] br_nf_pre_routing_finish at ffffffffa046d908

    #19 [ffff88000e303c90] NF_HOOK_THRESH at ffffffffa046d277

    #20 [ffff88000e303cc0] br_nf_pre_routing at ffffffffa046e369

    #21 [ffff88000e303d00] nf_iterate at ffffffff813e1b8d

    #22 [ffff88000e303d50] nf_hook_slow at ffffffff813e1c3a

    #23 [ffff88000e303dc0] NF_HOOK.clone.3 at ffffffffa0468f07

    #24 [ffff88000e303df0] br_handle_frame at ffffffffa0469251

    #25 [ffff88000e303e20] __netif_receive_skb at ffffffff813bedd0

    #26 [ffff88000e303e80] process_backlog at ffffffff813c0742

    #27 [ffff88000e303ee0] net_rx_action at ffffffff813c08c4

    #28 [ffff88000e303f40] __do_softirq at ffffffff81053dc9

    #29 [ffff88000e303fb0] call_softirq at ffffffff8100abdc

    --- <IRQ stack> ---

    #30 [ffff88008ca79c20] netif_rx at ffffffff813bfbce

    #31 [ffff88008ca79c60] netif_rx_ni at ffffffff813bfced

    #32 [ffff88008ca79c80] tun_get_user at ffffffffa005d888

    #33 [ffff88008ca79d00] tun_chr_aio_write at ffffffffa005df3a

    #34 [ffff88008ca79d40] do_sync_readv_writev at ffffffff81117d22

    #35 [ffff88008ca79e50] do_readv_writev at ffffffff81117f78

    #36 [ffff88008ca79f30] vfs_writev at ffffffff8111803d

    #37 [ffff88008ca79f40] sys_writev at ffffffff81118160

    #38 [ffff88008ca79f80] system_call_fastpath at ffffffff81009cf2

        RIP: 00000034e04d8ab7  RSP: 00007fe3a75e6998  RFLAGS: 00010202

        RAX: 0000000000000014  RBX: ffffffff81009cf2  RCX: 0000000001376e68

        RDX: 0000000000000001  RSI: 00007fe3a75e6920  RDI: 000000000000002a

        RBP: 0000000000000001   R8: 0000000000000000   R9: 0000000000000000

        R10: 0000000001343630  R11: 0000000000000293  R12: 00007fe3a75e6920

        R13: 0000000001343670  R14: 0000000101343670  R15: 0000000000000000

        ORIG_RAX: 0000000000000014  CS: 0033  SS: 002b

     

 

젠장할 길다. 그러나 사실 크게 여러가지 볼 필요는 없다. 이미 Stack Protector 가 동작한 주소가 나오고 있기 때문이다.

보면 icmp_send 라는 함수부에서 동일한 메모리 번지를 할당받았다.

icmp 룰 을 재정의하는 과정에 ( iptable 재시작을 했으니 ) 서 어떤 오류로 잘못된 참조값이 들어갔다는 얘기일 테니까..

일단 버그를 찾아보자...icmp_send 를 키워드로 bugzilla 와 kernel.org 또한 lkml 과 구글에게 물어봤으나,

이들도 썩 맞는 케이스를 던져주고 있지 않았다.

혹시 정말 icmp 소스에 어떤 논리적 오류라도 있는건가? 하여 소스를 확인해 보기로 했다.

 

  1.  

    crash> gdb list *0xffffffff81417235

    0xffffffff81417235 is in icmp_send (net/ipv4/icmp.c:649).

    644     ende:

    645             ip_rt_put(rt);

    646     out_unlock:

    647             icmp_xmit_unlock(sk);

    648     out:;

    649     }

    650     

    651     

    652     /*

    653      *      Handle ICMP_DEST_UNREACH, ICMP_TIME_EXCEED, and ICMP_QUENCH.

     

 

지금 나타내는 메모리번지의 코드라인은 649... } 로 블럭이 닫히는 부분이다.

제길 이 소스보기로는 의미가 없다 왜냐하면 저 주소는 저 코드가 들어가는 부분에 대한 표시일 뿐인거였다.

 

어쨋든 icmp.c 의 icmp_send 함수에서 생기는 문제인건 다시 확실해 졌는데 뭔가 다시 얻어낼 힌트 없을까?

소스를 쭈욱 직접 열어서 보면.... icmp_send 코드내용중에 

 

  1.  /* RFC says return as much as we can without exceeding 576 bytes. */

    631     

    632             room = dst_mtu(&rt->u.dst);

    633             if (room > 576)

    crash> l

    634                     room = 576;

    635             room -= sizeof(struct iphdr) + icmp_param.replyopts.optlen;

    636             room -= sizeof(struct icmphdr);

    637     

    638             icmp_param.data_len = skb_in->len - icmp_param.offset;

    639             if (icmp_param.data_len > room)

    640                     icmp_param.data_len = room;

    641             icmp_param.head_len = sizeof(struct icmphdr);

 

굵게 칠한 부분들이 눈에 띈다.. 어라 이거 MTU 값이 576 인부분에대한 처리인데??

좋다 거의 다 왔다. 아까부터 사실 스택에 들어있는 함수들을 볼때 신경쓰였던게 br 즉 브릿지 관련 함수들이였다.

네트워크 관련된 이야기인데, KVM 에서는 호스트머신과 Guest 머신간 통신에 설정되는 내부 브릿지는 MTU 를 576 으로 소통한다.

즉 커널버그인건데, 버그질라에서 안나와서 구글에게 물었더니 RHEL6 에 관련된 버그질라 내용을 떡하니 보여준다. ( kvm icmp 로 키워드 )

https://partner-bugzilla.redhat.com/show_bug.cgi?id=629590 젠장... partner 라고 붙는 주소다...라지만 공개되어있다.

 

여기의 설명에 따르면 다음과 같은 구조를 설명해 준다.

  1.  

              <Remote Machine>--<Host Machine>--<Bridge>--<Tun/Tap>--<KVM Guest>
                    1500 mtu              576 mtu        576 mtu    576 mtu     1500 mtu
              

재밌는건 소스코드를 비교해봤는데 패치가 이미 적용되어 있다.

혹시 몰라 lkml 을 뒤져본다.

http://lkml.org/lkml/2010/8/30/391

요로코롬 이번엔 ip_output.c 의 ip_fragment 함수에 대해 패치가 있다.

어...이건 적용이 안되어있다.

커밋된지 한참 된것같은데....뭐 일단 어찌됐든, KVM 에서 Host 와 Guest 간 브릿지 MTU 값에 대한 문제로 생긴 icmp 라우팅문제라는게 대략적 결론.

 

다른아저씨들처럼 아직 MTU 수정해서 테스트해보진 않았으나 (글작성후 할거임)

확실히 다시 해보니 동일한 내용으로 코어가 생성된다.

커널메일링에 있는대로 ip option 관련 패치좀 해보고 정상유무 확인해야겠다. 오래된건데 왜 적용을 안했을까... 흑..

 

 

Coredump Analysis 10#

 

상황#

이번에도 역시 내 노트북에서 발생한 커널 패닉이다.

Fedora16 으로 업그레이드를 했어야 하나, 귀차니즘으로 마냥 있다보니 Fedora 15 이다 아직.

대략적인 상황으로는 이녀석을 요즘은 내가 노트북이 그닥 필요없어진 경지 - 라기보단 그냥 없어도 되는일들인 - 인지라,

집에 놓고당기는데, 이녀석이 꼭 돌아와보면 먹통. 즉, Wakeup 이 안된다는점... 그래서 항상 강제리부팅을 해오다,

커널패닉이 왜 안떨어지지? 라며 Sysrq 를 이용해 강제 크래슁을 시켰더니 먹통은 아니더라.....

그래서 일단 커널덤프를 살펴보기로 마음먹었다.. 오랜만이다 +.,+

 

시스템 (OS) : Fedora 15 ( Lovelock )

Kernel Ver.  : 2.6.41.4-1.fc15

Machine      : x86_64

Memory       : 4G

 

 

분석과정#

 

  1.       KERNEL: /usr/lib/debug/lib/modules/2.6.41.4-1.fc15.x86_64/vmlinux
        DUMPFILE: /var/crash/127.0.0.1-2011-12-31-02:55:50/vmcore
            CPUS: 4
            DATE: Sat Dec 31 11:55:50 2011
          UPTIME: 1 days, 16:02:09
    LOAD AVERAGE: 89.57, 89.12, 89.00
           TASKS: 398
        NODENAME: Mirr-N
         RELEASE: 2.6.41.4-1.fc15.x86_64
         VERSION: #1 SMP Tue Nov 29 11:53:48 UTC 2011
         MACHINE: x86_64  (2393 Mhz)
          MEMORY: 3.8 GB
           PANIC: "[143880.225534] Oops: 0002 [#1] SMP " (check log for details)
             PID: 29800
         COMMAND: "kworker/0:1"
            TASK: ffff880107d32e60  [THREAD_INFO: ffff880112062000]
             CPU: 0
           STATE: TASK_RUNNING (PANIC)

 

자.. 일단 여기서 보여주는 정보..에서의 특징은 oops SMP 에 대한 패닉내용과, kworker 를 보면 알 수 있는데,

매직키를 이용한 커널덤프를 발생시켰음을 추측 해 볼 수 있다는 점.

 

언제나처럼 log 를 찍어보도록 하자.

  1. crash> log
    b7 d0 c1 e8 10 39 c2 74 07 f3 90 <0f> b7 17 eb f5 5d c3 55 48 89 e5 66 66 66 66 90 8b 07 89 c2 c1
    [143763.111566] Call Trace:
    [143763.111570]  <IRQ>  [<ffffffff8149ca36>] _raw_spin_lock+0xe/0x10
    [143763.111589]  [<ffffffffa040d866>] rtl_lps_leave+0x1c/0xea [rtlwifi]
    [143763.111603]  [<ffffffffa040f3cb>] _rtl_pci_ips_leave_tasklet+0xe/0x10 [rtlwifi]
    [143763.111611]  [<ffffffff8105cddb>] tasklet_action+0x7f/0xd2
    [143763.111619]  [<ffffffff8105d683>] __do_softirq+0xc9/0x1b5
    [143763.111627]  [<ffffffff81027719>] ? ack_APIC_irq+0x15/0x17
    [143763.111634]  [<ffffffff81014b35>] ? paravirt_read_tsc+0x9/0xd
    [143763.111642]  [<ffffffff814a542c>] call_softirq+0x1c/0x30
    [143763.111649]  [<ffffffff81010b45>] do_softirq+0x46/0x81
    [143763.111657]  [<ffffffff8105d94b>] irq_exit+0x57/0xb1
    [143763.111663]  [<ffffffff814a5d0e>] do_IRQ+0x8e/0xa5
    [143763.111671]  [<ffffffff8149ce2e>] common_interrupt+0x6e/0x6e
    [143763.111675]  <EOI>  [<ffffffff8124bd80>] ? ip_compute_csum+0x34/0x34
    [143763.111689]  [<ffffffff8124be69>] ? delay_tsc+0x35/0x74
    [143763.111697]  [<ffffffff8124bdd9>] __delay+0xf/0x11
    [143763.111704]  [<ffffffff8124be07>] __const_udelay+0x2c/0x2e
    [143763.111717]  [<ffffffffa0424ac4>] rtl92s_phy_set_rf_power_state+0x50f/0x601 [rtl8192se]
    [143763.111732]  [<ffffffffa040dd55>] ? rtl_swlps_rf_sleep+0x177/0x177 [rtlwifi]
    [143763.111746]  [<ffffffffa040d393>] rtl_ps_set_rf_state+0xdd/0xe3 [rtlwifi]
    [143763.111760]  [<ffffffffa040dc5e>] rtl_swlps_rf_sleep+0x80/0x177 [rtlwifi]
    [143763.111774]  [<ffffffffa040dd82>] rtl_swlps_wq_callback+0x2d/0x83 [rtlwifi]

    [143763.111782]  [<ffffffff8106ed8c>] process_one_work+0x176/0x2a9
    [143763.111790]  [<ffffffff8106f89a>] worker_thread+0xda/0x15d
    [143763.111798]  [<ffffffff8106f7c0>] ? manage_workers+0x176/0x176
    [143763.111805]  [<ffffffff81072ce7>] kthread+0x84/0x8c
    [143763.111813]  [<ffffffff814a5334>] kernel_thread_helper+0x4/0x10
    [143763.111821]  [<ffffffff81072c63>] ? kthread_worker_fn+0x148/0x148
    [143763.111829]  [<ffffffff814a5330>] ? gs_change+0x13/0x13
    [143763.182744] BUG: soft lockup - CPU#1 stuck for 22s! [kworker/u:1:11382]
    [143763.182749] Modules linked in: tun ip6table_filter ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack xt_CHECKSUM iptable_mangle bridge ipv6 tcp_lp fuse ip6_tables ebtable_nat ebtables nfsd lockd nfs_acl auth_rpcgss sunrpc 8021q garp stp llc acpi_cpufreq mperf rfcomm bnep xfs btrfs zlib_deflate libcrc32c snd_hda_codec_hdmi snd_hda_codec_conexant snd_hda_intel arc4 rtl8192se rtlwifi mac80211 cfg80211 snd_hda_codec virtio_net kvm_intel kvm thinkpad_acpi btusb bluetooth uvcvideo videodev iTCO_wdt rfkill media joydev snd_hwdep snd_seq snd_seq_device snd_pcm snd_timer snd iTCO_vendor_support e1000e v4l2_compat_ioctl32 intel_ips i2c_i801 snd_page_alloc soundcore microcode wmi i915 drm_kms_helper drm i2c_algo_bit i2c_core video [last unloaded: scsi_wait_scan]
    [143763.182853] CPU 1
    [143763.182855] Modules linked in: tun ip6table_filter ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack xt_CHECKSUM iptable_mangle bridge ipv6 tcp_lp fuse ip6_tables ebtable_nat ebtables nfsd lockd nfs_acl auth_rpcgss sunrpc 8021q garp stp llc acpi_cpufreq mperf rfcomm bnep xfs btrfs zlib_deflate libcrc32c snd_hda_codec_hdmi snd_hda_codec_conexant snd_hda_intel arc4 rtl8192se rtlwifi mac80211 cfg80211 snd_hda_codec virtio_net kvm_intel kvm thinkpad_acpi btusb bluetooth uvcvideo videodev iTCO_wdt rfkill media joydev snd_hwdep snd_seq snd_seq_device snd_pcm snd_timer snd iTCO_vendor_support e1000e v4l2_compat_ioctl32 intel_ips i2c_i801 snd_page_alloc soundcore microcode wmi i915 drm_kms_helper drm i2c_algo_bit i2c_core video [last unloaded: scsi_wait_scan]
    [143763.182958]
    [143763.182963] Pid: 11382, comm: kworker/u:1 Not tainted 2.6.41.4-1.fc15.x86_64 #1 LENOVO 3249PQ9/3249PQ9
    [143763.182972] RIP: 0010:[<ffffffff81085dc9>]  [<ffffffff81085dc9>] do_raw_spin_lock+0x1e/0x25
    [143763.182983] RSP: 0018:ffff8801011cbda0  EFLAGS: 00000293
    [143763.182988] RAX: 000000000000b484 RBX: 0000000000000286 RCX: 0000000000002a3b
    [143763.182994] RDX: 000000000000b481 RSI: 0000000000000286 RDI: ffff88012d3a9d74
    [143763.182999] RBP: ffff8801011cbda0 R08: ffff88012d3a9408 R09: 00000000005b3607
    [143763.183005] R10: 00000000005b3607 R11: ffff880137c92d00 R12: ffff8801011cbd28
    [143763.183010] R13: 0000000000000000 R14: 0000000000000002 R15: 0000000101da448b
    [143763.183017] FS:  0000000000000000(0000) GS:ffff880137c80000(0000) knlGS:0000000000000000
    [143763.183023] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
    [143763.183029] CR2: 0000000000cbf000 CR3: 0000000001a05000 CR4: 00000000000026e0
    [143763.183034] DR0: 0000000000000003 DR1: 00000000000000b0 DR2: 0000000000000001
    [143763.183040] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
    [143763.183046] Process kworker/u:1 (pid: 11382, threadinfo ffff8801011ca000, task ffff880040d08000)
    [143763.183051] Stack:
    [143763.183055]  ffff8801011cbdb0 ffffffff8149ca36 ffff8801011cbdd0 ffffffffa040dbaf
    [143763.183064]  ffff88012d3a9d40 ffff88012d3a8540 ffff8801011cbe00 ffffffffa040ac8c
    [143763.183074]  ffff88012d3a8540 0000000000000010 ffff88012cbe3800 ffffffffa03c0713
    [143763.183083] Call Trace:
    [143763.183091]  [<ffffffff8149ca36>] _raw_spin_lock+0xe/0x10
    [143763.183106]  [<ffffffffa040dbaf>] rtl_swlps_rf_awake+0x54/0x6c [rtlwifi]
    [143763.183119]  [<ffffffffa040ac8c>] rtl_op_config+0x128/0x328 [rtlwifi]
    [143763.183142]  [<ffffffffa03c0713>] ? ieee80211_rx_mgmt_beacon+0x4d3/0x4d3 [mac80211]
    [143763.183159]  [<ffffffffa03b6fcb>] ieee80211_hw_config+0x102/0x107 [mac80211]
    [143763.183182]  [<ffffffffa03c0745>] ieee80211_dynamic_ps_disable_work+0x32/0x47 [mac80211]
    [143763.183191]  [<ffffffff8106ed8c>] process_one_work+0x176/0x2a9
    [143763.183199]  [<ffffffff8106f89a>] worker_thread+0xda/0x15d
    [143763.183207]  [<ffffffff8106f7c0>] ? manage_workers+0x176/0x176
    [143763.183214]  [<ffffffff81072ce7>] kthread+0x84/0x8c
    [143763.183222]  [<ffffffff814a5334>] kernel_thread_helper+0x4/0x10
    [143763.183230]  [<ffffffff81072c63>] ? kthread_worker_fn+0x148/0x148
    [143763.183238]  [<ffffffff814a5330>] ? gs_change+0x13/0x13
    [143763.183242] Code: 00 00 10 00 74 05 e8 17 6e 1c 00 5d c3 55 48 89 e5 66 66 66 66 90 b8 00 00 01 00 f0 0f c1 07 0f b7 d0 c1 e8 10 39 c2 74 07 f3 90 <0f> b7 17 eb f5 5d c3 55 48 89 e5 66 66 66 66 90 8b 07 89 c2 c1
    [143763.183313] Call Trace:
    [143763.183320]  [<ffffffff8149ca36>] _raw_spin_lock+0xe/0x10
    [143763.183334]  [<ffffffffa040dbaf>] rtl_swlps_rf_awake+0x54/0x6c [rtlwifi]
    [143763.183348]  [<ffffffffa040ac8c>] rtl_op_config+0x128/0x328 [rtlwifi]
    [143763.183370]  [<ffffffffa03c0713>] ? ieee80211_rx_mgmt_beacon+0x4d3/0x4d3 [macrash> bt
    PID: 29800  TASK: ffff880107d32e60  CPU: 0   COMMAND: "kworker/0:1"
     #0 [ffff880137c03640] machine_kexec at ffffffff8102ba1a
     #1 [ffff880137c036b0] crash_kexec at ffffffff810925c1
     #2 [ffff880137c03780] oops_end at ffffffff8149db69
     #3 [ffff880137c037b0] no_context at ffffffff814930f1
     #4 [ffff880137c03810] __bad_area_nosemaphore at ffffffff814932cb
     #5 [ffff880137c03870] bad_area_nosemaphore at ffffffff814932ff
     #6 [ffff880137c03880] do_page_fault at ffffffff8149fb96
     #7 [ffff880137c03990] page_fault at ffffffff8149d0f5
        [exception RIP: sysrq_handle_crash+22]
        RIP: ffffffff812d6ed1  RSP: ffff880137c03a40  RFLAGS: 00010086
        RAX: 0000000000000010  RBX: ffffffff81a70e20  RCX: 000000000000dc0e
        RDX: 0000000000000000  RSI: 0000000000000046  RDI: 0000000000000063
        RBP: ffff880137c03a40   R8: 0000000000000001   R9: 0000ffff00066c0a
        R10: 0000ffff00066c0a  R11: 0000000000000000  R12: 0000000000000004
        R13: 0000000000000063  R14: 0000000000000002  R15: 0000000000000001
        ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
     #8 [ffff880137c03a48] __handle_sysrq at ffffffff812d7464
     #9 [ffff880137c03a88] sysrq_filter at ffffffff812d7655
    #10 [ffff880137c03ac8] input_pass_event at ffffffff81381be6
    #11 [ffff880137c03b28] input_handle_event at ffffffff8138320a
    #12 [ffff880137c03b78] input_event at ffffffff8138330b
    #13 [ffff880137c03bc8] atkbd_interrupt at ffffffff813886de
    crash>

 

이번 것 역시 딱 보면 어디가 문제인지 알기 쉽게 나와있다.

그것은 바로 Spin_Lock 의 문제라는것! 고질적인 이놈의 스핀락 롹롹롹!!! 설마 LoveLock 이라는 릴리즈명 때문은 아니겠지? ㅎ

아무튼 눈에 띄는 그동안 알고 있던 내용들을 우선적으로 찾아보면, Spin Lock 으로 인해 CPU time 을 제대로 얻어오지 못했음을

직감적으로 알 수 있어야 한다. - 알고 있지 다들?

 

자, 그럼 이제 그 스택들을 살펴보도록 하자. 

일단 IRQ 에 대한 spin lock 을 관리하는 raw_spin_lock 시스템 콜이 찍혀있음을 보았을때,

이것은 H/W 의 드라이버 혹은 H/W 관련된 문제임을 알 수 있다. - 그냥 그렇게 알면 된다.

그담에 눈여겨 볼것이 있다. 바로 rtl_lps_leave+0x1c/0xea [rtlwifi] 이녀석들인데!

눈치밥있다면 Realtek 관련 함수이지 않을까 라고 때려줘야 한다는 사실...

 

이것은 rtl92s_phy_set_rf_power_state+0x50f/0x601 [rtl8192se] 이녀석을 찾아보면 확실해진다.

그렇다! 내가 쓰고 있는 노트북인 IBM X201 모델에 들어있는 Realtek 무선랜카드는,

rtl8192SE 라는 드라이버를 사용하고 있으며, 이녀석은 커널에서 자체지원하지 않던 모델이라,

내가 직접 드라이버를 다운받아 컴파일하여 올려논 드라이버였다.

즉, 노트북이 대기모드나, 화면절약모드로 들어가있을때, 무선랜카드에서 전해지는 신호를 감지하거나,

유지시키는등의 Context Switching 과정에서 문제가 생겨 무한 데드락이 걸리는 현상이였던 것이다.

 

자..여기서 "그렇다면 문제는 커널 Spin Lock 이라고 내뱉을게 아니라, 드라이버 오류 Tained 를 뿝어야 하는거 아니냐!"

라는 맘에드는 예리한 인간이 있었으면 좋겠을려만... 나혼자 있는 상황이니 넘어가도록 하자.

 

항상 얘기하듯 이런건 일단 버그라고 뜬 부분이 있으니 버그질라를 찾아보도록 하자.

아주아주 깔쌈하게도, rtl_lps_leave 로 구글링을 하면 동일 버젼의 비슷한 부류의 커널 버그들을 알려주고 있는

RedHat Bugzilla 와, Kernel.org 가 여럿 발견된다.

https://bugzilla.redhat.com/show_bug.cgi?id=755154

http://thread.gmane.org/gmane.linux.kernel.wireless.general/81542/focus=81657

아주아주 간단하고도 친절스럽게, lps_leave 라는 함수는 Interrup context 로 부터 얼마든지 호출 될 수 있고,

이 과정에서 IRQ 에 대한 충돌이 일어나 Deadlock 에 진입 할 수도 있다는 간략한 설명이 있으며,

간단하게 IRQ 에 대한 스핀락 처리 함수를 Replace 하는 방법으로 해결 할 수 있다고 나와있다.

 

재밌게도 내가 컴파일해 사용하던 rtl8192se 의 드라이버에서는 당연히 spin_lock_irq 함수와,

spin_lock_irqsave 등의 함수들을 잘 사용하고 있었고, 역시 문제는 Kernel 에서 대기모드에서

활성모드로 전향하기 위한 irq spin lock 부분을 실제 처리해주는 모듈인 rtlwifi 가 문제이기 때문에,

위 문제를 해결하려면 나의 커널을 Fedora16 의 커널인 3.1대로 올리던가,

최소한 커널버젼 2.4.41.6-1.fc15 이상으로 올려야 한다고 한다.

 

문제는 위 버그질라에서 얘기하는 커널은 아직 Stable 커널이 아닌 Testing 커널이라는점,

어차피 나야 개인노트북이고, Fedora16 로 올라가야할 시간도 남아있으니 테스팅커널을 받아 이것저것 테스팅 해볼참이다.

테스팅 커널을 받는 방법은 다음과 같다.

 

  1. [root@Mirr-N ~ ]# yum update kernel --enablerepo=updates-testing

  2. Loaded plugins: fastestmirror, langpacks, presto, refresh-packagekit
    Loading mirror speeds from cached hostfile
     * fedora: ftp.cuhk.edu.hk
     * rpmfusion-free: mirrors.163.com
     * rpmfusion-free-updates: mirrors.163.com
     * rpmfusion-nonfree-updates: ucmirror.canterbury.ac.nz
     * updates: ftp.riken.jp
     * updates-testing: ftp.riken.jp
    Setting up Install Process
    Resolving Dependencies
    There are unfinished transactions remaining. You might consider running yum-complete-transaction first to finish them.
    --> Running transaction check
    ---> Package kernel.x86_64 0:2.6.41.6-1.fc15 will be installed
    --> Finished Dependency Resolution
    --> Running transaction check
    ---> Package kernel.x86_64 0:2.6.40.6-0.fc15 will be erased
    --> Finished Dependency Resolution

    Dependencies Resolved

    ================================================================================
     Package      Arch         Version                  Repository             Size
    ================================================================================
    Installing:
     kernel       x86_64       2.6.41.6-1.fc15          updates-testing        27 M
    Removing:
     kernel       x86_64       2.6.40.6-0.fc15          @updates              110 M

    Transaction Summary
    ================================================================================
    Install       1 Package(s)
    Remove        1 Package(s)

    Total download size: 27 M
    Is this ok [y/N]: y
    Downloading Packages:
    Setting up and reading Presto delta metadata
    updates-testing/prestodelta                              | 4.2 kB     00:00    
    Processing delta metadata
    Package(s) data still to download: 27 M
    kernel-2.6.41.6-1.fc15.x86_64.rpm                        |  27 MB     02:04    
    Running rpm_check_debug
    Running Transaction Test
    Transaction Test Succeeded
    Running Transaction
      Installing : kernel-2.6.41.6-1.fc15.x86_64                                1/2
      Cleanup    : kernel-2.6.40.6-0.fc15.x86_64                                2/2

    Removed:
      kernel.x86_64 0:2.6.40.6-0.fc15                                              
    Installed:
      kernel.x86_64 0:2.6.41.6-1.fc15                                             
    Complete!

  3. [root@Mirr-N ~ ]# cat /etc/grub.conf
    # grub.conf generated by anaconda
    #
    # Note that you do not have to rerun grub after making changes to this file
    # NOTICE:  You have a /boot partition.  This means that
    #          all kernel and initrd paths are relative to /boot/, eg.
    #          root (hd0,0)
    #          kernel /vmlinuz-version ro root=/dev/mapper/vg_mirr-LogVol00
    #          initrd /initrd-[generic-]version.img
    #boot=/dev/sda
    default=0
    timeout=0
    splashimage=(hd0,0)/grub/splash.xpm.gz
    hiddenmenu
    title Fedora (2.6.41.6-1.fc15.x86_64)
        root (hd0,0)
        kernel /vmlinuz-2.6.41.6-1.fc15.x86_64 root=/dev/mapper/vg_mirr-LogVol00 ro rd_LVM_LV=vg_mirr/LogVol00 rd_LVM_LV=vg_mirr/LogVol01 rd_NO_LUKS rd_NO_MD rd_NO_DM LANG=ko_KR.UTF-8 KEYTABLE=us rhgb quiet crashkernel=192M
        initrd /initramfs-2.6.41.6-1.fc15.x86_64.img

    title Fedora (2.6.41.4-1.fc15.x86_64.debug)
        root (hd0,0)
        kernel /vmlinuz-2.6.41.4-1.fc15.x86_64.debug root=/dev/mapper/vg_mirr-LogVol00 ro rd_LVM_LV=vg_mirr/LogVol00 rd_LVM_LV=vg_mirr/LogVol01 rd_NO_LUKS rd_NO_MD rd_NO_DM LANG=ko_KR.UTF-8 KEYTABLE=us rhgb quiet crashkernel=192M
        initrd /initramfs-2.6.41.4-1.fc15.x86_64.debug.img
    title Fedora (2.6.41.4-1.fc15.x86_64)
        root (hd0,0)
        kernel /vmlinuz-2.6.41.4-1.fc15.x86_64 root=/dev/mapper/vg_mirr-LogVol00 ro rd_LVM_LV=vg_mirr/LogVol00 rd_LVM_LV=vg_mirr/LogVol01 rd_NO_LUKS rd_NO_MD rd_NO_DM LANG=ko_KR.UTF-8 KEYTABLE=us rhgb quiet crashkernel=192M
        initrd /initramfs-2.6.41.4-1.fc15.x86_64.img

 

아주 간단하게 인스톨 되었다.

이제 부팅 후 Realtek 모듈 다시 올려본 뒤 한참 대기모드에 넣어보면 비교가 가능 할 것이다. 우히힛

 

역시 패치해보니 잘 행업 없이 잘 동작함을 확인 할 수 있었다. :)





http://blog.daum.net/ckcjck/15

+ Recent posts