Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

79258
1323
114581


[라즈베리파이] 워크큐(Workqueue) - ftrace 동작 확인 8. Workqueue

이번에는 라즈베리파이에서 워크가 실제 어떻게 동작하는지 ftrace로 확인하겠습니다. 

이를 위해 다음과 같이 ftrace 로그를 설정할 필요가 있습니다.
#!/bin/sh

echo 0 > /sys/kernel/debug/tracing/tracing_on
sleep 1
echo "tracing_off"

echo 0 > /sys/kernel/debug/tracing/events/enable
sleep 1
echo "events disabled"

echo  secondary_start_kernel  > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter init"

echo function > /sys/kernel/debug/tracing/current_tracer
sleep 1
echo "function tracer enabled"

echo insert_work brcmf_sdio_dataworker > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"

echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable

echo 1 > /sys/kernel/debug/tracing/events/workqueue/enable 

sleep 1
echo "event enabled"

echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
echo "function stack trace enabled"

echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on"

이전 ftrace 설정과 다른 점은 다음과 같이 set_ftrace_filter로 insert_work() 함수와 brcmf_sdio_dataworker() 함수를 지정한다는 겁니다.
echo insert_work brcmf_sdio_dataworker > /sys/kernel/debug/tracing/set_ftrace_filter

insert_work() 함수는 워크를 워크큐에 큐잉할 때 호출되고 brcmf_sdio_dataworker() 함수는 라즈비안에서 구동하는 워크 핸들러 함수입니다.

두 함수를 set_ftrace_filter로 지정하면 워크를 워크큐에 큐잉하고 워커 쓰레드에서 워크를 실행하는 콜스택을 볼 수 있습니다.
 
다음은 워크큐 관련 ftrace 이벤트를 키는 설정입니다.
echo 1 > /sys/kernel/debug/tracing/events/workqueue/enable 

/sys/kernel/debug/tracing/events/workqueue 디렉토리에 가면 아래 워크큐 관련 이벤트를 볼 수 있는데, 위 명령어로 다음 이벤트들을 킬 수 있습니다. 
workqueue_queue_work, workqueue_activate_work, workqueue_execute_start, workqueue_execute_end

이렇게 ftrace를 설정하고 10초 후 ftrace 로그를 받습니다.

분석하려는 ftrace 로그는 다음과 같습니다.
1 irq/92-mmc1-65    [002] d...   335.716213: workqueue_queue_work: work struct=b972ca68 function=brcmf_sdio_dataworker [brcmfmac] workqueue=b7afd200 req_cpu=4 cpu=4294967295
2 irq/92-mmc1-65    [002] d...   335.716214: workqueue_activate_work: work struct b972ca68
3 irq/92-mmc1-65    [002] d...   335.716215: insert_work <-__queue_work
4 irq/92-mmc1-65    [002] d...   335.716236: <stack trace>
5 => brcmf_sdio_isr
6 => brcmf_sdiod_ib_irqhandler
7 => process_sdio_pending_irqs
8 => sdio_run_irqs
9 => bcm2835_mmc_thread_irq
10 => irq_thread_fn
11 => irq_thread
12 => kthread
13 => ret_from_fork
14 <idle>-0 [001] dnh. 335.716247: sched_wakeup: comm=kworker/u8:1 pid=1353 prio=120 target_cpu=001
15 irq/92-mmc1-65 [002] d... 335.716249: sched_switch: prev_comm=irq/92-mmc1 prev_pid=65 prev_prio=49 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
16 <idle>-0 [001] d... 335.716251: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=1353 next_prio=120
17 kworker/u8:1-1353  [001] ....   335.716257: workqueue_execute_start: work struct b972ca68: function brcmf_sdio_dataworker [brcmfmac]
18 kworker/u8:1-1353  [001] ....   335.716258: brcmf_sdio_dataworker <-process_one_work
19 kworker/u8:1-1353  [001] ....   335.716267: <stack trace>
20 => worker_thread
21 => kthread
22 => ret_from_fork

위 ftrace 로그는 다음 그림과 같이 3 단계로 나눌 수 있습니다.

각각 단계별로 동작 흐름을 정리해 보겠습니다.

[1] 단계
워크를 워크큐에 큐잉하는 동작입니다. __queue_work() -> insert_work() 함수 흐름으로 워크를 워크큐에 큐잉하는 겁니다.

[2] 단계
워크를 워크큐에 큐잉하고 난 후 wake_up_worker() 함수 호출로 워커 쓰레드를 깨웁니다.

[3] 단계
스케쥴링으로 워커 쓰레드가 깨어나 동작을 시작합니다. 워커 쓰레드 핸들 함수인 worker_thread() 함수에서 process_one_work() 함수를 호출해서 워크 핸들러 함수를 호출합니다.

이제 [1]단계 ftrace 로그부터 분석을 시작합니다.

1번 줄 로그부터 분석하겠습니다.
1 irq/92-mmc1-65 [002] d... 335.716213: workqueue_queue_work: work struct=b972ca68 function=brcmf_sdio_dataworker [brcmfmac] workqueue=b7afd200 req_cpu=4 cpu=4294967295
2 irq/92-mmc1-65    [002] d...   335.716214: workqueue_activate_work: work struct b972ca68

먼저 가장 왼쪽 "irq/92-mmc1-65" 메시지를 보면 실행 중인 프로세스는 pid가 65인 "irq/92-mmc1"입니다. 

이런 유형의 프로세스는 IRQ Thread라고 이전 장에서 배웠습니다. IRQ Thread 이름으로 92번 "mmc1" 인터럽트 후반부를 처리하는 IRQ Thread라는 점을 유추할 수 있습니다.

이제 workqueue_queue_work와 workqueue_activate_work 이벤트 로그를 보겠습니다.
워크 핸들러가 brcmf_sdio_dataworker() 함수인 워크를 워크큐에 큐잉하는 동작입니다. struct work_struct 구조체 주소는 0xb972ca68입니다.

2번 줄 로그를 보면 workqueue_activate_work 이벤트 메시지가 보이니 풀 워크에 링크드 리스트에 struct work_struct.entry 주소를 추가했다는 정보를 알 수 있습니다.

다음 3번 줄 로그를 보겠습니다.
3 irq/92-mmc1-65    [002] d...   335.716215: insert_work <-__queue_work
4 irq/92-mmc1-65    [002] d...   335.716236: <stack trace>
5 => brcmf_sdio_isr
6 => brcmf_sdiod_ib_irqhandler
7 => process_sdio_pending_irqs
8 => sdio_run_irqs
9 => bcm2835_mmc_thread_irq
10 => irq_thread_fn
11 => irq_thread
12 => kthread
13 => ret_from_fork

3~13줄 로그로 전체 콜스택 흐름을 보면 irq_thread_fn() -> bcm2835_mmc_thread_irq() 함수 흐름으로 IRQ Thread 핸들러 bcm2835_mmc_thread_irq() 함수가 처리되는 과정에서 워크를 워크큐에 큐잉했음을 알 수 있습니다. 이후 __queue_work() 함수와 insert_work() 함수 순서로 함수 호출이 수행되어 워크를 워크큐에 큐잉합니다.

이 때 struct work_struct 구조체 주소는 0xb972ca68이며 워크 핸들러는 brcmf_sdio_dataworker() 함수 입니다.

다음 14번 줄 로그부터 분석하겠습니다.
14 <idle>-0 [001] dnh. 335.716247: sched_wakeup: comm=kworker/u8:1 pid=1353 prio=120 target_cpu=001
15 irq/92-mmc1-65 [002] d... 335.716249: sched_switch: prev_comm=irq/92-mmc1 prev_pid=65 prev_prio=49 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
16 <idle>-0 [001] d... 335.716251: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=1353 next_prio=120

워크를 워크큐에 큐잉했으니 insert_work() 함수에서 wake_up_worker() 함수를 호출해서 워커 쓰레드를 깨우는 동작을 합니다.

14번 줄 로그는 <idle>-0 프로세스에서 "kworker/u8:1" 이란 워커 쓰레드를 깨우는 동작입니다. pid가 1353인 "kworker/u8:1" 프로세스를 런큐에 큐잉하면 스케쥴러는 이 시점의 프로세스 우선 순위를 점검하고 스케쥴러는 "kworker/u8:1" 프로세스를 실행합니다.

15번 줄 로그는 "irq/92-mmc1-65" 이란 IRQ Thread는  "swapper/2"로 스케쥴링됩니다.
16번 줄 로그에서 "<idle>-0" 프로세스에서 "kworker/u8:1" 프로세스로 스케쥴링됩니다. 이제 "kworker/u8:1"이란 워커 쓰레드가 실행하기 직전입니다.

이제부터 다음 그림 [3] 단계 ftrace 로그를 분석을 시작하겠습니다. [1]과 [2] 단계에서 워크를 워크큐에 큐잉한 다음 워커 쓰레드를 깨웠으니 [3] 단계에서는 워커 쓰레드가 깨어나 큐잉한 워크를 실행합니다.

17번 로그를 볼 차례입니다.
17 kworker/u8:1-1353  [001] ....   335.716257: workqueue_execute_start: work struct b972ca68: function brcmf_sdio_dataworker [brcmfmac]

우선 가장 오른편 로그를 보면 실행 중인 프로세스는 pid가 1353인 “kworker/u8:1”입니다. “kworker/u8:1”이란 프로세스 이름으로 워커 쓰레드임을 알 수 있습니다.

마지막 18번 줄 로그부터 콜스택을 확인해보겠습니다.
18 kworker/u8:1-1353  [001] ....   335.716258: brcmf_sdio_dataworker <-process_one_work
19 kworker/u8:1-1353  [001] ....   335.716267: <stack trace>
20 => worker_thread
21 => kthread
22 => ret_from_fork

18번과 20번 줄 로그로 worker_thread() -> process_one_work() 흐름으로 함수 호출 흐름을 볼 수 있습니다. 

워커 쓰레드는 쓰레드 핸들 함수가 worker_thread() 입니다. worker_thread 함수에서 process_one_work() 함수를 호출해서 brcmf_sdio_dataworker() 이란 워크 핸들러 함수를 호출합니다.

리눅스 커널 코드 분석을 하면 시야가 좁아져 전체 코드 흐름을 파악하기 어렵습니다. 그래서 커널 코드를 분석하고 나서 ftrace 로 함수 실행 흐름을 점검할 필요가 있습니다.

다음에 워크를 관련 코드를 실제 입력해서 라즈베리파이에서 동작을 확인합니다.


Reference(워크큐)
워크큐(Workqueue) Overview


덧글

  • padawan 2018/09/27 11:51 # 삭제 답글

    커널 소스를 분석 하다보면 시야가 좁아진다는 말이 와닿습니다.
    Source Insight를 이용해서 정적으로 커널 소스를 분석 하면서 저도 동일한 생각을 했습니다.
    포인터와 구조체를 머릿속으로 따라가면서 그림을 그리다보면... 지금 이 함수가 뭐하는 함수였더라? 던가..
    처음에 어디서 시작 했더라? 같은 상황을 마주하게 되더라고요.
    이제 막 ftrace를 사용 해 보기 시작했는데.. 저도 적극 활용해 보려고 합니다.
    분석하신 내용을 쉽게 설명 해 주셔서 참 좋습니다.
  • Guillermo 2018/09/27 13:19 #

    ftrace 는 자주 활용하면 좋은 기능입니다. ftrace 추가 설정은 다음 글을 참고하세요.
    http://rousalome.egloos.com/9940849
댓글 입력 영역