귀차니즘을 무릅쓰고 덤프분석을 오랜만에 시행했다.
뭐 보고싶은사람들만 보도록 :P
이번에도 역시 내 노트북에서 발생한 커널 패닉이다.
Fedora16 으로 업그레이드를 했어야 하나,
귀차니즘으로 마냥 있다보니 Fedora 15 이다 아직.
대략적인 상황으로는 이녀석을 요즘은 내가 노트북이 그닥 필요없어진 경지
- 라기보단 그냥 없어도 되는일들인 - 인지라,
집에 놓고당기는데, 이녀석이 꼭 돌아와보면 먹통.
즉, Wakeup 이 안된다는점... 그래서 항상 강제리부팅을 해오다,
커널패닉이 왜 안떨어지지? 라며 Sysrq 를 이용해 강제 크래슁을 시켰더니
먹통은 아니더라.....
그래서 일단 커널덤프를 살펴보기로 마음먹었다.. 오랜만이다 +.,+
Kernel Ver. : 2.6.41.4-1.fc15
Machine : x86_64
분석과정
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 를 찍어보도록 하자.
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 및 Context Contain 과정에
문제가 생겨 데드락을 발생시켜 Hang-Up 을 일으킨 것이였다.
자..여기서 "그렇다면 문제는 커널 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 가 문제이기 때문에, ( BUG 로 나타나게 된 이유 )
위 문제를 해결하려면 나의 커널을 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-packagekitLoading 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!
# 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 모듈 다시 올려본 뒤 한참 대기모드에 넣어보면 비교가 가능 할 것이다. 우히힛
Add : 역시 잘 되는것 같다. 커널 업데이트 이후 행업은 없어졌다. :)
커널 덤프분석은 아무것도 아니다.
다만 프로그래밍 그리고 디버깅에 대한 막연한 두려움이 중요한 걸 찾아 낼 수 있는
눈을 흐리멍텅하게 가릴 뿐, 두려움 따위는 벗어던지고, 모르면 공부하면 되는거다.
Add 2 : 기존 커널분석 보러가기 ( Mirr's Springnote )
'Skills > mY Technutz' 카테고리의 다른 글
| HAL 데몬 사용하기 (Simple) (0) | 2012.04.03 |
|---|---|
| Enhanced Using Sar data collector (1) | 2012.03.18 |
| 오픈소스 VTL 드라이버 MHVTL 로 테잎사용환경 구축하기 (0) | 2011.12.26 |
| 마법의 도구 Testdisk 를 이용해 데이타복원하기. (2) | 2011.08.21 |
| Installable USB stick 만들기. (0) | 2011.07.27 |
