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: vmlinux2.4.2147.ELhugemem
DEBUGINFO: ./vmlinux2.4.2147.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.2147.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.01 2
8175870: 322e342e 37342d31 634c452e 6f747375 .4.2147.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 버그일수도 있겠는데.......... :P
( 사실 소스를 난 봤는데 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 라고 붙는 주소다...라지만 공개되어있다.
여기의 설명에 따르면 다음과 같은 구조를 설명해 준다.
재밌는건 소스코드를 비교해봤는데 패치가 이미 적용되어 있다.
혹시 몰라 lkml 을 뒤져본다.
http://lkml.org/lkml/2010/8/30/391
요로코롬 이번엔 ip_output.c 의 ip_fragment 함수에 대해 패치가 있다.
어...이건 적용이 안되어있다.
커밋된지 한참 된것같은데....뭐 일단 어찌됐든, KVM 에서 Host 와 Guest 간 브릿지 MTU 값에 대한 문제로 생긴 icmp 라우팅문제라는게 대략적 결론.
다른아저씨들처럼 아직 MTU 수정해서 테스트해보진 않았으나 (글작성후 할거임)
확실히 다시 해보니 동일한 내용으로 코어가 생성된다.
커널메일링에 있는대로 ip option 관련 패치좀 해보고 정상유무 확인해야겠다. 오래된건데 왜 적용을 안했을까... 흑..
Coredump Analysis 10#
이번에도 역시 내 노트북에서 발생한 커널 패닉이다.
Fedora16 으로 업그레이드를 했어야 하나, 귀차니즘으로 마냥 있다보니 Fedora 15 이다 아직.
대략적인 상황으로는 이녀석을 요즘은 내가 노트북이 그닥 필요없어진 경지 - 라기보단 그냥 없어도 되는일들인 - 인지라,
집에 놓고당기는데, 이녀석이 꼭 돌아와보면 먹통. 즉, Wakeup 이 안된다는점... 그래서 항상 강제리부팅을 해오다,
커널패닉이 왜 안떨어지지? 라며 Sysrq 를 이용해 강제 크래슁을 시켰더니 먹통은 아니더라.....
그래서 일단 커널덤프를 살펴보기로 마음먹었다.. 오랜만이다 +.,+
시스템 (OS) : Fedora 15 ( Lovelock )
Kernel Ver. : 2.6.41.4-1.fc15
Machine : x86_64
Memory : 4G
분석과정#
KERNEL: /usr/lib/debug/lib/modules/2.6.41.4-1.fc15.x86_64/vmlinux
DUMPFILE: /var/crash/127.0.0.1-2011-12-31-02:55:50/vmcore
CPUS: 4
DATE: Sat Dec 31 11:55:50 2011
UPTIME: 1 days, 16:02:09
LOAD AVERAGE: 89.57, 89.12, 89.00
TASKS: 398
NODENAME: Mirr-N
RELEASE: 2.6.41.4-1.fc15.x86_64
VERSION: #1 SMP Tue Nov 29 11:53:48 UTC 2011
MACHINE: x86_64 (2393 Mhz)
MEMORY: 3.8 GB
PANIC: "[143880.225534] Oops: 0002 [#1] SMP " (check log for details)
PID: 29800
COMMAND: "kworker/0:1"
TASK: ffff880107d32e60 [THREAD_INFO: ffff880112062000]
CPU: 0
STATE: TASK_RUNNING (PANIC)
자.. 일단 여기서 보여주는 정보..에서의 특징은 oops SMP 에 대한 패닉내용과, kworker 를 보면 알 수 있는데,
매직키를 이용한 커널덤프를 발생시켰음을 추측 해 볼 수 있다는 점.
언제나처럼 log 를 찍어보도록 하자.
crash> log
b7 d0 c1 e8 10 39 c2 74 07 f3 90 <0f> b7 17 eb f5 5d c3 55 48 89 e5 66 66 66 66 90 8b 07 89 c2 c1
[143763.111566] Call Trace:
[143763.111570] <IRQ> [<ffffffff8149ca36>] _raw_spin_lock+0xe/0x10
[143763.111589] [<ffffffffa040d866>] rtl_lps_leave+0x1c/0xea [rtlwifi]
[143763.111603] [<ffffffffa040f3cb>] _rtl_pci_ips_leave_tasklet+0xe/0x10 [rtlwifi]
[143763.111611] [<ffffffff8105cddb>] tasklet_action+0x7f/0xd2
[143763.111619] [<ffffffff8105d683>] __do_softirq+0xc9/0x1b5
[143763.111627] [<ffffffff81027719>] ? ack_APIC_irq+0x15/0x17
[143763.111634] [<ffffffff81014b35>] ? paravirt_read_tsc+0x9/0xd
[143763.111642] [<ffffffff814a542c>] call_softirq+0x1c/0x30
[143763.111649] [<ffffffff81010b45>] do_softirq+0x46/0x81
[143763.111657] [<ffffffff8105d94b>] irq_exit+0x57/0xb1
[143763.111663] [<ffffffff814a5d0e>] do_IRQ+0x8e/0xa5
[143763.111671] [<ffffffff8149ce2e>] common_interrupt+0x6e/0x6e
[143763.111675] <EOI> [<ffffffff8124bd80>] ? ip_compute_csum+0x34/0x34
[143763.111689] [<ffffffff8124be69>] ? delay_tsc+0x35/0x74
[143763.111697] [<ffffffff8124bdd9>] __delay+0xf/0x11
[143763.111704] [<ffffffff8124be07>] __const_udelay+0x2c/0x2e
[143763.111717] [<ffffffffa0424ac4>] rtl92s_phy_set_rf_power_state+0x50f/0x601 [rtl8192se]
[143763.111732] [<ffffffffa040dd55>] ? rtl_swlps_rf_sleep+0x177/0x177 [rtlwifi]
[143763.111746] [<ffffffffa040d393>] rtl_ps_set_rf_state+0xdd/0xe3 [rtlwifi]
[143763.111760] [<ffffffffa040dc5e>] rtl_swlps_rf_sleep+0x80/0x177 [rtlwifi]
[143763.111774] [<ffffffffa040dd82>] rtl_swlps_wq_callback+0x2d/0x83 [rtlwifi]
[143763.111782] [<ffffffff8106ed8c>] process_one_work+0x176/0x2a9
[143763.111790] [<ffffffff8106f89a>] worker_thread+0xda/0x15d
[143763.111798] [<ffffffff8106f7c0>] ? manage_workers+0x176/0x176
[143763.111805] [<ffffffff81072ce7>] kthread+0x84/0x8c
[143763.111813] [<ffffffff814a5334>] kernel_thread_helper+0x4/0x10
[143763.111821] [<ffffffff81072c63>] ? kthread_worker_fn+0x148/0x148
[143763.111829] [<ffffffff814a5330>] ? gs_change+0x13/0x13
[143763.182744] BUG: soft lockup - CPU#1 stuck for 22s! [kworker/u:1:11382]
[143763.182749] Modules linked in: tun ip6table_filter ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack xt_CHECKSUM iptable_mangle bridge ipv6 tcp_lp fuse ip6_tables ebtable_nat ebtables nfsd lockd nfs_acl auth_rpcgss sunrpc 8021q garp stp llc acpi_cpufreq mperf rfcomm bnep xfs btrfs zlib_deflate libcrc32c snd_hda_codec_hdmi snd_hda_codec_conexant snd_hda_intel arc4 rtl8192se rtlwifi mac80211 cfg80211 snd_hda_codec virtio_net kvm_intel kvm thinkpad_acpi btusb bluetooth uvcvideo videodev iTCO_wdt rfkill media joydev snd_hwdep snd_seq snd_seq_device snd_pcm snd_timer snd iTCO_vendor_support e1000e v4l2_compat_ioctl32 intel_ips i2c_i801 snd_page_alloc soundcore microcode wmi i915 drm_kms_helper drm i2c_algo_bit i2c_core video [last unloaded: scsi_wait_scan]
[143763.182853] CPU 1
[143763.182855] Modules linked in: tun ip6table_filter ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack xt_CHECKSUM iptable_mangle bridge ipv6 tcp_lp fuse ip6_tables ebtable_nat ebtables nfsd lockd nfs_acl auth_rpcgss sunrpc 8021q garp stp llc acpi_cpufreq mperf rfcomm bnep xfs btrfs zlib_deflate libcrc32c snd_hda_codec_hdmi snd_hda_codec_conexant snd_hda_intel arc4 rtl8192se rtlwifi mac80211 cfg80211 snd_hda_codec virtio_net kvm_intel kvm thinkpad_acpi btusb bluetooth uvcvideo videodev iTCO_wdt rfkill media joydev snd_hwdep snd_seq snd_seq_device snd_pcm snd_timer snd iTCO_vendor_support e1000e v4l2_compat_ioctl32 intel_ips i2c_i801 snd_page_alloc soundcore microcode wmi i915 drm_kms_helper drm i2c_algo_bit i2c_core video [last unloaded: scsi_wait_scan]
[143763.182958]
[143763.182963] Pid: 11382, comm: kworker/u:1 Not tainted 2.6.41.4-1.fc15.x86_64 #1 LENOVO 3249PQ9/3249PQ9
[143763.182972] RIP: 0010:[<ffffffff81085dc9>] [<ffffffff81085dc9>] do_raw_spin_lock+0x1e/0x25
[143763.182983] RSP: 0018:ffff8801011cbda0 EFLAGS: 00000293
[143763.182988] RAX: 000000000000b484 RBX: 0000000000000286 RCX: 0000000000002a3b
[143763.182994] RDX: 000000000000b481 RSI: 0000000000000286 RDI: ffff88012d3a9d74
[143763.182999] RBP: ffff8801011cbda0 R08: ffff88012d3a9408 R09: 00000000005b3607
[143763.183005] R10: 00000000005b3607 R11: ffff880137c92d00 R12: ffff8801011cbd28
[143763.183010] R13: 0000000000000000 R14: 0000000000000002 R15: 0000000101da448b
[143763.183017] FS: 0000000000000000(0000) GS:ffff880137c80000(0000) knlGS:0000000000000000
[143763.183023] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[143763.183029] CR2: 0000000000cbf000 CR3: 0000000001a05000 CR4: 00000000000026e0
[143763.183034] DR0: 0000000000000003 DR1: 00000000000000b0 DR2: 0000000000000001
[143763.183040] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[143763.183046] Process kworker/u:1 (pid: 11382, threadinfo ffff8801011ca000, task ffff880040d08000)
[143763.183051] Stack:
[143763.183055] ffff8801011cbdb0 ffffffff8149ca36 ffff8801011cbdd0 ffffffffa040dbaf
[143763.183064] ffff88012d3a9d40 ffff88012d3a8540 ffff8801011cbe00 ffffffffa040ac8c
[143763.183074] ffff88012d3a8540 0000000000000010 ffff88012cbe3800 ffffffffa03c0713
[143763.183083] Call Trace:
[143763.183091] [<ffffffff8149ca36>] _raw_spin_lock+0xe/0x10
[143763.183106] [<ffffffffa040dbaf>] rtl_swlps_rf_awake+0x54/0x6c [rtlwifi]
[143763.183119] [<ffffffffa040ac8c>] rtl_op_config+0x128/0x328 [rtlwifi]
[143763.183142] [<ffffffffa03c0713>] ? ieee80211_rx_mgmt_beacon+0x4d3/0x4d3 [mac80211]
[143763.183159] [<ffffffffa03b6fcb>] ieee80211_hw_config+0x102/0x107 [mac80211]
[143763.183182] [<ffffffffa03c0745>] ieee80211_dynamic_ps_disable_work+0x32/0x47 [mac80211]
[143763.183191] [<ffffffff8106ed8c>] process_one_work+0x176/0x2a9
[143763.183199] [<ffffffff8106f89a>] worker_thread+0xda/0x15d
[143763.183207] [<ffffffff8106f7c0>] ? manage_workers+0x176/0x176
[143763.183214] [<ffffffff81072ce7>] kthread+0x84/0x8c
[143763.183222] [<ffffffff814a5334>] kernel_thread_helper+0x4/0x10
[143763.183230] [<ffffffff81072c63>] ? kthread_worker_fn+0x148/0x148
[143763.183238] [<ffffffff814a5330>] ? gs_change+0x13/0x13
[143763.183242] Code: 00 00 10 00 74 05 e8 17 6e 1c 00 5d c3 55 48 89 e5 66 66 66 66 90 b8 00 00 01 00 f0 0f c1 07 0f b7 d0 c1 e8 10 39 c2 74 07 f3 90 <0f> b7 17 eb f5 5d c3 55 48 89 e5 66 66 66 66 90 8b 07 89 c2 c1
[143763.183313] Call Trace:
[143763.183320] [<ffffffff8149ca36>] _raw_spin_lock+0xe/0x10
[143763.183334] [<ffffffffa040dbaf>] rtl_swlps_rf_awake+0x54/0x6c [rtlwifi]
[143763.183348] [<ffffffffa040ac8c>] rtl_op_config+0x128/0x328 [rtlwifi]
[143763.183370] [<ffffffffa03c0713>] ? ieee80211_rx_mgmt_beacon+0x4d3/0x4d3 [macrash> bt
PID: 29800 TASK: ffff880107d32e60 CPU: 0 COMMAND: "kworker/0:1"
#0 [ffff880137c03640] machine_kexec at ffffffff8102ba1a
#1 [ffff880137c036b0] crash_kexec at ffffffff810925c1
#2 [ffff880137c03780] oops_end at ffffffff8149db69
#3 [ffff880137c037b0] no_context at ffffffff814930f1
#4 [ffff880137c03810] __bad_area_nosemaphore at ffffffff814932cb
#5 [ffff880137c03870] bad_area_nosemaphore at ffffffff814932ff
#6 [ffff880137c03880] do_page_fault at ffffffff8149fb96
#7 [ffff880137c03990] page_fault at ffffffff8149d0f5
[exception RIP: sysrq_handle_crash+22]
RIP: ffffffff812d6ed1 RSP: ffff880137c03a40 RFLAGS: 00010086
RAX: 0000000000000010 RBX: ffffffff81a70e20 RCX: 000000000000dc0e
RDX: 0000000000000000 RSI: 0000000000000046 RDI: 0000000000000063
RBP: ffff880137c03a40 R8: 0000000000000001 R9: 0000ffff00066c0a
R10: 0000ffff00066c0a R11: 0000000000000000 R12: 0000000000000004
R13: 0000000000000063 R14: 0000000000000002 R15: 0000000000000001
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
#8 [ffff880137c03a48] __handle_sysrq at ffffffff812d7464
#9 [ffff880137c03a88] sysrq_filter at ffffffff812d7655
#10 [ffff880137c03ac8] input_pass_event at ffffffff81381be6
#11 [ffff880137c03b28] input_handle_event at ffffffff8138320a
#12 [ffff880137c03b78] input_event at ffffffff8138330b
#13 [ffff880137c03bc8] atkbd_interrupt at ffffffff813886de
crash>
이번 것 역시 딱 보면 어디가 문제인지 알기 쉽게 나와있다.
그것은 바로 Spin_Lock 의 문제라는것! 고질적인 이놈의 스핀락 롹롹롹!!! 설마 LoveLock 이라는 릴리즈명 때문은 아니겠지? ㅎ
아무튼 눈에 띄는 그동안 알고 있던 내용들을 우선적으로 찾아보면, Spin Lock 으로 인해 CPU time 을 제대로 얻어오지 못했음을
직감적으로 알 수 있어야 한다. - 알고 있지 다들?
자, 그럼 이제 그 스택들을 살펴보도록 하자.
일단 IRQ 에 대한 spin lock 을 관리하는 raw_spin_lock 시스템 콜이 찍혀있음을 보았을때,
이것은 H/W 의 드라이버 혹은 H/W 관련된 문제임을 알 수 있다. - 그냥 그렇게 알면 된다.
그담에 눈여겨 볼것이 있다. 바로 rtl_lps_leave+0x1c/0xea [rtlwifi] 이녀석들인데!
눈치밥있다면 Realtek 관련 함수이지 않을까 라고 때려줘야 한다는 사실...
이것은 rtl92s_phy_set_rf_power_state+0x50f/0x601 [rtl8192se] 이녀석을 찾아보면 확실해진다.
그렇다! 내가 쓰고 있는 노트북인 IBM X201 모델에 들어있는 Realtek 무선랜카드는,
rtl8192SE 라는 드라이버를 사용하고 있으며, 이녀석은 커널에서 자체지원하지 않던 모델이라,
내가 직접 드라이버를 다운받아 컴파일하여 올려논 드라이버였다.
즉, 노트북이 대기모드나, 화면절약모드로 들어가있을때, 무선랜카드에서 전해지는 신호를 감지하거나,
유지시키는등의 Context Switching 과정에서 문제가 생겨 무한 데드락이 걸리는 현상이였던 것이다.
자..여기서 "그렇다면 문제는 커널 Spin Lock 이라고 내뱉을게 아니라, 드라이버 오류 Tained 를 뿝어야 하는거 아니냐!"
라는 맘에드는 예리한 인간이 있었으면 좋겠을려만... 나혼자 있는 상황이니 넘어가도록 하자.
항상 얘기하듯 이런건 일단 버그라고 뜬 부분이 있으니 버그질라를 찾아보도록 하자.
아주아주 깔쌈하게도, rtl_lps_leave 로 구글링을 하면 동일 버젼의 비슷한 부류의 커널 버그들을 알려주고 있는
RedHat Bugzilla 와, Kernel.org 가 여럿 발견된다.
https://bugzilla.redhat.com/show_bug.cgi?id=755154
http://thread.gmane.org/gmane.linux.kernel.wireless.general/81542/focus=81657
아주아주 간단하고도 친절스럽게, lps_leave 라는 함수는 Interrup context 로 부터 얼마든지 호출 될 수 있고,
이 과정에서 IRQ 에 대한 충돌이 일어나 Deadlock 에 진입 할 수도 있다는 간략한 설명이 있으며,
간단하게 IRQ 에 대한 스핀락 처리 함수를 Replace 하는 방법으로 해결 할 수 있다고 나와있다.
재밌게도 내가 컴파일해 사용하던 rtl8192se 의 드라이버에서는 당연히 spin_lock_irq 함수와,
spin_lock_irqsave 등의 함수들을 잘 사용하고 있었고, 역시 문제는 Kernel 에서 대기모드에서
활성모드로 전향하기 위한 irq spin lock 부분을 실제 처리해주는 모듈인 rtlwifi 가 문제이기 때문에,
위 문제를 해결하려면 나의 커널을 Fedora16 의 커널인 3.1대로 올리던가,
최소한 커널버젼 2.4.41.6-1.fc15 이상으로 올려야 한다고 한다.
문제는 위 버그질라에서 얘기하는 커널은 아직 Stable 커널이 아닌 Testing 커널이라는점,
어차피 나야 개인노트북이고, Fedora16 로 올라가야할 시간도 남아있으니 테스팅커널을 받아 이것저것 테스팅 해볼참이다.
테스팅 커널을 받는 방법은 다음과 같다.
[root@Mirr-N ~ ]# yum update kernel --enablerepo=updates-testing
Loaded plugins: fastestmirror, langpacks, presto, refresh-packagekit
Loading mirror speeds from cached hostfile
* fedora: ftp.cuhk.edu.hk
* rpmfusion-free: mirrors.163.com
* rpmfusion-free-updates: mirrors.163.com
* rpmfusion-nonfree-updates: ucmirror.canterbury.ac.nz
* updates: ftp.riken.jp
* updates-testing: ftp.riken.jp
Setting up Install Process
Resolving Dependencies
There are unfinished transactions remaining. You might consider running yum-complete-transaction first to finish them.
--> Running transaction check
---> Package kernel.x86_64 0:2.6.41.6-1.fc15 will be installed
--> Finished Dependency Resolution
--> Running transaction check
---> Package kernel.x86_64 0:2.6.40.6-0.fc15 will be erased
--> Finished Dependency Resolution
Dependencies Resolved
================================================================================
Package Arch Version Repository Size
================================================================================
Installing:
kernel x86_64 2.6.41.6-1.fc15 updates-testing 27 M
Removing:
kernel x86_64 2.6.40.6-0.fc15 @updates 110 M
Transaction Summary
================================================================================
Install 1 Package(s)
Remove 1 Package(s)
Total download size: 27 M
Is this ok [y/N]: y
Downloading Packages:
Setting up and reading Presto delta metadata
updates-testing/prestodelta | 4.2 kB 00:00
Processing delta metadata
Package(s) data still to download: 27 M
kernel-2.6.41.6-1.fc15.x86_64.rpm | 27 MB 02:04
Running rpm_check_debug
Running Transaction Test
Transaction Test Succeeded
Running Transaction
Installing : kernel-2.6.41.6-1.fc15.x86_64 1/2
Cleanup : kernel-2.6.40.6-0.fc15.x86_64 2/2
Removed:
kernel.x86_64 0:2.6.40.6-0.fc15
Installed:
kernel.x86_64 0:2.6.41.6-1.fc15
Complete!
[root@Mirr-N ~ ]# cat /etc/grub.conf
# grub.conf generated by anaconda
#
# Note that you do not have to rerun grub after making changes to this file
# NOTICE: You have a /boot partition. This means that
# all kernel and initrd paths are relative to /boot/, eg.
# root (hd0,0)
# kernel /vmlinuz-version ro root=/dev/mapper/vg_mirr-LogVol00
# initrd /initrd-[generic-]version.img
#boot=/dev/sda
default=0
timeout=0
splashimage=(hd0,0)/grub/splash.xpm.gz
hiddenmenu
title Fedora (2.6.41.6-1.fc15.x86_64)
root (hd0,0)
kernel /vmlinuz-2.6.41.6-1.fc15.x86_64 root=/dev/mapper/vg_mirr-LogVol00 ro rd_LVM_LV=vg_mirr/LogVol00 rd_LVM_LV=vg_mirr/LogVol01 rd_NO_LUKS rd_NO_MD rd_NO_DM LANG=ko_KR.UTF-8 KEYTABLE=us rhgb quiet crashkernel=192M
initrd /initramfs-2.6.41.6-1.fc15.x86_64.img
title Fedora (2.6.41.4-1.fc15.x86_64.debug)
root (hd0,0)
kernel /vmlinuz-2.6.41.4-1.fc15.x86_64.debug root=/dev/mapper/vg_mirr-LogVol00 ro rd_LVM_LV=vg_mirr/LogVol00 rd_LVM_LV=vg_mirr/LogVol01 rd_NO_LUKS rd_NO_MD rd_NO_DM LANG=ko_KR.UTF-8 KEYTABLE=us rhgb quiet crashkernel=192M
initrd /initramfs-2.6.41.4-1.fc15.x86_64.debug.img
title Fedora (2.6.41.4-1.fc15.x86_64)
root (hd0,0)
kernel /vmlinuz-2.6.41.4-1.fc15.x86_64 root=/dev/mapper/vg_mirr-LogVol00 ro rd_LVM_LV=vg_mirr/LogVol00 rd_LVM_LV=vg_mirr/LogVol01 rd_NO_LUKS rd_NO_MD rd_NO_DM LANG=ko_KR.UTF-8 KEYTABLE=us rhgb quiet crashkernel=192M
initrd /initramfs-2.6.41.4-1.fc15.x86_64.img
아주 간단하게 인스톨 되었다.
이제 부팅 후 Realtek 모듈 다시 올려본 뒤 한참 대기모드에 넣어보면 비교가 가능 할 것이다. 우히힛
역시 패치해보니 잘 행업 없이 잘 동작함을 확인 할 수 있었다. :)
http://blog.daum.net/ckcjck/15
tail.exe
