Arm Linux Kernel Hacks

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

[Kernel][Panic] crash due to "signature and/or required key missing" (0)	2023.05.07
[Linux][Kernel]뮤텍스 데드락(Mutex Deadlock) 락업(lockup) - "simpleperf" 디버깅 (0)	2023.05.07
[Linux][Kernel] panic@___might_sleep (0)	2023.05.07
[Linux][Kernel][Stability] Kernel panic @0x0 from xfrm_local_error+0x4c (0)	2023.05.07
[Kernel][Debug] "cat /d/shrinker" kernel panic (0)	2023.05.07

[Linux][Kernel] panic@___might_sleep

AustinKim 2023. 5. 7. 17:45

2023. 5. 7. 17:45

#커널 크래시 디버깅 및 TroubleShooting

리눅스 커널 synchronization의 꽃 중의 하나인 Mutex Lock에 대해서 조금 짚어 볼께요. Mutex Lock은 보통 스핀락(Spinlock)과 많이 비교하죠. 사실 소스 코드를 보면 Mutex Lock이 스핀락보다 훨씬 소프트웨어적으로 복잡해요. 그 이유는?

1> Mutex Lock을 잠근 프로세스만 해제할 수 있어요

2> 이미 다른 프로세스가 Mutex Lock을 획득한 상태면 struct mutex.wait_list에 대기하고 Wait Queue에 넣고

잠들어야 해요.

음, 이 소리는. Mutex Lock을 잡고 있는 프로세스가 Mutex Lock을 해제하면 누군가가 다시 대기 중이던 프로세스를 WaitQueue에서 끄집어 내서 런큐에 큐잉을 해줘야겠죠.

마지막으로 Mutex Lock을 잡는 동작에서 Sanity-Check을 해주는 루틴이 있어요. 이 역할을 하는 함수가 ___might_sleep()이거든요. 함수의 구현부는 아래와 같은데요. 아래 if문 3개의 조건을 만족하면 return되는데, return이 안되면 커널 크래시가 기다리고 있어요.

void ___might_sleep(const char *file, int line, int preempt_offset)

{

static unsigned long prev_jiffy; /* ratelimiting */

unsigned long preempt_disable_ip;

rcu_sleep_check(); /* WARN_ON_ONCE() by default, no rate limit reqd. */

if ((preempt_count_equals(preempt_offset) && !irqs_disabled() && //<<--

!is_idle_task(current)) || oops_in_progress)

return;

if (system_state != SYSTEM_RUNNING &&

(!__might_sleep_init_called || system_state != SYSTEM_BOOTING))

return;

if (time_before(jiffies, prev_jiffy + HZ) && prev_jiffy)

return;

prev_jiffy = jiffies;

/* Save this before calling printk(), since that will clobber it */

preempt_disable_ip = get_preempt_disable_ip(current);

printk(KERN_ERR

"BUG: sleeping function called from invalid context at %s:%d\n",

file, line);

printk(KERN_ERR

"in_atomic(): %d, irqs_disabled(): %d, pid: %d, name: %s\n",

in_atomic(), irqs_disabled(),

current->pid, current->comm);

//snip

#ifdef CONFIG_PANIC_ON_SCHED_BUG

BUG(); //<←

그런데 위 코드에서 커널 패닉이 죽는 덤프를 봤거든요.

콜스택은 아래와 같구요. Binder 드라이버에서 Mutex Lock을 잡는 동작에서 커널 크래시가 발생한 거네요.

-000|do_debug_exception(addr = 0, esr = 0, regs = 0x0)

-001|el1_dbg(asm)

-->|exception

-002|___might_sleep(file = 0xFFFFFF8BA9C4C2F3, ?, ?) //<<-- panic

-003|__might_sleep(file = 0xFFFFFF8BA9C4C2F3, line = 98, preempt_offset = 0)

-004|mutex_lock(lock = 0xFFFFFFCCF32FC938)

-005|binder_defer_work(proc = 0xFFFFFFCCE000FC80, ?)

-006|binder_flush(filp = 0xFFFFFFCC998D8300, ?)

-007|filp_close(filp = 0xFFFFFFCC998D8300, id = 0xFFFFFFCD472DBAC0)

-008|__close_fd(files = 0xFFFFFFCD472DBAC0, ?)

-009|task_close_fd.isra.33(?)

-010|binder_transaction_buffer_release(proc = 0xFFFFFFCD46098480, buffer = 0xFFFFFF801F12D270, failed_at

-011|binder_transaction(?, thread = 0xFFFFFFCCE000EC80, tr = 0xFFFFFFCCA944BC30, ?, extra_buffers_size =

-012|binder_thread_write(proc = 0xFFFFFFCCE000FC80, thread = 0xFFFFFFCCE000EC80, ?, ?, consumed = 0xFFFFF

-013|binder_ioctl_write_read(filp = 0xFFFFFFCC998D8300, ?, arg = 549020159624, thread = 0xFFFFFFCCE000EC8

-014|binder_ioctl(filp = 0xFFFFFFCC998D8300, cmd = 3224396289, arg = 549020159624)

-015|vfs_ioctl(inline)

-015|do_vfs_ioctl(filp = 0xFFFFFFCC998D8300, fd = 1, ?, arg = 549020159624)

-016|SYSC_ioctl(inline)

-016|sys_ioctl(fd = 1, cmd = 3224396289, arg = 549020159624)

커널 패닉이 발생한 이유는 해당 프로세스의 struct thread_info의 preempt_count값이 2이기 때문이죠.

(struct thread_info*)(0xffffffcca944b880 & ~0x3fff) = 0xFFFFFFCCA9448000 -> (

flags = 0x2,

addr_limit = 0x0000008000000000,

task = 0xFFFFFFCD03CC1FC0,

ttbr0 = 0x44510000BB944000,

preempt_count = 0x2, //<<--

cpu = 0x6)

다시 말하자면, preempt_disable() 함수를 두 번 호출했다는 거죠.

preempt_disable()의 구현부를 보면, 간단히 struct thread_info.preempt_count 값만 +1시키고 있어요.

#define preempt_disable() \

do { \

preempt_count_inc(); \

barrier(); \

} while (0)

사실 이 값 struct thread_info.preempt_count이 0이어야만 preemption이 되어 스케쥴이 가능하거든요. 그 이유는 다른 섹션에서 다루기로 하구요. (어셈블코드 리뷰가 필요할 것 같네요.)

아무리 눈을 씻고 찾아봐도, 그리 논리적 오류가 될만한 코드가 없어 보여서,

아래와 같은 패치를 반영했더니, 크래시는 사라졌어요.

원리는 잠시 preempt_count를 -1 시켜서 _mutex_sleep에서 크래시를 회피하고 이후,

다시 원래 값으로 돌리는 거죠.

diff --git a/drivers/android/binder.c b/drivers/android/binder.c

index d1490be..eea603b 100644

--- a/drivers/android/binder.c

+++ b/drivers/android/binder.c

@@ -458,7 +458,9 @@ static long task_close_fd(struct binder_proc *proc, unsigned int fd)

if (proc->files == NULL)

return -ESRCH;

+ preempt_enable_no_resched();

retval = __close_fd(proc->files, fd);

+ preempt_disable();

/* can't restart close syscall because file table entry was cleared */

if (unlikely(retval == -ERESTARTSYS ||

retval == -ERESTARTNOINTR ||

관련 매크로는 아래 코드를 참고하세요.

#define preempt_enable_no_resched() sched_preempt_enable_no_resched()

#define sched_preempt_enable_no_resched() \

do { \

barrier(); \

preempt_count_dec(); \

} while (0)

#define __preempt_count_dec() __preempt_count_sub(1)

# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

[Linux][Kernel]뮤텍스 데드락(Mutex Deadlock) 락업(lockup) - "simpleperf" 디버깅 (0)	2023.05.07
[Linux][Kernel] Kernel Panic @__stack_chk_fail - 스택 카나리 (Stack canary Feature) (0)	2023.05.07
[Linux][Kernel][Stability] Kernel panic @0x0 from xfrm_local_error+0x4c (0)	2023.05.07
[Kernel][Debug] "cat /d/shrinker" kernel panic (0)	2023.05.07
[Linux-Kernel][Debug]kernel panic@mmc_wait_data_done (0)	2023.05.07

[Linux][Kernel][Stability] Kernel panic @0x0 from xfrm_local_error+0x4c

AustinKim 2023. 5. 7. 17:44

2023. 5. 7. 17:44

#커널 크래시 디버깅 및 TroubleShooting

커널 패닉이 났어요.

네트워크 드라이버 리눅스 커널 코드에서 발생한 것 같은데요. 음.

일단 당황하지 마시구요. 차근 차근 커널 로그와 코어 덤프를 살펴보면, 정답이 나와요.

일단 커널 로그를 보면, 프로그램 카운터가 0x0을 가르키고 있네요.

음... 그리고

링크 레지스터(R14)가 0xc0adc274(LR is at xfrm_local_error+0x4c/0x58) 을 가르키고 있습니다.

[ 262.401303] Unable to handle kernel NULL pointer dereference at virtual address 00000000

[ 262.401365] pgd = dbdc4000

[ 262.401389] [00000000] *pgd=00000000

[ 262.401433] Internal error: Oops: 80000005 [#1] PREEMPT SMP ARM

[ 262.401459] Modules linked in:

[ 262.401495] CPU: 0 PID: 7107 Comm: Framework Tainted: G W 3.10.49-g356bd9f-00007-gadca646 #1

[ 262.401522] task: da6b0540 ti: d9412000 task.ti: d9412000

[ 262.401549] PC is at 0x0

[ 262.401590] LR is at xfrm_local_error+0x4c/0x58

[ 262.401619] pc : [<00000000>] lr : [<c0adc274>] psr: a00f0013

[ 262.401619] sp : d9413c68 ip : c0ac6c20 fp : 0000dd86

[ 262.401654] r10: 0000010e r9 : 0000010a r8 : de0ddc20

[ 262.401678] r7 : c13ddf00 r6 : 00000500 r5 : d9094540 r4 : c13e3780

[ 262.401703] r3 : 00000000 r2 : 00000001 r1 : 00000500 r0 : d9094540

일단 커널 로그에서 R14가 가르키는(커널 패닉이 발생한 함수를 호출한) 주소로 가보면요.

R3를 branch instruction으로 수행하고 있었습니다. 이런 Instruction은 함수 포인터로 함수를 호출할 때 쓰이죠.

그런데 커널 로그에서 R3이 0x0이라고 하네요.

NSR:C0ADC264|E1A00005 cpy r0,r5 ; proto,skb

NSR:C0ADC268|E594344C ldr r3,[r4,#0x44C]

NSR:C0ADC26C|E1A01006 cpy r1,r6 ; r1,mtu

NSR:C0ADC270|E12FFF33 blx r3 //<<--

아 이제, 커널 로그가 가르키는 스택 주소 0xd9413c68로 좀 가볼까요?

d.v %y.l 0xD9413C68

______address|_data________|value_____________|symbol

NSD:D9413C60| 13 00 0F A0 0xA00F0013

NSD:D9413C64| FF FF FF FF 0xFFFFFFFF

NSD:D9413C68| 40 45 09 D9 0xD9094540 // <<-R4

NSD:D9413C6C| 00 0C 42 DC 0xDC420C00 //<<--R5

NSD:D9413C70| 40 45 09 D9 0xD9094540 //<<-- R6

NSD:D9413C74| 0C 11 AD C0 0xC0AD110C \vmlinuxxfrm4_output__xfrm4_output+0xE4 //<<--R14

NSD:D9413C78| 00 00 00 00 0x0

NSD:D9413C7C| 01 00 00 00 0x1

NSD:D9413C80| 00 0C 42 DC 0xDC420C00

NSD:D9413C84| 6C C0 AD C0 0xC0ADC06C \vmlinuxxfrm_outputxfrm_output_resume+0x41C

@D9413C74 스택 주소를 보니, 0xC0AD110C 즉 __xfrm4_output+0xE4 주소를 볼 수 있는데요.

0xC0AD110C 주소를 가보니, xfrm_local_error란 함수를 branch operation으로 수행을 하네요.

______addr/line|code_____|label____|mnemonic________________|comment

NSR:C0AD1104|E1A00004 cpy r0,r4 ; r0,skb

NSR:C0AD1108|EB002C46 bl 0xC0ADC228 ; xfrm_local_error

xfrm_local_error() 함수 초반 ARM Instruction을 보면, R14, R6, R5, R4 순으로 스택에 Push를 하네요.

NSR:C0ADC228|E92D4070 xfrm_local_error: push {r4-r6,r14}

NSR:C0ADC22C|E1A05000 cpy r5,r0 ; skb,pr

예를 들면, 이런 거죠. 스택에 이렇게 Push를 하고나면 새로운 스택 주소는 D9413C68(<-D9413C74)가 되는거죠.

stack 주소

D9413C68 R4을 스택에 Push =>> 0xD9094540

D9413C6C R5을 스택에 Push =>> 0xDC420C00

D9413C70 R6을 스택에 Push =>> 0xD9094540

D9413C74 R14 주소 스택에 Push =>> 0xC0AD110C

이렇게 새로운 함수가 호출될 때 스택에 파라미터를 Push하는 규칙은 CPU 아키텍쳐마다 다르거든요.

위의 경우에는 ARM32 아키텍처 Calling Convention에 따른 거에요.

ARM 스팩 문서를 보시면 위 내용이 자세히 나와 있어요.

자 다시 커널 로그로 돌아가 봅시다.

[ 262.401495] CPU: 0 PID: 7107 Comm: BaldTainted: G W 3.10.49-g356bd9f-00007-gadca646 #1

[ 262.401522] task: da6b0540 ti: d9412000 task.ti: d9412000

[ 262.401549] PC is at 0x0

[ 262.401590] LR is at xfrm_local_error+0x4c/0x58

[ 262.401619] pc : [<00000000>] lr : [<c0adc274>] psr: a00f0013

[ 262.401619] sp : d9413c68 ip : c0ac6c20 fp : 0000dd86

T32 프로그램으로,

커널 로그에서 찍힌 LR을 프로그램 카운터로 설정하고, 스택 주소는 그대로 설정 그리고 위 스택 정보에서 살펴본 0xC0AD110C(__xfrm4_output+0xE4) 주소를

설정하면. 이렇게 이쁘게 콜 스택이 보이네요.

-000|xfrm_local_error(skb = 0xDCD376C0, mtu = -611987776)

-001|__xfrm4_output(skb = 0xD9094540)

-002|xfrm_output_resume(skb = 0xD9094540, err = 1)

-003|__xfrm4_output(skb = 0xD9094540)

-004|ip_local_out(skb = 0xD9094540)

-005|ip_send_skb(net = 0xC13DDF00, ?)

-006|udp_send_skb(skb = 0xD9094540, ?)

-007|udp_sendmsg(?, sk = 0xDE0F1680, msg = 0xD9413EE0, len = 1300)

-008|inet_sendmsg(iocb = 0xD9413E58, ?, msg = 0xD9413EE0, size = 1300)

-009|sock_sendmsg(sock = 0xDA9A5500, msg = 0xD9413EE0, size = 1300)

-010|SYSC_sendto(inline)

-010|sys_sendto(?, buff = -1997588480, ?, ?, addr = -1985806992, addr_len = 16)

-011|ret_fast_syscall(asm)

T32 명령어는 아래와 같아요.

r.s R13 0xD9413C68

r.s R14 0xC0AD110C

r.s PC 0xC0ADC270

0xC0ADC270 주소에 다시 가볼까요? R3가 어떻게 0x0으로 업데이트되는지 봐야겠죠.

확인해보니, ldr r3,[r4,#0x44C] 명령어로 업데이트 되네요.

NSR:C0ADC264|E1A00005 cpy r0,r5 ; proto,skb

NSR:C0ADC268|E594344C ldr r3,[r4,#0x44C]

NSR:C0ADC26C|E1A01006 cpy r1,r6 ; r1,mtu

NSR:C0ADC270|E12FFF33 blx r3

0xC0ADC270 주소로 실제 소스 코드 위치를 알면 좋을 상황인데요. T32에서 이런 상황에서 아주 유용한 커맨드를 제공해요.

y.l.line 0xC0ADC270

__________address________|module__________________________________|source________|line______|o

P:C0ADC25C--C0ADC263|\vmlinuxxfrm_output |.1/android/kernel/net/xfrm/xfrm_output.c|247--247 |

P:C0ADC264--C0ADC273|\vmlinuxxfrm_output |.1/android/kernel/net/xfrm/xfrm_output.c|248--250 |

음, kernel/net/xfrm/xfrm_output.c의 248--250 라인인 것 같네요.

역시나, 실제 소스 코드를 보면 함수 포인터(콜백 함수 형태)로 함수를 호출하고 있네요.

234void xfrm_local_error(struct sk_buff *skb, int mtu)

235{

236 unsigned int proto;

237 struct xfrm_state_afinfo *afinfo;

238

// ...생략...

245

246 afinfo = xfrm_state_get_afinfo(proto);

247 if (!afinfo)

248 return;

249

250 afinfo->local_error(skb, mtu); //<<--

251 xfrm_state_put_afinfo(afinfo);

struct xfrm_state_afinfo란 구조체에서 local_error란 멤버의 오프셋 주소가 얼마인지 알아볼까요?

예를 들어서, bald_manager란 구조체가 있으면, issue 멤버는 0x4, issue_list 멤버는 0x8 오프셋이라고 볼 수 있어요.

struct bald_manager {

int phone;

int issue;

struct list_head issue_list;

};

음, 이럴 때 커널 패닉을 디버깅하는 Crash Tool이란 좋은 툴에서 아주 유용한 기능을 제공하거든요.

아래와 같은 명령어를 입력하면, local_error 멤버의 오프셋이 0x44c임을 알 수 있어요.

crash> struct -o xfrm_state_afinfo.local_error

struct xfrm_state_afinfo {

[0x44c] void (*local_error)(struct sk_buff *, u32);

}

어떤 T32 매니아가 저에게 질문을 던지네요.

음 T32로는 확인할 수 없냐구요? 아래 매크로 기능으로 확인 가능해요.

T32로 아래 명령어를 입력하면 되요.

sYmbol.NEW.MACRO offsetof(type,member) ((int)(&((type*)0)->member))

이게 제가 뚝딱만든 코드는 아니구요. 이미 리눅스 커널 코드에 있는 매크로를 그대로 가져온 거거든요.

[android/kernel/include/linux/stddef.h]

#define offsetof(TYPE, MEMBER) ((size_t) &((TYPE *)0)->MEMBER)

요렇게 입력하면 똑같은 0x044C 오프셋 주소를 확인할 수 있어요. T32로 디버깅할 때 자주 쓰면 좋아요.

v.v %h offsetof(struct xfrm_state_afinfo,local_error)

offsetof(struct xfrm_state_afinfo,local_error) = 0x044C

자, 이제 0xC0ADC270 주소에 다시 가보면 [1] instruction이 afinfo->local_error(skb, mtu); 함수 라인에 매핑되는 걸 알 수 있어요.

NSR:C0ADC264|E1A00005 cpy r0,r5 ; proto,skb

NSR:C0ADC268|E594344C ldr r3,[r4,#0x44C] //<<--[1]

250 afinfo->local_error(skb, mtu); //<<--[1]

NSR:C0ADC26C|E1A01006 cpy r1,r6 ; r1,mtu

NSR:C0ADC270|E12FFF33 blx r3

커널 패닉 시 로그를 다시 보면, R4가 0xc13e3780이거든요.

이 값을 T32로 (struct xfrm_state_afinfo *) 타입으로 캐스팅해서 올려보면, local_error값이 0x0이네요.

어라, 그리고 0xC13E3780 주소의 정체가 xfrm4_state_afinfo란 전역 벼수라는 것도 알 수 있네요.

v.v %all (struct xfrm_state_afinfo *)0xc13e3780

(struct xfrm_state_afinfo *) (struct xfrm_state_afinfo *)0xc13e3780 = 0xC13E3780 = xfrm4_state_afinfo -> (

(unsigned int) family = 2 = 0x2 = '....',

(unsigned int) proto = 4 = 0x4 = '....',

(__be16) eth_proto = 8 = 0x8 = '..',

(struct module *) owner = 0x0 = -> NULL,

(struct xfrm_type * [256]) type_map = ([0] = 0x0 = -> NULL, [1] = 0x0 = -> NULL, [2] = 0x0 = -> NULL, [3] = 0

(struct xfrm_mode * [5]) mode_map = ([0] = 0xC13E31D8 = xfrm4_transport_mode -> ((int (*)()) input2 = 0x0 = , (i

(int (*)()) init_flags = 0xC0AD0AD0 = xfrm4_init_flags -> ,

(void (*)()) init_tempsel = 0xC0AD0B6C = __xfrm4_init_tempsel -> ,

(void (*)()) init_temprop = 0xC0AD0AF4 = xfrm4_init_temprop -> ,

(int (*)()) tmpl_sort = 0x0 = -> NULL,

(int (*)()) state_sort = 0x0 = -> NULL,

(int (*)()) output = 0xC0AD12E4 = xfrm4_output -> ,

(int (*)()) output_finish = 0xC0AD129C = xfrm4_output_finish -> ,

(int (*)()) extract_input = 0xC0AD0D8C = xfrm4_extract_input -> ,

(int (*)()) extract_output = 0xC0AD11E0 = xfrm4_extract_output -> ,

(int (*)()) transport_finish = 0xC0AD0D94 = xfrm4_transport_finish -> ,

(void (*)()) local_error = 0x0 = -> NULL) //<<--

이제 정리 좀 하면.

afinfo->local_error(skb, mtu); 주소가 0x0이라서 커널 패닉으로 타겟이 크래시가 난 거에요.

참, 결론은 허무하죠. 대부분의 커널 패닉 문제는 허무하게 끝납니다.

아 이제, 코드 리뷰를 해볼 시간인데. xfrm4_state_afinfo란 변수 선언문을 가보았더니 에서 local_error 멤버를 초기화하지 않고 있네요.

[kernel/net/ipv4/xfrm4_state.c]

static struct xfrm_state_afinfo xfrm4_state_afinfo = {

.family = AF_INET,

.proto = IPPROTO_IPIP,

.eth_proto = htons(ETH_P_IP),

.owner = THIS_MODULE,

.init_flags = xfrm4_init_flags,

.init_tempsel = __xfrm4_init_tempsel,

.init_temprop = xfrm4_init_temprop,

.output = xfrm4_output,

.output_finish = xfrm4_output_finish,

.extract_input = xfrm4_extract_input,

.extract_output = xfrm4_extract_output,

.transport_finish = xfrm4_transport_finish,

};

아래와 같이 local_error 멤버에 대한 콜백 함수를 추가하는 코드를 추가하니 커널 패닉 증상은 사라졌습니다.

diff --git a/net/ipv4/xfrm4_state.c b/net/ipv4/xfrm4_state.c

index 9258e75..0b2a064 100644

--- a/net/ipv4/xfrm4_state.c

+++ b/net/ipv4/xfrm4_state.c

@@ -83,6 +83,7 @@ static struct xfrm_state_afinfo xfrm4_state_afinfo = {

.extract_input = xfrm4_extract_input,

.extract_output = xfrm4_extract_output,

.transport_finish = xfrm4_transport_finish,

+ .local_error = xfrm4_local_error,

};

# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

https://chromium-review.googlesource.com/c/345895/

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

[Linux][Kernel]뮤텍스 데드락(Mutex Deadlock) 락업(lockup) - "simpleperf" 디버깅 (0)	2023.05.07
[Linux][Kernel] Kernel Panic @__stack_chk_fail - 스택 카나리 (Stack canary Feature) (0)	2023.05.07
[Linux][Kernel] panic@___might_sleep (0)	2023.05.07
[Kernel][Debug] "cat /d/shrinker" kernel panic (0)	2023.05.07
[Linux-Kernel][Debug]kernel panic@mmc_wait_data_done (0)	2023.05.07

[Kernel][Debug] "cat /d/shrinker" kernel panic

AustinKim 2023. 5. 7. 17:42

2023. 5. 7. 17:42

#커널 크래시 디버깅 및 TroubleShooting

100% 커널 패닉으로 타겟이 죽어버리는 이슈를 발견했어요.

자자, 일단 커널 로그부터 좀 볼까요?

뭐, PID가 6978이 sh 프로세스에서 do_raw_spin_lock() 함수에서 데이터 어보트를 유발시켰네요.

[ 761.636711] Unable to handle kernel paging request at virtual address f38a9a84

[ 761.645048] pgd = e8074000

[ 761.649800] [f38a9a84] *pgd=a0721811, *pte=00000000, *ppte=00000000

[ 761.658106] Internal error: Oops: 7 [#1] PREEMPT SMP ARM

[ 761.665481] Modules linked in:

[ 761.670605] CPU: 6 PID: 6978 Comm: sh Tainted: G W 3.18.31-g5b0528e-dirty #12

[ 761.680852] task: eb5b8000 ti: d228e000 task.ti: d228e000

[ 761.688315] PC is at do_raw_spin_lock+0x8/0x17c

[ 761.694912] LR is at list_lru_count_node+0x14/0x60

//--- skip ---

[ 761.885719] [<c016a650>] (do_raw_spin_lock) from [<c02057f4>] (list_lru_count_node+0x14/0x60)

[ 761.896307] [<c02057f4>] (list_lru_count_node) from [<c022dffc>] (super_cache_count+0x40/0x94)

[ 761.906982] [<c022dffc>] (super_cache_count) from [<c01f2708>] (debug_shrinker_show+0x44/0x7c)

[ 761.917658] [<c01f2708>] (debug_shrinker_show) from [<c024a56c>] (seq_read+0x1a4/0x3f0)

[ 761.927726] [<c024a56c>] (seq_read) from [<c022c87c>] (vfs_read+0x88/0x138)

[ 761.936755] [<c022c87c>] (vfs_read) from [<c022cda8>] (SyS_read+0x3c/0x7c)

[ 761.945695] [<c022cda8>] (SyS_read) from [<c0106840>] (ret_fast_syscall+0x0/0x38)

[ 761.955242] Code: e12fff1e deaf1eed e92d47f0 e1a08000 (e5902004)

T32로 코어덤프를 올려서 콜스택을 잡아 봤어요.

do_raw_spin_lock() 함수 내에서 debug_spin_lock_before() 함수 호출을 하는데,

debug_spin_lock_before()는 spinlock 멤버 변수의 sanity-checkf를 하거든요. 그 동작에서 크래시가 난 거죠.

-000|do_DataAbort(addr = 170, fsr = 3247439880, regs = 0xEC4901C0)

-001|__dabt_svc(asm)

-->|exception

-002|debug_spin_lock_before(inline) //<<-- data abort

-002|do_raw_spin_lock(lock = 0xF38A9A80)

-003|list_lru_count_node(?, ?)

-004|super_cache_count(shrink = 0xEBC47DE0, sc = 0xD228FEF8)

-005|debug_shrinker_show(s = 0xE7CF63C0, ?)

-006|seq_read(file = 0xE805CA00, buf = 0xB3246000, size = 4096, ppos = 0xD228FF80)

-007|vfs_read(file = 0xFFFFFFFF, buf = 0x0, ?, pos = 0xD228FF80)

-008|SYSC_read(inline)

-008|sys_read(?, buf = -1289461760, count = 4096)

-009|ret_fast_syscall(asm)

스핀락 값을 좀 더 살펴봤더니, 역시나.

owner, next값이 왕창 깨져있네요. next는 owner보다 같거나(스핀락 해제), 1만큼만 크거든요.(스핀락 획득)

(register raw_spinlock_t *) [R0] lock = 0xF38A9A80 -> (

(arch_spinlock_t) [NSD:0xF38A9A80] raw_lock = (

(u32) [NSD:0xF38A9A80] slock = 0x6F632F34,

(struct __raw_tickets) [NSD:0xF38A9A80] tickets = (

(u16) [NSD:0xF38A9A80] owner = 0x2F34, //<<--

(u16) [NSD:0xF38A9A82] next = 0x6F63)), //<<--

(unsigned int) [NSD:0xF38A9A84] magic = 0x6E6F6D6D //<<--

(unsigned int) [NSD:0xF38A9A88] owner_cpu = 0x6F6F675F,

(void *) [NSD:0xF38A9A8C] owner = 0x5F656C67))

spin_lock 변수가 어디서 호출되었는지 살펴보면, &lru->node[nid]; 이네요.

list_lru_count_node() 함수의 첫 번째 파라미터로 넘어온 거죠.

51unsigned long

52list_lru_count_node(struct list_lru *lru, int nid)

53{

54 unsigned long count = 0;

55 struct list_lru_node *nlru = &lru->node[nid]; <<--

57 spin_lock(&nlru->lock);

The list_lru_count_node() 함수 출처를 살펴보면, super_cache_count() 함수 내 &sb->s_dentry_lru 로컬변수이네요.

08static unsigned long super_cache_count(struct shrinker *shrink,

109 struct shrink_control *sc)

110{

111 struct super_block *sb;

112 long total_objects = 0;

113

114 sb = container_of(shrink, struct super_block, s_shrink);

//snip

124 if (sb->s_op && sb->s_op->nr_cached_objects)

125 total_objects = sb->s_op->nr_cached_objects(sb,

126 sc->nid);

127

128 total_objects += list_lru_count_node(&sb->s_dentry_lru, //<<--

129 sc->nid);

이제 super_cache_count() 함수를 호출한 흐름을 따라가보면,

debug_shrinker_show() 함수 내 shrinker->count_objects(shrinker, &sc); 루틴임을 알 수 있어요.

205static int debug_shrinker_show(struct seq_file *s, void *unused)

206{

207 struct shrinker *shrinker;

208 struct shrink_control sc;

209

210 sc.gfp_mask = -1;

211 sc.nr_to_scan = 0;

212

213 down_read(&shrinker_rwsem);

214 list_for_each_entry(shrinker, &shrinker_list, list) {

215 int num_objs;

216

217 num_objs = shrinker->count_objects(shrinker, &sc); //<<-- shrinker->count_objects = super_cache_count

자자, 이제 좀 정리 좀 해볼까요?

함수에 따라 호출된 변수의 흐름을 살펴보죠.

1. super_cache_count() 함수에서 shrinker->count_objects(shrinker, &sc); 를 호출하죠.

2. list_lru_count_node(&sb->s_dentry_lru, sc->nid); // &sb->s_dentry_lru, sc->nid 변수를 파라미터로 넘기네요.

3. list_lru_count_node(struct list_lru *lru, int nid) // <<-- nid 파라미터 즉 sc->nid로 넘어온 값이 쓰레기 값이네요.

3.1 struct list_lru_node *nlru = &lru->node[nid]; // &lru->node[nid]; &lru->node[쓰레기값];

3.2 spin_lock(&nlru->lock); // &nlru->lock: 쓰레기 주소 접근

debug_shrinker_show() 함수에서 선언된 struct shrink_control sc 로컬 변수를 초기화하지 않고 Call-by-value로 호출하는게 문제였어요.

구글링을 해보니, 이미 구글에서 패치를 릴리즈했네요. 좀 미리 문제를 알았으면 오픈 소스에 Contribution할 수 있었는데 아쉽네요.

Commit log

ANDROID: Revert "mm: vmscan: Add a debug file for shrinkers"

Kernel panic when type "cat /sys/kernel/debug/shrinker"

Unable to handle kernel paging request at virtual address 0af37d40

pgd = d4dec000

[0af37d40] *pgd=00000000

Internal error: Oops: 5 [#1] PREEMPT SMP ARM

[<c0bb8f24>] (_raw_spin_lock) from [<c020aa08>] (list_lru_count_one+0x14/0x28)

[<c020aa08>] (list_lru_count_one) from [<c02309a8>] (super_cache_count+0x40/0xa0)

[<c02309a8>] (super_cache_count) from [<c01f6ab0>] (debug_shrinker_show+0x50/0x90)

[<c01f6ab0>] (debug_shrinker_show) from [<c024fa5c>] (seq_read+0x1ec/0x48c)

[<c024fa5c>] (seq_read) from [<c022e8f8>] (__vfs_read+0x20/0xd0)

[<c022e8f8>] (__vfs_read) from [<c022f0d0>] (vfs_read+0x7c/0x104)

[<c022f0d0>] (vfs_read) from [<c022f974>] (SyS_read+0x44/0x9c)

[<c022f974>] (SyS_read) from [<c0107580>] (ret_fast_syscall+0x0/0x3c)

Code: e1a04000 e3a00001 ebd66b39 f594f000 (e1943f9f)

---[ end trace 60c74014a63a9688 ]---

Kernel panic - not syncing: Fatal exception

shrink_control.nid is used but not initialzed, same for

shrink_control.memcg.

This reverts commit b0e7a582b2264cdf75874dcd8df915b6b4427755.

Reported-by: Xiaowen Liu <xiaowen.liu@freescale.com>

Signed-off-by: Dmitry Shmidt <dimitrysh@google.com>

# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

https://patchwork.kernel.org/patch/7089351/

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

[Linux][Kernel]뮤텍스 데드락(Mutex Deadlock) 락업(lockup) - "simpleperf" 디버깅 (0)	2023.05.07
[Linux][Kernel] Kernel Panic @__stack_chk_fail - 스택 카나리 (Stack canary Feature) (0)	2023.05.07
[Linux][Kernel] panic@___might_sleep (0)	2023.05.07
[Linux][Kernel][Stability] Kernel panic @0x0 from xfrm_local_error+0x4c (0)	2023.05.07
[Linux-Kernel][Debug]kernel panic@mmc_wait_data_done (0)	2023.05.07

[Linux-Kernel][Debug]kernel panic@mmc_wait_data_done

AustinKim 2023. 5. 7. 17:41

2023. 5. 7. 17:41

#커널 크래시 디버깅 및 TroubleShooting

Debugging

"ndroid.systemui" 프로세스가 raw_spin_lock_irqsave() API 동작 중에 watchdog reset이 되었다.

-000|aee_wdt_atf_entry()

-001|prefetchw(inline)

-001|arch_spin_lock(inline)

-001|do_raw_spin_lock_flags(inline)

-001|__raw_spin_lock_irqsave(inline)

-001|raw_spin_lock_irqsave(lock = 0xDD82725C)

-002|__wake_up(q = 0xDD82725C, mode = 1, nr_exclusive = 1, key = 0x0)

-003|mmc_wait_data_done

-004|msdc_irq_data_complete(host = 0xDD827280, ?, error = 0)

-005|msdc_irq(?, dev_id = 0xDD13B9C8)

-006|static_key_count(inline)

-006|static_key_false(inline)

-006|trace_irq_handler_exit(inline)

-006|handle_irq_event_percpu(?, action = 0xDD13B9C8)

-007|handle_irq_event(desc = 0xC0F38440)

-008|cond_unmask_eoi_irq(inline)

-008|handle_fasteoi_irq(?, desc = 0xC0F38440)

-009|static_key_count(inline)

-009|static_key_false(inline)

-009|trace_irq_exit(inline)

-009|__handle_domain_irq(domain = 0xDE806000, hwirq = 111, lookup = TRUE, ?)

-010|__raw_readl(inline)

-010|gic_handle_irq(regs = 0xDD13BFB0)

-011|__irq_usr(asm)

spinlock이 release되어 spinlock 변수가 [owner: 0x56AC, next: 0x56AD]로 업데이트되기까지 기다리고 있었다.

다른 프로세스가 spinlock을 잡고 있었는데..

(raw_spinlock_t *)0xDD82725C = 0xDD82725C -> (

raw_lock = (

slock = 0x56AD56AB,

tickets = (

owner = 0x56AB, // <<--

next = 0x56AD))) // <<--

0xDD82725C spinlock 변수 주소를 누가 접근하는 지 검색해보면.

(where)

(raw_spinlock_t *)0xDD82725C

c2d01b78: dd82725c

c2d01b7c: dd82725c

c44f0994: dd82725c

dd13bd60: dd82725c // "ndroid.systemui"

dd13bd9c: dd82725c // "ndroid.systemui"

dd13bdc8: dd82725c // "ndroid.systemui"

ddbefdb8: dd82725c // <<--"mmcqd/0"

ddbefdd0: dd82725c

e0abd994: dd82725c

"mmcqd/0" 프로세스가 접근함을 알 수 있었다.

v.v % (struct thread_info*)(0xDDBEFDB8 & ~0x1fff)

(long unsigned int) swap_in = 0 = 0x0 = '....',

(long unsigned int) swap_out = 0 = 0x0 = '....',

(struct task_cputime) cputime_expires = ((cputime_t) utime = 0 = 0x0 = '....', (cputime_t) stime = 0 = 0x0 = '....', (long lo

(struct list_head [3]) cpu_timers = ([0] = ((struct list_head *) next = 0xDDB49A08 = -> ((struct list_head *) next = 0xDDB49

(struct cred *) real_cred = 0xDDB71200 = -> ((atomic_t) usage = ((int) counter = 2 = 0x2 = '....'), (kuid_t) uid = ((uid_t)

(struct cred *) cred = 0xDDB71200 = -> ((atomic_t) usage = ((int) counter = 2 = 0x2 = '....'), (kuid_t) uid = ((uid_t) val =

(char [16]) comm = "mmcqd/0",

"mmcqd/0" 프로세스 콜스택은 아래와 같다.

-000|schedule()

-001|mmc_wait_for_data_req_done(inline)

-001|mmc_start_req(host = 0xC0F75D0C, areq = 0xC0F644E0, error = 0xC102CB08)

-002|mmc_blk_issue_rw_rq(mq = 0xDDB64408, rqc = 0x0)

-003|mmc_blk_issue_rq(mq = 0xDDB64408, req = 0x0)

-004|mmc_queue_thread(d = 0xDDB64408)

-005|kthread(_create = 0xDDB8BDC0)

-006|ret_from_fork(asm)

-007|ret_fast_syscall(asm)

mmc_wait_for_data_req_done 코드를 가보면, spin_lock_irqsave(&context_info->lock, flags); API를 통해 lock을 걸고 있었다.

static int mmc_wait_for_data_req_done(struct mmc_host *host,

struct mmc_request *mrq,

struct mmc_async_req *next_req)

{

struct mmc_command *cmd;

struct mmc_context_info *context_info = &host->context_info;

int err;

unsigned long flags;

while (1) {

wait_event_interruptible(context_info->wait,

(context_info->is_done_rcv ||

context_info->is_new_req));

spin_lock_irqsave(&context_info->lock, flags);

context_info->is_waiting_last_req = false;

조금 더 코드를 보면 Watchdog Reset이 trigger된 "ndroid.systemui" 프로세스 콜 스택에 아래 함수들이 있었다.

-003|mmc_wait_data_done

-004|msdc_irq_data_complete(host = 0xDD827280, ?, error = 0)

mmc_wait_data_done() 함수를 보면 mrq->host->context_info.is_done_rcv = true로 설정하고,

&mrq->host->context_info.wait wait queue을 깨우는 역할을 수행했다.

static void mmc_wait_data_done(struct mmc_request *mrq){

mrq->host->context_info.is_done_rcv = true;

wake_up_interruptible(&mrq->host->context_info.wait);

}

그런데 mmc_wait_for_data_req_done() 함수의 아래 구문은 context_info->is_done_rcv, context_info->is_new_req가 true가

될 때 까지 기다리는 코드다.

wait_event_interruptible(context_info->wait,

(context_info->is_done_rcv ||

context_info->is_new_req));

정리해보면, race condition으로 wake_up_interruptible(&mrq->host->context_info.wait); 함수를 통해 wait_queue에 queue된

&mrq->host->context_info.wait으로 등록된 프로세스를 깨우기 전에 아래 구문이 풀려버려 이미 깨어버린 경우임을 짐작할 수 있다.

잠을 자고 있는 누군가를 깨우려고 손을 대려고 하는데 이미 깨버린 경우와 비슷하네.

In-depth Analysis

내 추정이 맞다면 아래 코드를 삽입하면 바로 커널 패닉이 나야 한다.

(램덤프 force_mmc_wait_data_done_crash)

static void mmc_wait_data_done(struct mmc_request mrq){*

mrq->host->context_info.is_done_rcv = true;

+ mdelay(1);

wake_up_interruptible(&mrq->host->context_info.wait);

}

그런데 바로 커널 패닉이 발생했다.

-000|do_DataAbort(addr = 0, fsr = 0, regs = 0x0)

-001|__dabt_svc(asm)

-->|exception

-002|debug_spin_lock_before(inline)

-002|do_raw_spin_lock(lock = 0x02B4)

-003|raw_spin_lock_irqsave(lock = 0x02B4)

-004|__wake_up(q = 0x02B4, mode = 1, nr_exclusive = 1, key = 0x0)

-005|mmc_wait_data_done(mrq = 0xDC9725F8)

-006|msdc_irq_data_complete(host = 0xDC919300, ?, error = 0)

-007|msdc_irq(?, dev_id = 0x1)

-008|handle_irq_event_percpu(?, action = 0xDC91E0C0)

-009|handle_irq_event(desc = 0xC121A440)

-010|cond_unmask_eoi_irq(inline)

-010|handle_fasteoi_irq(?, desc = 0xC121A440)

-011|static_key_count(inline)

-011|static_key_false(inline)

-011|trace_irq_exit(inline)

-011|__handle_domain_irq(domain = 0xDE806000, hwirq = 111, lookup = TRUE, ?)

-012|__raw_readl(inline)

-012|gic_handle_irq(regs = 0xCB773E10)

-013|__irq_svc(asm)

-->|exception

-014|current_thread_info(inline)

-014|check_preemption_disabled(what1 = 0xC0F115AC, what2 = 0xC0EE0B28)

-015|debug_smp_processor_id()

-016|MT_trace_preempt_on()

-017|preempt_count_sub

-018|current_thread_info(inline)

-018|preempt_count(inline)

-018|should_resched(inline)

-018|__percpu_counter_add(fbc = 0xD8AC7178, amount = 0, batch = 32)

-019|__sb_start_write(sb = 0xC0F115AC, level = -1058141400, wait = FALSE)

-020|file_start_write(inline)

-020|vfs_write(file = 0xD366C480, buf = 0xBEA83A4C, ?, pos = 0xCB773F78)

-021|SYSC_write(inline)

-021|sys_write(?, buf = -1096271284, count = 146)

-022|ret_fast_syscall(asm)

mrq->host->context_info.wait 변수를 확인해보면, 이미 mrq->host 변수가 0이다.

(struct mmc_request *)0xDC9725F8 = 0xDC9725F8 -> (

sbc = 0xDC97262C,

cmd = 0xDC972660,

data = 0xDC9726C8,

stop = 0xDC972694,

completion = (done = 0x0, wait = (lock = (rlock = (raw_lock = (slock = 0x0,

done = 0x0,

host = 0x0)

어머 그런데, mmcqd/0 프로세스가 mmc_wait_for_data_req_done() 코드를 이미 수행했네?

-000|context_switch(inline)

-000|__schedule()

-001|schedule()

-002|mmc_wait_for_data_req_done(inline)

-002|mmc_start_req(host = 0xDC919000, areq = 0xDC972710, ?)

-003|mmc_blk_issue_rw_rq(mq = 0x0, rqc = 0xC64B18C0)

-004|mmc_blk_issue_rq(mq = 0xDC972494, req = 0xC64B18C0)

-005|mmc_queue_thread(d = 0xDC972494)

-006|kthread(_create = 0xDCA24E40)

-007|ret_from_fork(asm)

-008|ret_fast_syscall(asm)

@ftrace log를 좀 더 추가해보자.

diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c

index db74413..fcf6692 100644

? a/drivers/mmc/core/core.c

+++ b/drivers/mmc/core/core.c

@@ -1034,6 +1034,9 @@ out:

}

EXPORT_SYMBOL(mmc_start_bkops);

#endif

mmc_wait_data_done() - done callback for data request

@mrq: done data request

@@ -1042,10 +1045,25 @@ EXPORT_SYMBOL(mmc_start_bkops);

static void mmc_wait_data_done(struct mmc_request *mrq)

static void mmc_wait_data_done(struct mmc_request mrq) *{

mrq->host->context_info.is_done_rcv = true;

+ trace_printk("+msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

mdelay(1);

+ trace_printk("++msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

wake_up_interruptible(&mrq->host->context_info.wait);

+ trace_printk("--msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

역시나 GIC mtk-msdc(111) IRQ가 Trigger된 다음에 아래와 같이 커널 패닉이 발생하였네.

(램덤프: neo_more_crash_ftrace)

-000|do_DataAbort(addr = 0, fsr = 0, regs = 0x0)

-001|__dabt_svc(asm)

-->|exception

-002|debug_spin_lock_before(inline)

-002|do_raw_spin_lock(lock = 0x02B4)

-003|raw_spin_lock_irqsave(lock = 0x02B4)

-004|__wake_up(q = 0x02B4, mode = 1, nr_exclusive = 1, key = 0x0)

-005|mmc_wait_data_done(mrq = 0xDC9235F8)

-006|msdc_irq_data_complete(host = 0xDC927300, ?, error = 0)

-007|msdc_irq(?, dev_id = 0x1)

-008|handle_irq_event_percpu(?, action = 0xDC92B180)

-009|handle_irq_event(desc = 0xC121A440)

-010|cond_unmask_eoi_irq(inline)

-010|handle_fasteoi_irq(?, desc = 0xC121A440)

-011|static_key_count(inline)

-011|static_key_false(inline)

-011|trace_irq_exit(inline)

-011|__handle_domain_irq(domain = 0xDE806000, hwirq = 111, lookup = TRUE, ?)

-012|__raw_readl(inline)

-012|gic_handle_irq(regs = 0xC2631E20)

-013|__irq_svc(asm)

-->|exception

-014|__fget(?, mask = 16384)

-015|__fget_light(?, mask = 16384)

-016|__fdget

-017|sockfd_lookup_light(?, err = 0xC2631EC8, fput_needed = 0xC2631ECC)

-018|SYSC_recvfrom(inline)

-018|sys_recvfrom(?, ubuf = -1212542344, ?, flags = 64, addr = 0, addr_len = 0)

-019|ret_fast_syscall(asm)

Ftrace log 분석 좀 해보자.

커널 패닉이 일어나기 직전 상황

[1]: irq=111 name=mtk-msdc 가 Trigger됨

[2]: IRQ context에서 mmc_wait_data_done() 함수가 호출 from(msdc_irq_data_complete)

[2]~[3] 사이 mmcq0 process가 context switching 되지 않고 수행 ( InputDispatcher-1538)

[3]: mdelay(1); 이후 찍히는 ftrace log

[4]: wake_up_interruptible(&mrq->host->context_info.wait); API 호출로 mmcq0 process을 wakeup 시킴

CPU5: mmcqd/0, pid=244

sched_wakeup: comm=mmcqd/0 pid=244 prio=120 success=1 target_cpu=005 state=W

[5]: wake_up_interruptible(&mrq->host->context_info.wait); API 호출이 끝난 후 찍히는 로그(별 의미 없음)

kworker/4:0-25 [004] 149.827488: irq_handler_entry: irq=111 name=mtk-msdc // <<--[1]

kworker/4:0-25 [004] 149.827495: bprint: mmc_wait_data_done: +msdc [F: mmc_wait_data_done, L:1049]: ? ? from(msdc_irq_data_complete) // <<--[2]

InputDispatcher-1538 [005] 149.827496: sched_migrate_task: comm=m.lge.launcher3 pid=2135 prio=120 orig_cpu=6 dest_cpu=4 state=W

InputDispatcher-1538 [005] 149.827519: sched_wakeup: comm=m.lge.launcher3 pid=2135 prio=120 success=1 target_cpu=004 state=W

InputDispatcher-1538 [005] 149.827591: sched_migrate_task: comm=ndroid.systemui pid=1622 prio=120 orig_cpu=5 dest_cpu=6 state=W

InputDispatcher-1538 [005] 149.827608: sched_wakeup: comm=ndroid.systemui pid=1622 prio=120 success=1 target_cpu=006 state=W

InputDispatcher-1538 [005] 149.827675: sched_migrate_task: comm=android.ui pid=1287 prio=118 orig_cpu=4 dest_cpu=6 state=W

InputDispatcher-1538 [005] 149.827694: sched_wakeup: comm=android.ui pid=1287 prio=118 success=1 target_cpu=006 state=W

InputDispatcher-1538 [005] 149.827855: sched_switch: prev_comm=InputDispatcher prev_pid=1538 prev_prio=112 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 extra_prev_state=K|m|d

<idle>-0 [005] 149.827912: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=InputDispatcher next_pid=1538 next_prio=112 extra_prev_state=K|m|d

InputDispatcher-1538 [005] 149.828064: sched_switch: prev_comm=InputDispatcher prev_pid=1538 prev_prio=112 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 extra_prev_state=K|m|d

<idle>-0 [005] 149.828209: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=InputDispatcher next_pid=1538 next_prio=112 extra_prev_state=K|m|d

InputDispatcher-1538 [005] 149.828352: sched_switch: prev_comm=InputDispatcher prev_pid=1538 prev_prio=112 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 extra_prev_state=K|m|d

kworker/4:0-25 [004] 149.828497: bprint: mmc_wait_data_done: ++msdc [F: mmc_wait_data_done, L:1058]: ? ? from(msdc_irq_data_complete) // <<--[3]

kworker/4:0-25 [004] 149.828521: sched_wakeup: comm=mmcqd/0 pid=244 prio=120 success=1 target_cpu=005 state=W // <<--[4]

kworker/4:0-25 [004] 149.828525: bprint: mmc_wait_data_done: -msdc [F: mmc_wait_data_done, L:1060]: ? ? from(msdc_irq_data_complete) <<-[5]

<idle>0 [005] 149.828528: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=mmcqd/0 next_pid=244 next_prio=120 extra_prev_state=K|m|d <<-[6]

kworker/4:0-25 [004] 149.828530: irq_handler_exit: irq=111 ret=handled

1046 static void mmc_wait_data_done(struct mmc_request *mrq)

1047*{*

1048 mrq->host->context_info.is_done_rcv = true;

1049 trace_printk("+msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[2]

//생략

1051 mdelay(1);

//생략

1057

1058 trace_printk("++msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[3]

1059 wake_up_interruptible(&mrq->host->context_info.wait);

1060 trace_printk("-msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<-[5]

커널 패닉 상황

[7]: irq=111 name=mtk-msdc 가 handle 되었음

[8]: [mmcqd/0-244, CPU5]mmc_wait_for_data_req_done() 함수 내[from(mmc_blk_issue_rw_rq)] wait_event_interruptible()에서 빠져나옴.

[9][10]: [mmcqd/0-244, CPU5]mmc_wait_for_data_req_done() 함수를 빠져나옴

[11]: irq=111 name=mtk-msdc 가 Trigger됨 --> CPU4의 m.lge.launcher3-2135

[12]: [mmcqd/0-244, CPU5] 깨어난 mmcqd/0-244 프로세스 활동 시작

&mqrq->brq 변수를 0으로 밀어버림 (where: memset(brq, 0, sizeof(struct mmc_blk_request));

[13]: [m.lge.launcher3-2135 CPU4] irq=111 name=mtk-msdc IRQ로 Trigger되어 실행되어

mmc_wait_data_done() 함수 진입

[14][15]: [mmcqd/0-244, CPU5] mmc_blk_rw_rq_prep() 함수 퇴장하려함

[16][17][18] [mmcqd/0-244, CPU5] mmc_wait_for_data_req_done() 함수 처리 후 퇴장하려함

[19]: [m.lge.launcher3-2135 CPU4] wake_up_interruptible(&mrq->host->context_info.wait);

[20] 커널 패닉

[12]번 동작에서 0으로 초기화된 &mrq->host 변수를 통해 밀린((where: memset(brq, 0, sizeof(struct mmc_blk_request)) wake_up_interruptible() API 호출

kworker/4:0-25 [004] 149.828530: irq_handler_exit: irq=111 ret=handled // <<--[7]

mmcqd/0-244 [005] 149.828536: bprint: mmc_start_req: ++mmcq [F: mmc_wait_for_data_req_done, L:1236]: ? ? from(mmc_blk_issue_rw_rq) // <<--[8]

kworker/4:0-25 [004] 149.828537: irq_handler_entry: irq=30 name=arch_timer

kworker/4:0-25 [004] 149.828546: irq_handler_exit: irq=30 ret=handled

mmcqd/0-244 [005] 149.828559: bprint: mmc_start_req: mmcq [F: mmc_wait_for_data_req_done, L:1268]: ? ? from(mmc_blk_issue_rw_rq) // <<-[9]

mmcqd/0-244 [005] 149.828561: bprint: mmc_start_req: mmcq release [F: mmc_wait_for_data_req_done, L:1270]: ? ? from(mmc_blk_issue_rw_rq) // <<--[10]

kworker/4:0-25 [004] 149.828584: workqueue_execute_end: work struct 0xcb40cae4

kworker/4:0-25 [004] 149.828630: sched_switch: prev_comm=kworker/4:0 prev_pid=25 prev_prio=120 prev_state=S ==> next_comm=m.lge.launcher3 next_pid=2135 next_prio=120 extra_prev_state=K|m|d

m.lge.launcher3-2135 [004] 149.828660: irq_handler_entry: irq=111 name=mtk-msdc // <<--[11]

mmcqd/0-244 [005] 149.828661: bprint: mmc_blk_rw_rq_prep: ++mmc_blk_rw_rq_prep [F: mmc_blk_rw_rq_prep, L:1725]: ? ? from(mmc_blk_issue_rw_rq) // <<--[12]

m.lge.launcher3-2135 [004] 149.828666: bprint: mmc_wait_data_done: +msdc [F: mmc_wait_data_done, L:1049]: ? ? from(msdc_irq_data_complete) // <<--[13]

mmcqd/0-244 [005] 149.828670: bprint: mmc_blk_rw_rq_prep: -mmc_blk_rw_rq_prep [F: mmc_blk_rw_rq_prep, L:1905]: ? ? from(mmc_blk_issue_rw_rq) // <<-[14]

mmcqd/0-244 [005] 149.828672: bprint: mmc_blk_rw_rq_prep: mmc_blk_rw_rq_prep [F: mmc_blk_rw_rq_prep, L:1907]: ? ? from(mmc_blk_issue_rw_rq) // <<-[15]

mmcqd/0-244 [005] 149.828681: bprint: mmc_start_req: +mmcq [F: mmc_wait_for_data_req_done, L:1231]: ? ? from(mmc_blk_issue_rw_rq) // <<--[16]

mmcqd/0-244 [005] 149.828683: bprint: mmc_start_req: ++mmcq [F: mmc_wait_for_data_req_done, L:1236]: ? ? from(mmc_blk_issue_rw_rq) // <<--[17]

mmcqd/0-244 [005] 149.828695: bprint: mmc_start_req: -mmcq [F: mmc_wait_for_dat뗥nQ, L:0]: ? ? from(0x726f776bS) // <<--[18]

m.lge.launcher3-2135 [004] 149.829669: bprint: mmc_wait_data_done: ++msdc [F: mmc_wait_data_done, L:1058]: ? ? from(msdc_irq_data_complete) // <<--[19]

m.lge.launcher3-2135 [004] 149.829748: tracing_on: ftrace is disabled caller=oops_enter // <<?[20]

1222 static int mmc_wait_for_data_req_done(struct mmc_host *host,

1223 struct mmc_request *mrq,

1224 struct mmc_async_req *next_req)

1225*{*

1226 struct mmc_command *cmd;

1227 struct mmc_context_info *context_info = &host->context_info;

1228 int err;

1229 unsigned long flags;

1230

1231 trace_printk("+mmcq [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[16]

1232 while (1) {

1233 wait_event_interruptible(context_info->wait,

1234 (context_info->is_done_rcv ||

1235 context_info->is_new_req));

1236 trace_printk("++mmcq [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[8], [17]

1237 spin_lock_irqsave(&context_info->lock, flags);

//snip

1268 trace_printk("mmcq [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<-[9], [18]

1269 mmc_retune_release(host);

1270 trace_printk("mmcq release [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

1271 return err;

1272 }

1701 static void mmc_blk_rw_rq_prep(struct mmc_queue_req *mqrq,

1702 struct mmc_card *card,

1703 int disable_multi,

1704 struct mmc_queue *mq)

1705*{*

1706 u32 readcmd, writecmd;

1707 struct mmc_blk_request *brq = &mqrq->brq;

//생략

1724 memset(brq, 0, sizeof(struct mmc_blk_request));

1725 trace_printk("++mmc_blk_rw_rq_prep [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[12]

1726 brq->mrq.cmd = &brq->cmd;

//생략

1905 trace_printk("-mmc_blk_rw_rq_prep [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); //<<-[14]

1906 mmc_queue_bounce_pre(mqrq);

1907 trace_printk("-mmc_blk_rw_rq_prep [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

1908 }

1046 static void mmc_wait_data_done(struct mmc_request *mrq)

1047*{*

1048 mrq->host->context_info.is_done_rcv = true;

1049 trace_printk("+msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[13]

//생략

1051 mdelay(1);

//생략

1057

1058 trace_printk("++msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[19]

1059 wake_up_interruptible(&mrq->host->context_info.wait);

1060 trace_printk("--msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

정리하면 wake_up_interruptible() API에 파라미터로 전달되는 &mrq->host->context_info.wait를 다른 값(mmcqd를 깨울 수 있는 wait_queue)으로 바꾸거나,

wake_up_interruptible() 호출 시 조건을 줘야 한다. 혹은 spinlock irq save로 코드 보호

솔류션

분석된 내용에 따라 아래 패치를 적용하였더니 문제가 사라졌다.

diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c

index c3abe34..01e4bfc 100644

--- a/drivers/mmc/core/core.c

+++ b/drivers/mmc/core/core.c

@@ -403,8 +403,13 @@ EXPORT_SYMBOL(mmc_start_bkops);

static void mmc_wait_data_done(struct mmc_request *mrq)

{

+ unsigned long flags;

+ struct mmc_context_info *context_info = &mrq->host->context_info;

+ spin_lock_irqsave(&context_info->lock, flags);

mrq->host->context_info.is_done_rcv = true;

wake_up_interruptible(&mrq->host->context_info.wait);

+ spin_unlock_irqrestore(&context_info->lock, flags);

}

static void mmc_wait_done(struct mmc_request *mrq)

@@ -465,6 +470,7 @@ static int mmc_wait_for_data_req_done(struct mmc_host *host,

struct mmc_command *cmd;

struct mmc_context_info *context_info = &host->context_info;

int err;

+ bool is_done_rcv = false;

unsigned long flags;

while (1) {

@@ -472,9 +478,10 @@ static int mmc_wait_for_data_req_done(struct mmc_host *host,

(context_info->is_done_rcv ||

context_info->is_new_req));

spin_lock_irqsave(&context_info->lock, flags);

+ is_done_rcv = context_info->is_done_rcv;

context_info->is_waiting_last_req = false;

spin_unlock_irqrestore(&context_info->lock, flags);

- if (context_info->is_done_rcv) {

+ if (is_done_rcv) {

context_info->is_done_rcv = false;

context_info->is_new_req = false;

cmd = mrq->cmd;

그런데, 리눅스 커뮤니티에서 이미 패치를 릴리즈했네.

diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c

index 347108a..db74413 100644

--- a/drivers/mmc/core/core.c

+++ b/drivers/mmc/core/core.c

@@ -1042,8 +1042,10 @@ EXPORT_SYMBOL(mmc_start_bkops);

static void mmc_wait_data_done(struct mmc_request *mrq)

{

- mrq->host->context_info.is_done_rcv = true;

- wake_up_interruptible(&mrq->host->context_info.wait);

+ struct mmc_context_info *context_info = &mrq->host->context_info;

+ context_info->is_done_rcv = true;

+ wake_up_interruptible(&context_info->wait);

}

# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

https://elixir.bootlin.com/linux/v5.15.30/source/arch/arm64/kernel/traps.c

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

[Linux][Kernel]뮤텍스 데드락(Mutex Deadlock) 락업(lockup) - "simpleperf" 디버깅 (0)	2023.05.07
[Linux][Kernel] Kernel Panic @__stack_chk_fail - 스택 카나리 (Stack canary Feature) (0)	2023.05.07
[Linux][Kernel] panic@___might_sleep (0)	2023.05.07
[Linux][Kernel][Stability] Kernel panic @0x0 from xfrm_local_error+0x4c (0)	2023.05.07
[Kernel][Debug] "cat /d/shrinker" kernel panic (0)	2023.05.07

BUG(): CONFIG_PANIC_ON_OOPS, CONFIG_PANIC_ON_OOPS_VALUE

AustinKim 2023. 5. 7. 16:55

2023. 5. 7. 16:55

Sometime I noticed that system does not crash when the call to BUG() is made in the kernel driver. I just observed the stack trace from the kernel log and then find that target is running rather than entering crash mode.

To make the target crash when BUG() is called, the following config should be present;

CONFIG_PANIC_ON_OOPS=y

CONFIG_PANIC_ON_OOPS_VALUE=1

Let's look at kernel die() function which is called from BUG() function.

void die(const char *str, struct pt_regs *regs, int err)

{

...

if (in_interrupt())

panic("%s: Fatal exception in interrupt", str);

if (panic_on_oops)

panic("%s: Fatal exception", str);

If panic_on_oops is true, the panic() is called with "Fatal exception message". How panic_on_oops is specified? Is it configured during run-time?

Let's take a look at below statement;

https://elixir.bootlin.com/linux/v5.15.30/source/kernel/panic.c

int panic_on_oops = CONFIG_PANIC_ON_OOPS_VALUE;

panic_on_oops depends on CONFIG_PANIC_ON_OOPS_VALUE.

Now is time to check the definition of CONFIG_PANIC_ON_OOPS_VALUE.

https://elixir.bootlin.com/linux/v5.15.30/source/lib/Kconfig.debug#L991

config PANIC_ON_OOPS_VALUE

int

range 0 1

default 0 if !PANIC_ON_OOPS

default 1 if PANIC_ON_OOPS

CONFIG_PANIC_ON_OOPS_VALUE can be configured by PANIC_ON_OOPS.

Conclusion

PANIC_ON_OOPS should be enabled to make the target crash when BUG() is called.

https://embetronicx.com/tutorials/linux/device-drivers/workqueue-in-linux-dynamic-creation/

'Core BSP 분석 > 리눅스 커널 핵심 분석' 카테고리의 다른 글

커널 버전별 변경사항 (v5.19~v6.3) 링크 (0)	2023.09.12
KTPI - commit (0)	2023.07.11
중요 사이트: 리눅스 커널 디바이스 드라이버 (0)	2023.05.07
[리눅스커널] 특정 슬럽 오브젝트 트레이싱 (0)	2023.05.07
[리눅스커널] ftrace: boottime-trace(부트타임 ftrace) (0)	2023.05.07

중요 사이트: 리눅스 커널 디바이스 드라이버

AustinKim 2023. 5. 7. 16:54

2023. 5. 7. 16:54

아래 사이트에 유익한 리눅스 커널 드라이버 샘플 코드가 있다.

<From: Mr. Paran Lee>

---

1. Arm64 Linux kernel 에서 수정 후 테스트해본 리눅스 커널 모듈 드라이버 코드입니다.

Tasklet

- https://gist.github.com/paranlee/84b6af08d1b4c636a06b9ba4af1b083d

Workqueue

- https://gist.github.com/paranlee/15f816a874818dfb247a6309a0ccc5c1

2. int generic_handle_irq(unsigned int irq) 관련 루틴

Invoke the handler for a particular irq

- https://www.kernel.org/doc/html/v4.12/core-api/genericirq.html#c.generic_handle_irq

---

'Core BSP 분석 > 리눅스 커널 핵심 분석' 카테고리의 다른 글

KTPI - commit (0)	2023.07.11
BUG(): CONFIG_PANIC_ON_OOPS, CONFIG_PANIC_ON_OOPS_VALUE (0)	2023.05.07
[리눅스커널] 특정 슬럽 오브젝트 트레이싱 (0)	2023.05.07
[리눅스커널] ftrace: boottime-trace(부트타임 ftrace) (0)	2023.05.07
[리눅스커널] LKDTM(Linux Kernel Dump Test Module) 소개 -c (0)	2023.05.07

[리눅스커널] 특정 슬럽 오브젝트 트레이싱

AustinKim 2023. 5. 7. 16:53

2023. 5. 7. 16:53

slub debug enable 하려면 부트 커멘드 라인 추가 요망

set bootopts slub_debug=FZPUAO,kmalloc-128

https://www.kernel.org/doc/html/v5.4/vm/slub.html>

...

F.e. in order to boot just with sanity checks and red zoning one would specify:

slub_debug=FZ

Trying to find an issue in the dentry cache? Try:

slub_debug=,dentry

to only enable debugging on the dentry cache. You may use an asterisk at the end of the slab name, in order to cover all slabs with the same prefix. For example, here’s how you can poison the dentry cache as well as all kmalloc slabs:

slub_debug=P,kmalloc-*,dentry

Red zoning and tracking may realign the slab. We can just apply sanity checks to the dentry cache with:

slub_debug=F,dentry

static int __init setup_slub_debug(char *str)

{

slab_flags_t flags;

char *saved_str;

char *slab_list;

bool global_slub_debug_changed = false;

bool slab_list_specified = false;

slub_debug = DEBUG_DEFAULT_FLAGS;

if (*str++ != '=' || !*str)

* No options specified. Switch on full debugging.

goto out;

saved_str = str; // 커멘드 라인 저장

while (str) {

str = parse_slub_debug_flags(str, &flags, &slab_list, true);

if (!slab_list) {

slub_debug = flags;

global_slub_debug_changed = true;

} else {

slab_list_specified = true; // 커멘드 라인에서 슬랩 캐시의 종류를 지정한 경우, slub_debug=P,kmalloc-*,dentry

}

if (slab_list_specified) {

if (!global_slub_debug_changed)

slub_debug = 0;

slub_debug_string = saved_str;

}

out:

if (slub_debug != 0 || slub_debug_string)

static_branch_enable(&slub_debug_enabled);

if ((static_branch_unlikely(&init_on_alloc) ||

static_branch_unlikely(&init_on_free)) &&

(slub_debug & SLAB_POISON))

pr_info("mem auto-init: SLAB_POISON will take precedence over init_on_alloc/init_on_free\n");

return 1;

}

__setup("slub_debug", setup_slub_debug);

(static struct kmem_cache * [14]) kmalloc_caches = (

[0] = 0x0 = -> NULL,

[1] = 0x0 = -> NULL,

[2] = 0x0 = -> NULL,

[3] = 0x0 = -> NULL,

[4] = 0x0 = -> NULL,

[5] = 0x0 = -> NULL,

[6] = 0x0 = -> NULL,

[7] = 0xFFFFFFD33FC20400 // "kmalloc-64"

[8] = 0xFFFFFFD33FC27780 // "kmalloc-128"

[9] = 0xFFFFFFD33FC20780 // "kmalloc-256"

[10] = 0xFFFFFFD33FC27400

[11] = 0xFFFFFFD33FC20B00

[12] = 0xFFFFFFD33FC27080

[13] = 0xFFFFFFD33FC20E80 // "kmalloc-8192"

https://mjmwired.net/kernel/Documentation/trace/boottime-trace.rst

'Core BSP 분석 > 리눅스 커널 핵심 분석' 카테고리의 다른 글

BUG(): CONFIG_PANIC_ON_OOPS, CONFIG_PANIC_ON_OOPS_VALUE (0)	2023.05.07
중요 사이트: 리눅스 커널 디바이스 드라이버 (0)	2023.05.07
[리눅스커널] ftrace: boottime-trace(부트타임 ftrace) (0)	2023.05.07
[리눅스커널] LKDTM(Linux Kernel Dump Test Module) 소개 -c (0)	2023.05.07
[리눅스커널] IPI Call 요청: SGI(Software Generated Interrupt) 요청 (로우 레벨 뷰) (0)	2023.05.07

[리눅스커널] ftrace: boottime-trace(부트타임 ftrace)

AustinKim 2023. 5. 7. 16:53

2023. 5. 7. 16:53

<version: ES1>

Overview

이번 포스트에서는 커널 v5.10에 반영된 boottime-trace를 소개합니다. 관련 문서는 아래 링크에서 확인할 수 있습니다.

강의 동영상 링크는 다음과 같습니다.

https://linuxfoundation.org/webinars/extra-boot-configuration-and-boot-time-tracing/

boottime-trace는 커멘드 라인을 통해 ftrace 설정을 해서 부팅 과정에서 ftrace의 주요 기능을 enable하는 기능입니다. 위 링크에서 소개된 패치는 initrd가 존재해야 효과가 있어(ex: 우분투), 배포판마다 활성화가 하기는 어렵습니다. 안드로이드나 크로뮴 OS에서는 initrd을 사용하지 않습니다.

소스 분석

v5.15 버전의 리눅스 커널 소스에서 확인한 디렉토리에서 커맨드 라인을 읽는 ftrace 옵션과 콜백 함수 리스트는 아래와 같습니다. ('kernel/trace'에서 서칭 )

$ egrep -nr __setup *

ftrace.c:5526:__setup("ftrace_notrace=", set_ftrace_notrace);

ftrace.c:5534:__setup("ftrace_filter=", set_ftrace_filter);

ftrace.c:5546:__setup("ftrace_graph_filter=", set_graph_function);

ftrace.c:5553:__setup("ftrace_graph_notrace=", set_graph_notrace_function);

ftrace.c:5562:__setup("ftrace_graph_max_depth=", set_graph_max_depth_function);

trace.c:197:__setup("ftrace=", set_cmdline_ftrace);

trace.c:213:__setup("ftrace_dump_on_oops", set_ftrace_dump_on_oops);

trace.c:221:__setup("traceoff_on_warning", stop_trace_on_warning);

trace.c:230:__setup("alloc_snapshot", boot_alloc_snapshot);

trace.c:240:__setup("trace_options=", set_trace_boot_options);

trace.c:251:__setup("trace_clock=", set_trace_boot_clock);

trace.c:263:__setup("tp_printk", set_tracepoint_printk);

trace.c:270:__setup("tp_printk_stop_on_boot", set_tracepoint_printk_stop);

trace.c:1507:__setup("trace_buf_size=", set_buf_size);

trace.c:1522:__setup("tracing_thresh=", set_tracing_thresh);

trace_events.c:3438:__setup("trace_event=", setup_trace_event);

trace_kprobe.c:36:__setup("kprobe_event=", set_kprobe_boot_events);

trace_stack.c:552:__setup("stacktrace", enable_stacktrace);

커맨드 라인에 boottime-trace 설정하기

크로뮴 OS

먼저 크로뮴 OS에서 아래 패치를 적용하면 커멘드 라인이 업데이트됩니다.

diff --git a/chromeos/config/x86_64/chromiumos-x86_64.flavour.config b/chromeos/config/x86_64/chromiumos-x86_64.flavour.config

index 084c67d005dd..ad8f8bddc233 100644

— a/chromeos/config/x86_64/chromiumos-x86_64.flavour.config

+++ b/chromeos/config/x86_64/chromiumos-x86_64.flavour.config

+CONFIG_CMDLINE="crashkernel=512M ftrace=function ftrace_filter=*_probe*

+CONFIG_CMDLINE_BOOL=y

'ftrace=function ftrace_filter=*_probe*'이 핵심 구문입니다.

라즈비안

이번에는 라즈비안에서 boottime-trace 커맨드 라인을 추가하는 방법을 소개합니다. 라즈비안은 디바이스 트리에서 부트 커멘트 라인을 업데이트할 수 있습니다. 아래는 arm32 기반 라즈비안에서 커멘드 라인을 수정하는 패치입니다. (소스 베이스: v5.15.33)

diff --git a/arch/arm/boot/dts/bcm2711-rpi-4-b.dts b/arch/arm/boot/dts/bcm2711-rpi-4-b.dts

index 8c0ab39..47e552e 100644

--- a/arch/arm/boot/dts/bcm2711-rpi-4-b.dts

+++ b/arch/arm/boot/dts/bcm2711-rpi-4-b.dts

@@ -282,7 +282,7 @@

/ {

chosen {

- bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

+ bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 ftrace=function ftrace_filter=*_probe*";

};

aliases {

위 패치는 Arm64 기반 라즈비안에 적용됩니다. bcm2711-rpi-4-b.dts 파일을 열면 "arm/boot/dts/bcm2711-rpi-4-b.dts"을 include하기 때문입니다.

arch/arm64/boot/dts/broadcom/bcm2711-rpi-4-b.dts

#include "../../../../arm/boot/dts/bcm2711-rpi-4-b.dts"

(리서치 1)

검색 과정에서 사용한 명령어는 다음과 같습니다.

rpi_5_15_src/linux/arch/arm/boot/dts$ find . -name "bcm271*.*" -type f | xargs grep bootargs

./bcm2711-rpi-cm4.dts: bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

./bcm2711-rpi-4-b.dts: bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 ftrace=function ftrace_filter=*_probe*";

./bcm2711-rpi-400.dts: bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

./bcm2710-rpi-3-b.dts: bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

./bcm2710-rpi-zero-2-w.dts: bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

./bcm2710-rpi-3-b-plus.dts: bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

./bcm2711-rpi-cm4s.dts: bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

각각 서로 다른 라즈베리 파이에 대해 다음 파일이 적용됩니다.

modified: arch/arm/boot/dts/bcm2711-rpi-4-b.dts

modified: arch/arm/boot/dts/bcm2711-rpi-400.dts

modified: arch/arm/boot/dts/bcm2711-rpi-cm4s.dts

(리서치 2)

CONFIG_ARCH_BCM_2835가 bcm2711_defconfig에 enable돼 있습니다.

out64/.config

...

293 # CONFIG_ARCH_APPLE is not set

294 CONFIG_ARCH_BCM2835=y

295 # CONFIG_ARCH_BCM4908 is not set

296 # CONFIG_ARCH_BCM_IPROC is not set

ARCH_BCM_2835를 Makefile에서 검색해 bcm27* dtb 파일이 빌드에 포함됨을 확인했습니다.

arch/arm64/boot/dts/broadcom/Makefile

# SPDX-License-Identifier: GPL-2.0

dtb-$(CONFIG_ARCH_BCM2835) += bcm2711-rpi-400.dtb \

bcm2711-rpi-4-b.dtb \

bcm2837-rpi-3-a-plus.dtb \

bcm2837-rpi-3-b.dtb \

bcm2837-rpi-3-b-plus.dtb \

bcm2837-rpi-cm3-io3.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2710-rpi-zero-2.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2710-rpi-2-b.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2710-rpi-3-b.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2710-rpi-3-b-plus.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2711-rpi-4-b.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2711-rpi-400.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2710-rpi-cm3.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2711-rpi-cm4.dtb

subdir-y += bcm4908

subdir-y += northstar2

subdir-y += stingray

# Enable fixups to support overlays on BCM2835 platforms

ifeq ($(CONFIG_ARCH_BCM2835),y)

DTC_FLAGS += -@

endif

샘플 ftrace 메시지

부트 커멘드 라인으로 "ftrace=function ftrace_filter=*initcall*"을 적용한 후

받은 ftrace 메시지는 다음과 같습니다.

# tracer: function

# entries-in-buffer/entries-written: 6800/6800 #P:4

# _-----=> irqs-off

# / _----=> need-resched

# | / _---=> hardirq/softirq

# || / _--=> preempt-depth

# ||| / delay

# TASK-PID CPU# |||| TIMESTAMP FUNCTION

# | | | |||| | |

<idle>-0 [000] d..1 0.250968: arch_probe_nr_irqs <-early_irq_init

<idle>-0 [000] ...1 0.252607: physflat_probe <-default_setup_apic_routing

<idle>-0 [000] ...1 0.252608: flat_probe <-default_setup_apic_routing

init-1 [000] .... 0.270282: watchdog_nmi_probe <-lockup_detector_init

init-1 [000] .... 0.281332: bus_probe_device <-device_add

init-1 [000] .... 0.281348: add_probe_files <-bus_register

...

init-1 [002] d..2 0.641288: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120

<idle>-0 [003] d..2 0.641309: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=76 next_prio=120

kworker/u8:1-76 [003] d..2 0.641337: sched_switch: prev_comm=kworker/u8:1 prev_pid=76 prev_prio=120 prev_state=R+ ==> next_comm=irq/42-mmc1 next_pid=107 next_prio=49

irq/42-mmc1-107 [003] d..2 0.641396: sched_switch: prev_comm=irq/42-mmc1 prev_pid=107 prev_prio=49 prev_state=S ==> next_comm=kworker/u8:1 next_pid=76 next_prio=120

kworker/u8:1-76 [003] d..2 0.641407: sched_switch: prev_comm=kworker/u8:1 prev_pid=76 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120

<idle>-0 [002] d..2 0.641408: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=125 next_prio=120

<idle>-0 [001] d..2 0.641414: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/1:0 next_pid=20 next_prio=120

kworker/1:0-20 [001] d..2 0.641458: sched_switch: prev_comm=kworker/1:0 prev_pid=20 prev_prio=120 prev_state=D ==> next_comm=swapper/1 next_pid=0 next_prio=120

kworker/u8:1-125 [002] d..2 0.641476: signal_generate: sig=17 errno=0 code=1 comm=kworker/u8:1 pid=76 grp=1 res=1

kworker/u8:1-125 [002] d..2 0.641482: sched_switch: prev_comm=kworker/u8:1 prev_pid=125 prev_prio=120 prev_state=Z ==> next_comm=swapper/2 next_pid=0 next_prio=120

<idle>-0 [003] d..2 0.641483: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=76 next_prio=120

kworker/u8:1-76 [003] d..2 0.641492: sched_switch: prev_comm=kworker/u8:1 prev_pid=76 prev_prio=120 prev_state=I ==> next_comm=swapper/3 next_pid=0 next_prio=120

<idle>-0 [002] d..2 0.641494: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=swapper/0 next_pid=1 next_prio=120

init-1 [002] d..2 0.641502: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120

<idle>-0 [003] d..2 0.641504: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=76 next_prio=120

kworker/u8:1-76 [003] d..2 0.641520: sched_switch: prev_comm=kworker/u8:1 prev_pid=76 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120

<idle>-0 [002] d..2 0.641521: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=126 next_prio=120

kworker/u8:1-126 [002] d..2 0.641543: signal_generate: sig=17 errno=0 code=1 comm=kworker/u8:1 pid=76 grp=1 res=1

kworker/u8:1-126 [002] d..2 0.641548: sched_switch: prev_comm=kworker/u8:1 prev_pid=126 prev_prio=120 prev_state=Z ==> next_comm=swapper/2 next_pid=0 next_prio=120

<idle>-0 [003] d..2 0.641549: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=76 next_prio=120

kworker/u8:1-76 [003] d..2 0.641555: sched_switch: prev_comm=kworker/u8:1 prev_pid=76 prev_prio=120 prev_state=I ==> next_comm=swapper/3 next_pid=0 next_prio=120

<idle>-0 [002] d..2 0.641557: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=swapper/0 next_pid=1 next_prio=120

init-1 [002] d..2 0.641565: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120

<idle>-0 [001] d..2 0.641586: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kthreadd next_pid=2 next_prio=120

kthreadd-2 [001] d..2 0.641612: sched_switch: prev_comm=kthreadd prev_pid=2 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120

<idle>-0 [002] d..2 0.641613: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kthreadd next_pid=127 next_prio=120

cryptomgr_probe-127 [002] d..2 0.641619: sched_switch: prev_comm=kthreadd prev_pid=127 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120

<idle>-0 [003] d..2 0.641620: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=swapper/0 next_pid=1 next_prio=120

init-1 [003] d..2 0.641628: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=swapper/3 next_pid=0 next_prio=120

<idle>-0 [002] d..2 0.641629: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=cryptomgr_probe next_pid=127 next_prio=120

cryptomgr_probe-127 [002] .... 0.641630: cryptomgr_probe <-kthread

...

init-1 [001] .... 0.642319: driver_deferred_probe_trigger <-deferred_probe_initcall

init-1 [001] d..2 0.642321: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=kworker/1:4 next_pid=109 next_prio=120

kworker/1:4-109 [001] .... 0.642321: deferred_probe_work_func <-process_one_work

kworker/1:4-109 [001] d..2 0.642323: sched_switch: prev_comm=kworker/1:4 prev_pid=109 prev_prio=120 prev_state=R+ ==> next_comm=swapper/0 next_pid=1 next_prio=120

init-1 [001] d..1 0.642327: console: [ 0.640227] PM: Magic number: 10:467:470

<idle>-0 [002] d.h3 0.642461: console: [ 0.640361] atkbd serio0: Unknown key released (translated set 2, code 0x7c on isa0060/serio0).

<idle>-0 [002] d.h3 0.642464: console: [ 0.640365] atkbd serio0: Use 'setkeycodes 7c <keycode>' to make it known.

init-1 [001] d..1 0.642535: console: [ 0.640435] ALSA device list:

init-1 [001] d..1 0.642539: console: [ 0.640440] No soundcards found.

init-1 [001] d..1 0.642558: console: [ 0.640459] Warning: unable to open an initial console. Fallback to ttynull.

init-1 [001] d..1 0.642563: console: [ 0.640464] printk: console [ttynull0] enabled

init-1 [001] d..2 0.642587: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=kworker/1:4 next_pid=109 next_prio=120

kworker/1:4-109 [001] d..2 0.642590: sched_switch: prev_comm=kworker/1:4 prev_pid=109 prev_prio=120 prev_state=I ==> next_comm=swapper/1 next_pid=0 next_prio=120

<idle>-0 [002] d..2 0.642630: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=irq/39-mmc0 next_pid=105 next_prio=49

<idle>-0 [001] d..2 0.642670: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/1:0 next_pid=20 next_prio=120

https://www.kernel.org/doc/html/latest/fault-injection/provoke-crashes.html

'Core BSP 분석 > 리눅스 커널 핵심 분석' 카테고리의 다른 글

중요 사이트: 리눅스 커널 디바이스 드라이버 (0)	2023.05.07
[리눅스커널] 특정 슬럽 오브젝트 트레이싱 (0)	2023.05.07
[리눅스커널] LKDTM(Linux Kernel Dump Test Module) 소개 -c (0)	2023.05.07
[리눅스커널] IPI Call 요청: SGI(Software Generated Interrupt) 요청 (로우 레벨 뷰) (0)	2023.05.07
[리눅스커널] IPI(Inter Processor Interrupt) Call 요청 루틴(하이 레벨 뷰) (0)	2023.05.07

[리눅스커널] LKDTM(Linux Kernel Dump Test Module) 소개 -c

AustinKim 2023. 5. 7. 16:52

2023. 5. 7. 16:52

LKDTM 소개

LKDTM은 Linux Kernel Dump Test Module (LKDTM)의 약자로 kdump를 활용해 덤프(vmcore)가 제대로 추출되는지 테스트하는 용도로 작성된 드라이버입니다.

관련 자료는 아래 링크에서 확인할 수 있습니다.

LKDTM 소스는 커널 버전이 업그레이드되면서 (불필요하게) 복잡해 졌는데요.

전체 구조는 예전 v3.18 소스를 보면 더 빨리 파악할 수 있습니다.

https://elixir.bootlin.com/linux/v3.18.130/source/drivers/misc/lkdtm.c

LKDTM 컨피그를 키는 방법

LKDTM는 드라이버 모듈 형식으로 빌드하거나 아예 빌트인으로 커널 이미지에 포함되도록 빌드할 수 있습니다. 이번에는 커널 이미지에 LKDTM을 포함시키는 방법을 소개합니다.

아래는 LKDTM 컨피그를 키는 예제 코드입니다. 라즈비안 커널 소스 기준입니다.

diff --git a/arch/arm64/configs/bcm2711_defconfig b/arch/arm64/configs/bcm2711_defconfig

index 16d756c..191fb28 100644

--- a/arch/arm64/configs/bcm2711_defconfig

+++ b/arch/arm64/configs/bcm2711_defconfig

@@ -16,6 +16,11 @@ CONFIG_IKCONFIG=m

CONFIG_IKCONFIG_PROC=y

CONFIG_MEMCG=y

CONFIG_BLK_CGROUP=y

CONFIG_DEBUG_INFO=y

+CONFIG_LKDTM=y

CONFIG_CFS_BANDWIDTH=y

CONFIG_CGROUP_PIDS=y

CONFIG_CGROUP_FREEZER=y

bcm2711_defconfig 파일에 'CONFIG_LKDTM=y' 코드 한 줄이 추가됐음을 확인할 수 있습니다.

위와 같은 커널 컨피그를 적용한 후 빌드를 하면, .config(빌드하면 생성되는)에서 'CONFIG_LKDTM=y'가 확인됩니다.

$ vi out/.config

...

CONFIG_FUNCTION_ERROR_INJECTION=y

# CONFIG_FAULT_INJECTION is not set

CONFIG_ARCH_HAS_KCOV=y

CONFIG_RUNTIME_TESTING_MENU=y

CONFIG_LKDTM=y

# CONFIG_TEST_MIN_HEAP is not set

'CONFIG_LKDTM=y'을 반영하고 커널을 빌드합니다. 빌드한 다음에 생성되는 커널 이미지를 타겟에 다운로드(플래시)합니다.

LKDTM 실행 하기 전 체크 포인트

LKDTM 컨피그가 플레시된 타겟 디바이스에서, LKDTM 실행 하기 전에 먼저 아래 파일이 제대로 보이는지 확인해야 합니다.

/sys/kernel/debug/provoke-crash

만약 위 파일이 보이지 않으면 'CONFIG_LKDTM=y' 컨피그에 제대로 적용되지 않고 빌드됐으니 다시 빌드를 해야 합니다.

LKDTM 간략한 코드 리뷰

LKDTM을 실행하는 방법을 설명드리기 전에 간단히 LKDTM에 대한 코드를 리뷰합니다.

LKDTM은 강제로 크래시를 유발할 수 있는 코드로 구성돼 있으며 각각 종류는 아래 코드에서 확인할 수 있습니다. (v5.4 기준)

https://elixir.bootlin.com/linux/v5.4.30/source/drivers/misc/lkdtm/core.c

/* Define the possible types of crashes that can be triggered. */

static const struct crashtype crashtypes[] = {

CRASHTYPE(PANIC),

CRASHTYPE(BUG),

CRASHTYPE(WARNING),

CRASHTYPE(WARNING_MESSAGE),

CRASHTYPE(EXCEPTION),

CRASHTYPE(LOOP),

CRASHTYPE(EXHAUST_STACK),

CRASHTYPE(CORRUPT_STACK),

CRASHTYPE(CORRUPT_STACK_STRONG),

CRASHTYPE(CORRUPT_LIST_ADD),

CRASHTYPE(CORRUPT_LIST_DEL),

CRASHTYPE(CORRUPT_USER_DS),

CRASHTYPE(STACK_GUARD_PAGE_LEADING),

CRASHTYPE(STACK_GUARD_PAGE_TRAILING),

CRASHTYPE(UNSET_SMEP),

CRASHTYPE(UNALIGNED_LOAD_STORE_WRITE),

CRASHTYPE(OVERWRITE_ALLOCATION),

CRASHTYPE(WRITE_AFTER_FREE),

CRASHTYPE(READ_AFTER_FREE),

CRASHTYPE(WRITE_BUDDY_AFTER_FREE),

CRASHTYPE(READ_BUDDY_AFTER_FREE),

CRASHTYPE(SLAB_FREE_DOUBLE),

CRASHTYPE(SLAB_FREE_CROSS),

CRASHTYPE(SLAB_FREE_PAGE),

CRASHTYPE(SOFTLOCKUP),

CRASHTYPE(HARDLOCKUP),

CRASHTYPE(SPINLOCKUP),

CRASHTYPE(HUNG_TASK),

CRASHTYPE(EXEC_DATA),

CRASHTYPE(EXEC_STACK),

CRASHTYPE(EXEC_KMALLOC),

CRASHTYPE(EXEC_VMALLOC),

CRASHTYPE(EXEC_RODATA),

CRASHTYPE(EXEC_USERSPACE),

CRASHTYPE(EXEC_NULL),

CRASHTYPE(ACCESS_USERSPACE),

CRASHTYPE(ACCESS_NULL),

CRASHTYPE(WRITE_RO),

CRASHTYPE(WRITE_RO_AFTER_INIT),

CRASHTYPE(WRITE_KERN),

CRASHTYPE(REFCOUNT_INC_OVERFLOW),

CRASHTYPE(REFCOUNT_ADD_OVERFLOW),

CRASHTYPE(REFCOUNT_INC_NOT_ZERO_OVERFLOW),

CRASHTYPE(REFCOUNT_ADD_NOT_ZERO_OVERFLOW),

CRASHTYPE(REFCOUNT_DEC_ZERO),

CRASHTYPE(REFCOUNT_DEC_NEGATIVE),

CRASHTYPE(REFCOUNT_DEC_AND_TEST_NEGATIVE),

CRASHTYPE(REFCOUNT_SUB_AND_TEST_NEGATIVE),

CRASHTYPE(REFCOUNT_INC_ZERO),

CRASHTYPE(REFCOUNT_ADD_ZERO),

CRASHTYPE(REFCOUNT_INC_SATURATED),

CRASHTYPE(REFCOUNT_DEC_SATURATED),

CRASHTYPE(REFCOUNT_ADD_SATURATED),

CRASHTYPE(REFCOUNT_INC_NOT_ZERO_SATURATED),

CRASHTYPE(REFCOUNT_ADD_NOT_ZERO_SATURATED),

CRASHTYPE(REFCOUNT_DEC_AND_TEST_SATURATED),

CRASHTYPE(REFCOUNT_SUB_AND_TEST_SATURATED),

CRASHTYPE(REFCOUNT_TIMING),

CRASHTYPE(ATOMIC_TIMING),

CRASHTYPE(USERCOPY_HEAP_SIZE_TO),

CRASHTYPE(USERCOPY_HEAP_SIZE_FROM),

CRASHTYPE(USERCOPY_HEAP_WHITELIST_TO),

CRASHTYPE(USERCOPY_HEAP_WHITELIST_FROM),

CRASHTYPE(USERCOPY_STACK_FRAME_TO),

CRASHTYPE(USERCOPY_STACK_FRAME_FROM),

CRASHTYPE(USERCOPY_STACK_BEYOND),

CRASHTYPE(USERCOPY_KERNEL),

CRASHTYPE(USERCOPY_KERNEL_DS),

CRASHTYPE(STACKLEAK_ERASING),

CRASHTYPE(CFI_FORWARD_PROTO),

};

크래시 타입 별로 크래시를 유발하는 코드를 확인하는게 중요한데요.

CRASHTYPE(BUG)은 다음 코드에 매핑됩니다.

https://elixir.bootlin.com/linux/v5.4.30/source/drivers/misc/lkdtm/bugs.c

void lkdtm_BUG(void)

{

BUG();

}

CRASHTYPE(EXCEPTION)에 매핑되는 루틴은 다음과 같습니다.

https://elixir.bootlin.com/linux/v5.4.30/source/drivers/misc/lkdtm/bugs.c

void lkdtm_EXCEPTION(void)

{

*((volatile int *) 0) = 0;

}

제가 위에서 정의된 크래시 타입을 전부 실행했는데, 대부분 크래시가 유발되나 크래시가 유발되지

않는 경우도 확인했습니다.

LKDTM 실행하기

(LKDTM 실행하기 전에 먼저 ftrace 이벤트를 활성화하면 좋습니다. vmcore에서 ftrace를 함께 보면 더 많은 디버깅 정보를 확인할 수 있거든요. e.g: sched_switch, irq_handle_entry, irq_handle_exit)

LKDTM을 실행하는 방법은 간단합니다. 셸을 하나 열고 아래 포멧으로 명령어를 입력하면 됩니다.

$ echo '크래시 타입' > /sys/kernel/debug/provoke-crash/DIRECT

몇 가지 예를 들겠습니다. CRASHTYPE(BUG)을 유발하려면 다음과 같은 명령어를 입력하면 됩니다.

$ echo BUG > /sys/kernel/debug/provoke-crash/DIRECT

'/sys/kernel/debug/provoke-crash/DIRECT'에 BUG 문자열을 전달하면 아래 코드가 실행됩니다.

https://elixir.bootlin.com/linux/v5.4.30/source/drivers/misc/lkdtm/bugs.c

void lkdtm_BUG(void)

{

BUG();

}

만약 스택을 오염(Corrupt) 시켜서 크래시를 유발하고 싶으면 아래 명령어를 입력하면 되겠네요.

$ echo CORRUPT_STACK > /sys/kernel/debug/provoke-crash/DIRECT

위 명령어를 실행하면 lkdtm_CORRUPT_STACK() 함수가 실행되면서 스택을 깹니다.

https://elixir.bootlin.com/linux/v5.4.30/source/drivers/misc/lkdtm/bugs.c

static noinline void __lkdtm_CORRUPT_STACK(void *stack)

{

memset(stack, '\xff', 64);

}

noinline void lkdtm_CORRUPT_STACK(void)

{

/* Use default char array length that triggers stack protection. */

char data[8] __aligned(sizeof(void *));

__lkdtm_CORRUPT_STACK(&data);

pr_info("Corrupted stack containing char array ...\n");

}

data를 char 타입인 배열(8)로 잡았는데, __lkdtm_CORRUPT_STACK() 함수에서 64바이트 사이즈로 메모리 카피를 하니 스택에 '\xff'를 덮어 씁니다.

권장 크래시 타입

사실 LKDTM으로 지원되는 크래시 타입을 모두 테스트하면 좋은데요.

실전 프로젝트에서 잘 발생하는 순서로 테스트를 하면 좋을 것 같아요.

주석을 달았으니 참고하시면 좋겠네요.

static const struct crashtype crashtypes[] = {

CRASHTYPE(PANIC), /* 테스트 요망 | 자주 발생 | 100% 유발 *'/

CRASHTYPE(BUG), /* 테스트 요망 | 자주 발생 | 100% 유발 *'/

CRASHTYPE(WARNING), /* 테스트 요망 | 발생 가능 | 크래시 유발안됨 *'/

CRASHTYPE(WARNING_MESSAGE),

CRASHTYPE(EXCEPTION), /* 테스트 요망 | 자주 발생 | 100% 유발 *'/

CRASHTYPE(LOOP),

CRASHTYPE(EXHAUST_STACK), /* 테스트 요망 | 종종 발생 | 100% 유발 *'/

CRASHTYPE(CORRUPT_STACK), /* 테스트 요망 | 종종 발생 | 100% 유발 *'/

CRASHTYPE(CORRUPT_STACK_STRONG),

CRASHTYPE(CORRUPT_LIST_ADD), /* 테스트 요망 | 자주 발생 | 100% 유발 *'/

CRASHTYPE(CORRUPT_LIST_DEL), /* 테스트 요망 | 자주 발생 | 100% 유발 *'/

CRASHTYPE(CORRUPT_USER_DS),

CRASHTYPE(STACK_GUARD_PAGE_LEADING),

CRASHTYPE(STACK_GUARD_PAGE_TRAILING),

CRASHTYPE(UNSET_SMEP),

CRASHTYPE(UNALIGNED_LOAD_STORE_WRITE),

CRASHTYPE(OVERWRITE_ALLOCATION),

CRASHTYPE(WRITE_AFTER_FREE), /* 테스트 요망 | 종종 발생(메모리 Corruption) | 100% 유발 *'/

CRASHTYPE(READ_AFTER_FREE), /* 테스트 요망 | 종종 발생(메모리 Corruption) | 100% 유발 *'/

CRASHTYPE(WRITE_BUDDY_AFTER_FREE),

CRASHTYPE(READ_BUDDY_AFTER_FREE),

CRASHTYPE(SLAB_FREE_DOUBLE),

CRASHTYPE(SLAB_FREE_CROSS),

CRASHTYPE(SLAB_FREE_PAGE),

CRASHTYPE(SOFTLOCKUP), /* 테스트 요망 | 자주 발생 | 100% 유발 *'/

CRASHTYPE(HARDLOCKUP), /* 테스트 요망 | 자주 발생 | 100% 유발 *'/

CRASHTYPE(SPINLOCKUP), /* 테스트 요망 | 종종 발생 | 100% 유발 *'/

CRASHTYPE(HUNG_TASK),

CRASHTYPE(EXEC_DATA),

CRASHTYPE(EXEC_STACK),

CRASHTYPE(EXEC_KMALLOC),

CRASHTYPE(EXEC_VMALLOC),

CRASHTYPE(EXEC_RODATA),

CRASHTYPE(EXEC_USERSPACE),

CRASHTYPE(EXEC_NULL),

CRASHTYPE(ACCESS_USERSPACE),

CRASHTYPE(ACCESS_NULL),

CRASHTYPE(WRITE_RO),

CRASHTYPE(WRITE_RO_AFTER_INIT),

CRASHTYPE(WRITE_KERN),

CRASHTYPE(REFCOUNT_INC_OVERFLOW),

CRASHTYPE(REFCOUNT_ADD_OVERFLOW),

CRASHTYPE(REFCOUNT_INC_NOT_ZERO_OVERFLOW),

CRASHTYPE(REFCOUNT_ADD_NOT_ZERO_OVERFLOW),

CRASHTYPE(REFCOUNT_DEC_ZERO),

CRASHTYPE(REFCOUNT_DEC_NEGATIVE),

CRASHTYPE(REFCOUNT_DEC_AND_TEST_NEGATIVE),

CRASHTYPE(REFCOUNT_SUB_AND_TEST_NEGATIVE),

CRASHTYPE(REFCOUNT_INC_ZERO),

CRASHTYPE(REFCOUNT_ADD_ZERO),

CRASHTYPE(REFCOUNT_INC_SATURATED),

CRASHTYPE(REFCOUNT_DEC_SATURATED),

CRASHTYPE(REFCOUNT_ADD_SATURATED),

CRASHTYPE(REFCOUNT_INC_NOT_ZERO_SATURATED),

CRASHTYPE(REFCOUNT_ADD_NOT_ZERO_SATURATED),

CRASHTYPE(REFCOUNT_DEC_AND_TEST_SATURATED),

CRASHTYPE(REFCOUNT_SUB_AND_TEST_SATURATED),

CRASHTYPE(REFCOUNT_TIMING),

CRASHTYPE(ATOMIC_TIMING),

CRASHTYPE(USERCOPY_HEAP_SIZE_TO),

CRASHTYPE(USERCOPY_HEAP_SIZE_FROM),

CRASHTYPE(USERCOPY_HEAP_WHITELIST_TO),

CRASHTYPE(USERCOPY_HEAP_WHITELIST_FROM),

CRASHTYPE(USERCOPY_STACK_FRAME_TO),

CRASHTYPE(USERCOPY_STACK_FRAME_FROM),

CRASHTYPE(USERCOPY_STACK_BEYOND),

CRASHTYPE(USERCOPY_KERNEL),

CRASHTYPE(USERCOPY_KERNEL_DS),

CRASHTYPE(STACKLEAK_ERASING),

CRASHTYPE(CFI_FORWARD_PROTO),

};

시그니처

LKDTM을 실행한 후 덤프(vmcore)에서 받은 커널 로그를 소개합니다.

아래는 'echo EXCEPTION > /sys/kernel/debug/provoke-crash/DIRECT' 명령어를 실행후 받은 덤프에서 확인한 커널 로그입니다.

[ 57.750675] Unable to handle kernel NULL pointer dereference at virtual address 00000000

[ 57.757757] pgd = ffffffc045138000

[ 57.761957] [00000000] *pgd=0000000000000000

[ 57.765404] Internal error: Oops: 96000045 [#1] PREEMPT SMP

[ 57.770949] Modules linked in:

[ 57.773996] CPU: 7 PID: 1897 Comm: sh Tainted: G B W 3.18.49-g9381d81-00083-gb8bb6a4-dirty #2

[ 57.783215] task: ffffffc04e980000 ti: ffffffc0450ec000 task.ti: ffffffc0450ec000

[ 57.790665] PC is at lkdtm_do_action+0x44/0x130

[ 57.795191] LR is at direct_entry+0x100/0x128

[ 57.799511] pc : [<ffffffc0006019e8>] lr : [<ffffffc000601bd4>] pstate: 80000145

[ 57.806883] sp : ffffffc0450efdb0

[ 57.810213] x29: ffffffc0450efdb0 x28: ffffffc0450ec000

[ 57.815480] x27: ffffffc00163b000 x26: 0000000000000040

[ 57.820774] x25: 0000000000000116 x24: 0000000000000015

[ 57.826068] x23: 0000000000000000 x22: 0000000000000003

[ 57.831370] x21: ffffffc0450efec8 x20: ffffffc02f240000

[ 57.836661] x19: 000000000000000a x18: 00000000ffffffff

[ 57.841956] x17: 0000007fa1e89344 x16: ffffffc0002ffb30

[ 57.847252] x15: 0000007fa1d1c120 x14: 0fffffffffffffff

[ 57.852549] x13: 0000000000000038 x12: 0101010101010101

[ 57.857842] x11: 7f7f7f7f7f7f7f7f x10: ff4d4e48534f4442

[ 57.863146] x9 : 7f7fffffffffffff x8 : 5045435845207972

[ 57.868430] x7 : 746e652074636572 x6 : ffffffc00186ee1f

[ 57.873727] x5 : 000000000000000a x4 : 0000000000000004

[ 57.879023] x3 : 0000000000000000 x2 : ffffffc0450ec000

[ 57.884316] x1 : ffffffc0006019d4 x0 : 0000000000000000 [ 57.889316] mdss_mdp_video_wait4comp: vsync wait timeout 0, fallback to poll mode

이번에는 'echo WRITE_AFTER_FREE > /sys/kernel/debug/provoke-crash/DIRECT' 명령어를 실행한 다음에 받은 덤프에서 확인한 커널 로그입니다.

[ 84.609150] lkdtm: Performing direct entry WRITE_AFTER_FREE

[ 84.127146] BUG kmalloc-1024 (Tainted: G B W ): Poison overwritten

[ 84.133909] -----------------------------------------------------------------------------

[ 84.143551] INFO: 0xffffffc00dd31600-0xffffffc00dd319fe. First byte 0x78 instead of 0x6b

[ 84.151630] INFO: Allocated in lkdtm_do_action+0xd4/0x130 age=8 cpu=4 pid=4509

[ 84.158827] +alloc_debug_processing+0x114/0x16c

[ 84.163340] +__slab_alloc.isra.52.constprop.58+0x3f4/0x504

[ 84.168805] +kmem_cache_alloc_trace+0x9c/0x1e8

[ 84.173234] +lkdtm_do_action+0xd0/0x130

[ 84.177053] +direct_entry+0xfc/0x128

[ 84.180617] +vfs_write+0xcc/0x178

[ 84.183912] +SyS_write+0x44/0x74

[ 84.187132] +cpu_switch_to+0x48/0x4c

[ 84.190689] INFO: Freed in lkdtm_do_action+0xdc/0x130 age=13 cpu=4 pid=4509

[ 84.197629] +free_debug_processing+0x22c/0x2cc

[ 84.202054] +__slab_free+0x44/0x2b0

[ 84.205525] +kfree+0x1f8/0x218

[ 84.208566] +lkdtm_do_action+0xd8/0x130

[ 84.212387] +direct_entry+0xfc/0x128

[ 84.215943] +vfs_write+0xcc/0x178

[ 84.219240] +SyS_write+0x44/0x74

[ 84.222454] +cpu_switch_to+0x48/0x4c

[ 84.226016] INFO: Slab 0xffffffbc05d12780 objects=23 used=23 fp=0x (null) flags=0x4080

[ 84.243379] Bytes b4 ffffffc00dd315f0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ

[ 84.837991] Object ffffffc00dd319f0: 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 xxxxxxxxxxxxxxxx

[ 84.847280] Redzone ffffffc00dd31a00: bb bb bb bb bb bb bb bb ........

[ 84.855961] Padding ffffffc00dd31b40: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ

[ 84.884090] Padding ffffffc00dd31b70: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ

[ 84.893467] CPU: 7 PID: 2510 Comm: Binder_10 Tainted: G B W 3.10.49-g9381d81-00083-gb8bb6a4-dirty #