이번에는 라즈베리파이에서 워크가 실제 어떻게 동작하는지 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
최근 덧글