Redhat kernel dump 분석 – 미르

Kernel Crash Dump Analysis Guide
소개
Tools
Crash 소개
기본명령어
사용방법
실행화면
Coredump Analysis 1
상황
분석과정
Coredump Analysis 2
상황
분석과정
Coredump Analysis 3
상황
분석과정
Coredump Analysis 4
상황
분석과정
Coredump Analysis 5
상황
분석과정
Coredump Analysis 6
상황
분석과정
Coredump Analysis 7
상황
분석과정
Coredump Analysis 8
상황
분석과정
Coredump Analysis 9
상황
분석과정
 
 
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 가 열고있는 파일디스크립터들을 출력해준다.
 
사용방법#
Usage: crash {namelist} {dumpfile}
[root@Test DUMP]# crash vmlinux vmcore
 
Crash 로 코어덤프를 분석하기 위해선 Debug 모드가 활성화 된 상태의 커널이 필요하다. ( kernel-debug )
실제론 동일 버젼의 커널 디버그패키지의 vmlinuz 를 합축해제한 vmlinux 파일을 필요로 한다.
 
debug 커널의 vmlinux 추출 방법은 다음과 같다.
 
[root@Test DUMP]# rpm2cpio kernel-debug-{version}.rpm | cpio -idh
[root@Test DUMP]# cd boot && od -A d -t x1 vmlinuz | grep ‘1f 8b 08 00’
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 으로 추출하는 과정이다. ( 역시 풀어설명하는게 더 복잡하다 그냥 명령어 코드 보자 )
 
실행화면#
 
[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
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 )
 
분석과정#
KERNEL: vmlinux
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
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
 
……………… 중략


    [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
 
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
………. 중략
SLAB      MEMORY    TOTAL  ALLOCATED  FREE
f7f4f000  f7f4f030     11         11     0
FREE / [ALLOCATED]
  [f7f4f030]
  [f7f4f188]
  [f7f4f2e0]
  [f7f4f438]
  [f7f4f590]
  [f7f4f6e8]
crash> inode.i_mem f7f4f030
  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
……….. 중략
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
분석과정#
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)
crash> bt
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
…….. 중략 …………
#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
  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
분석과정#
[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)                    
 please wait… (gathering module symbol data)
 please wait… (gathering task table data)                                                  
 please wait… (determining panic task)                                                      
   KERNEL: 2.6.9-22.ELsmp/vmlinux
   DUMPFILE: vmcore
   CPUS: 2
   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
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
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
…중략…
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 로그와는 확연히 다른 상세 로그가 남았다.
 
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 이라는 녀석이다.
 
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]
….중략…..
  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 로 확인 해 보았을 때 역시 표시가 있고,
 
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 … 약간 의심이 가기 시작한다.
 
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,
… 중략 …
  rlim = {{
      rlim_cur = 4294967295,
      rlim_max = 4294967295
…. 생략 …
 
task 를 찍어보았더니 너무 길다. 저번과 같이 deadbeef 같은 번지수는 찾아지지 않았다.
다만 rlim 값이 current 와 max 가 동일한 듯한 느낌이 든다.
 
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>
  … 중략 …
 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
 3207355798   f2d37390   c02a8a54  <tcp_synack_timer+200>
 
잘모르겠는데 타이머를 한번 찍어보았다.
역시 대략 특이한 점은 찾을 수 없었다.
 
bt 로 나왔던 몇몇 주소들을 dis 명령으로 disassembler 해본다.
 
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)
… 중략 …
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
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
분석과정#
      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)
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
….. 중략
#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 시스템콜등 디스크에 기록하는 부분들에서 멈춰댔다.
실제 이 것들만 보면 리부팅의 원인은 페이지 기록 즉 디스크에 기록하는 작업에서 문제가 발생한것으로
생각할 수 있다. 로그를 보자.
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 사용이 되고 있는지, 벤더 제공 디스크관련 모듈을 사용하고 있지 않은지 확인해 봐야 겠다.
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 )
그런데 큰일이 생겼다.
한참 분석중인상태에서 다시 리부팅이 이루어졌다.
보여진 메시지는 다음과 같다고 한다.
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 라고 뿌려지며 오늘 보내준 메시지 역시 다음과 같다.
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 를 통해 문자열들을 뽑아보면 커널 크래쉬 로그가 남는다.
 
# ] strings vmcore-incomplement > core_strings
 
7.1G 정도 쌓여있던 코어파일에서 약 260메가 정도 되는 파일이 생성되었다.
이제 이 스트링파일을 열어보자. 이 용량역시 엄청나 VI 로 열기 버거울 수 도 있겠지만
어쩌겠냐…열어봐야지
 
앞에 막 들어가있는 가비지문자들은 전부버리자. 아마 케이스마다 다르겠지만,
난 앞의 약 5만줄을 날렸더니 그럭저럭 다음과 같은 볼만한 문자가 보이더라.
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 포맷스트링들이 즐비해 있다.
다 무시하고 쭈~~~욱 내려가다보면 다음과 같은 눈에 확 들어오게 되는 문자열이 보이게 된다.
————-[ cut here ]————
 
많이 보던 문자 아닌가?
그렇다. crash 툴에서 찍어보던 log 를 나타내주는 문자열이였다.
자 이제 이 문자열을 검색해보자.
:/cut here
<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 실행을 해야 한다.
 
crash /boot/vmlinux-2.4.21-50.ELsmp vmlinux-2.4.21-50.ELsmp.debug /vmcore/vmcore
 
KERNEL: /boot/vmlinux-2.4.21-50.ELsmp
DEBUGINFO: vmlinux-2.4.21-50.ELsmp.debug
DUMPFILE: /vmcore/vmcore
CPUS: 4        
DATE: Tue Mar  2 00:10:38 2010      
UPTIME: 20 days, 17:24:55
LOAD AVERAGE: 37.56, 37.62, 33.58      
TASKS: 1679    
NODENAME: pil*****.*****.co.kr    
RELEASE: 2.4.21-50.ELsmp    
VERSION: #1 SMP Tue May 8 17:18:29 EDT 2007    
MACHINE: i686  (2664 Mhz)      
MEMORY: 17 GB      
PANIC: “Oops: 0002” (check log for details)        
PID: 3444    
COMMAND: “crond”        
TASK: efbe8000          
CPU: 3      
STATE: TASK_RUNNING (SYSRQ)
 
STAE 를 보면 재밌게도 TASK_RUNNING (SYSRQ) 라고 써져 있는 것을 볼 수 있다.
시스템 행업상태는 아니지만 SYSRQ 로 덤프를 떴다는 의미이다.
 
늘 R 사에서 하듯 log 부터 찍어보자.
 
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 로 인식한다 서버에서는…
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 에 대한 것만 나올테니 이번엔 대체 왜 문제가 생겼는지 부터 보자.
핵심은 행업상태인줄 알고 있었다는것 ( 서버 무반응 ). 일단 프로세스부터 보자.
 
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”
   ………….. 중략 …………….
[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”
    ………….. 중략 …………….
[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”
    ………….. 중략 …………….
[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 를 사용하여 전체를 잘 살펴봐야 한다. ( 눈빠진다..하지만 걱정마라 금방 원인이 추정되어 나온다. )
 
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”
……….. 중략 ………….
 
커널  프로세스 위주로 Backtrace 해봤다. swapper 가 동작하는것 외에 특별한 스택을 볼순 없었다.
다시 이제 user 영역을 찍어보자
 
crash> foreach user bt
………. 중략 ………….
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
………. 중략 ………….
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
………. 중략 ………….
 
자 전반적으로다가 의심스러운 스택들이 튀어나와있다.
 
 #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 상태로 의심할만한 반응이 없는 상태가 되는것이다.
 
좀 더 찾아보니 다음과 같은 것도 있었다.
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 갯수를 나타낸다.
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 이상 페이지를 갖고 있지 않다는 얘기이다.
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 갯수가 얼마나 되는지 확인해 보자.
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
…….. 중략 ……….
 
뭐, 간단히 SLAB 이란 원래 Solaris 계열에서 나온 정책인데, 쉽게 메모리 할당 후 혹시 쓰일지 모른다는 생각에
바로 폐기하지 않고, 남겨둔다는 것이다.
결국 커널은 동일한 크기의 연속된 메모리 (page) 를 요청하는 경향이 있기 때문에,
잦은 호출을 줄이기 위해 캐쉬 영역에 SLAB 을 둔다는 것이다.
결국 CACHE 에 SLAB 이 많이 존재 하게 되면 ( budy 를 자주 호출하게 되면 ) 직접적인 메모리 엑세스 타임에는
매우 큰 손실을 주게 되는 것이다. ( 캐쉬안에 존제된 연속된 채워진 혹은 비어있는 동일 크기의 페이지이므로 )
 
다시 한번 SLAB 부분 확인해 보고 결론을 들어가 보자.
[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 찍어보았다.
 
           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 >
 
로그 보자….
 
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 찍어보았다.
 
root@~]# crash /usr/lib/debug/lib/modules/2.6.18-194.3.1.el5/vmlinux vmcore20110128
………….생략…………….
      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 부터 찍어보자..
 
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 부분도 디스어셈코드를 보도록 하자 🙂
 
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 버그일수도 있겠는데………. 😛
( 사실 소스를 난 봤는데 sctp 쪽을 잘 몰라서 모르겠더라 )
 
자..그럼 이제 list_del 의 디스어셈코드를 확인 해 보자.
 
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
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 에 문자를 출력하는 시스템콜인거 설명해야되나 ㅡ.,ㅡ:: )
 
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 상태를 확인 할 수 있다.
 
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
 
 
분석과정#
 
      KERNEL: /usr/lib/debug/lib/modules/2.6.35.12-88.fc14.x86_64/vmlinux
    DUMPFILE: /var/crash/127.0.0.1-2011-04-21-19:37:30/vmcore
        CPUS: 4
        DATE: Thu Apr 21 19:37:24 2011
      UPTIME: 02:32:32
LOAD AVERAGE: 0.26, 0.56, 0.85
       TASKS: 509
    NODENAME: Mirr
     RELEASE: 2.6.35.12-88.fc14.x86_64
     VERSION: #1 SMP Thu Mar 31 21:21:57 UTC 2011
     MACHINE: x86_64  (2394 Mhz)
      MEMORY: 3.8 GB
       PANIC: “[ 9137.459831] Kernel panic – not syncing: stack-protector: Kernel stack is corrupted in: ffffffff81417249”
         PID: 8762
     COMMAND: “qemu-kvm”
        TASK: ffff88012e0f5d00  [THREAD_INFO: ffff88008ca78000]
         CPU: 2
       STATE: TASK_RUNNING (PANIC)
 
자.. 일단 여기서 보여주는 정보..매우 좋다.
PANIC 의 원인은 일단 PID 8762 를 할당받은 qemu-kvm 커맨드에서 kernel stack 이 잘못된 주소를 참조하여 stack-protector 가 동작해 싱크가 불가했다는 얘기이다.
어렵나? 일단 BT 찍어보자. 로그먼저 찍어보아도 좋다.
 
 
[ 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
 
 
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 소스에 어떤 논리적 오류라도 있는건가? 하여 소스를 확인해 보기로 했다.
 
 
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 코드내용중에
 
 /* 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 라고 붙는 주소다…라지만 공개되어있다.
 
여기의 설명에 따르면 다음과 같은 구조를 설명해 준다.
 
          <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 관련 패치좀 해보고 정상유무 확인해야겠다. 오래된건데 왜 적용을 안했을까… 흑..
 
 
 

서진우

슈퍼컴퓨팅 전문 기업 클루닉스/ 상무(기술이사)/ 정보시스템감리사/ 시스존 블로그 운영자

You may also like...

1 Response

  1. Thank you for your sharing. I am worried that I lack creative ideas. It is your article that makes me full of hope. Thank you. But, I have a question, can you help me?

페이스북/트위트/구글 계정으로 댓글 가능합니다.