이전에 소개한 용어와 함께 간단히 워크가 어떤 흐름으로 실행하는지 간단히 코드와 ftrace 로그를 살펴봅시다.
[https://elixir.bootlin.com/linux/v4.14.43/source/drivers/tty/vt/vt.c]
static DECLARE_WORK(console_work, console_callback);
워크를 실행하려면 우선 워크를 초기화해야 하는데 2가지 방법으로 나눌 수 있습니다. 워크를 전역 변수로 지정하는 방법과 커널 코드가 실행할 때 INIT_WORK() 매크로를 써서 워크를 초기화하는 방법입니다. 위 코드에서는 console_work 전역 변수로 워크를 선언했습니다.
워크를 표현하는 구조체는 struct work_struct인데 이 변수가 console_work이고 워크가 실행할 때 호출하는 핸들러는 console_callback() 함수입니다.
[https://elixir.bootlin.com/linux/v4.14.43/source/drivers/tty/vt/keyboard.c#L1454]
1 static void kbd_event(struct input_handle *handle, unsigned int event_type,
2 unsigned int event_code, int value)
3 {
4 /* We are called with interrupts disabled, just take the lock */
...
5 schedule_console_callback();
6}
7
8 void schedule_console_callback(void)
9 {
10 schedule_work(&console_work);
11 }
위와 같이 kbd_event() 함수 5번 줄 코드를 보면 schedule_console_callback() 함수를 호출하는데 schedule_console_callback() 함수 10번 줄 코드에서 console_work이란 워크를 schedule_work() 함수 인자로 입력해서 호출합니다. 이 코드가 워크를 워크큐에서 큐잉하는 동작입니다.
console_work이란 워크는 워커 쓰레스가 실행하며 이때 워크 핸들러인 console_callback() 함수를 호출합니다.
static void console_callback(struct work_struct *ignored)
{
console_lock();
if (want_console >= 0) {
이런 흐름으로 워커 쓰레드에서 워크를 실행합니다.
하지만 이렇게 코드만 보면 워크가 어떻게 실행하는지 큰 흐름을 그리기 어려우니 라즈베리파이에서 ftrace로 console_work이란 워크가 어떻게 실행하는지 확인할 필요가 있습니다.
분석하려는 ftrace 로그는 다음과 같습니다.
1 <idle>-0 [000] d.s. 180.551368: workqueue_queue_work: work struct=80c5bc3c function=console_callback workqueue=b9c06300 req_cpu=4 cpu=0
2 <idle>- [000] d.s. 180.551371: workqueue_activate_work: work struct 80c5bc3c
3 <idle>-0 [000] d.s. 180.551375: insert_work <-__queue_work
4 <idle>-0 [000] d.s. 180.551448: <stack trace>
5 => schedule_console_callback
6 => kbd_event
7 => input_to_handler
8 => input_pass_values.part.1
9 => input_repeat_key
10 => call_timer_fn
11 => expire_timers
12 => run_timer_softirq
13 => __do_softirq
14 => irq_exit
15 => __handle_domain_irq
16 => bcm2836_arm_irqchip_handle_irq
17 => __irq_svc
18 => arch_cpu_idle
19 => arch_cpu_idle
20 => default_idle_call
21 => do_idle
22 => cpu_startup_entry
23 => rest_init
24 => start_kernel
25 <idle>-0 [000] dns. 180.551462: sched_wakeup: comm=kworker/0:1 pid=29 prio=120 target_cpu=000
26 <idle>-0 [003] dnh. 180.551490: sched_wakeup: comm=thd pid=312 prio=120 target_cpu=003
...
27 <idle>-0 [000] d... 180.551574: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:1 next_pid=29 next_prio=120
28 kworker/0:1-29 [000] .... 180.551582: workqueue_execute_start: work struct 80c5bc3c: function console_callback
29 kworker/0:1-29 [000] .... 180.551585: console_callback <-process_one_work
30 kworker/0:1-29 [000] .... 180.551603: <stack trace>
31 => worker_thread
32 => kthread
33 => ret_from_fork
34 kworker/0:1-29 [000] .... 180.551616: workqueue_execute_end: work struct 80c5bc3c
1번 줄 로그부터 봅시다.
1 <idle>-0 [000] d.s. 180.551368: workqueue_queue_work: work struct=80c5bc3c function=console_callback workqueue=b9c06300 req_cpu=4 cpu=0
2 <idle>- [000] d.s. 180.551371: workqueue_activate_work: work struct 80c5bc3c
1번 줄 workqueue_queue_work와 2번 줄 workqueue_activate_work 로그로 워크를 워크큐에 큐잉하는 동작을 확인할 수 있습니다. 워크 핸들러 함수가 console_callback()인 console_work를 워크큐에 큐잉하는 겁니다.
실제 이 동작이 어느 코드에서 수행되는지는 워크 실행을 점검하는 시간에 알아봅니다.
다음은 console_work를 워크큐에 큐잉하는 콜스택을 확인합시다.
3 <idle>-0 [000] d.s. 180.551375: insert_work <-__queue_work
4 <idle>-0 [000] d.s. 180.551448: <stack trace>
5 => schedule_console_callback
6 => kbd_event
7 => input_to_handler
8 => input_pass_values.part.1
9 => input_repeat_key
10 => call_timer_fn
11 => expire_timers
12 => run_timer_softirq
13 => __do_softirq
14 => irq_exit
15 => __handle_domain_irq
16 => bcm2836_arm_irqchip_handle_irq
17 => __irq_svc
18 => arch_cpu_idle
19 => arch_cpu_idle
20 => default_idle_call
21 => do_idle
22 => cpu_startup_entry
23 => rest_init
24 => start_kernel
18~24번 줄 로그를 보면 start_kernel() 함수부터 arch_cpu_idle() 함수까지 실행된 콜스택을 볼 수 있습니다. 아이들 프로세스의 전형적인 콜스택입니다. 참고로 아이들 프로세스는 런큐에 실행할 프로세스가 없을 때 실행하는 프로세스입니다.
17번 줄 로그에서 인터럽트 벡터인 __irq_svc 함수가 보이니 인터럽트가 발생했다 볼 수 있습니다.
13번 줄 로그에서 __do_softirq() 함수가 보이니 인터럽트 핸들링을 하고 난 후 Soft IRQ 서비스를 실행하는 흐름임을 알 수 있습니다.
[참고]
타이머 관리 장을 공부했으면 위 콜스택은 그리 어렵지 않게 분석할 수 있습니다. 라즈베리파이가 ARM CPU를 탑재하므로 ARM 프로세서 기준으로 인터럽트를 살펴봅니다.
13번 줄 로그에서 __do_softirq()이란 함수가 보이고 이후 동적 타이머 핸들러 함수를 처리하는 run_timer_softirq() -> expire_timers() -> call_timer_fn() 함수 흐름을 볼 수 있습니다.
동적 타이머 핸들러는 input_repeat_key() 함수인데 이후 kbd_event() 함수가 실행해서 schedule_console_callback () 함수를 호출합니다. 이 콜스택은 console_work이란 워크를 큐잉하는 동작입니다.
다음 25번 줄은 워크를 실행할 워커 쓰레드를 깨우는 로그입니다. pid가29인 kworker/0:1 워커 쓰레드를 깨우는 동작입니다.
25 <idle>-0 [000] dns. 180.551462: sched_wakeup: comm=kworker/0:1 pid=29 prio=120 target_cpu=000
이번에 워크가 실행하는 ftrace 로그를 볼 차례입니다.
27 <idle>-0 [000] d... 180.551574: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:1 next_pid=29 next_prio=120
28 kworker/0:1-29 [000] .... 180.551582: workqueue_execute_start: work struct 80c5bc3c: function console_callback
29 kworker/0:1-29 [000] .... 180.551585: console_callback <-process_one_work
30 kworker/0:1-29 [000] .... 180.551603: <stack trace>
31 => worker_thread
32 => kthread
33 => ret_from_fork
34 kworker/0:1-29 [000] .... 180.551616: workqueue_execute_end: work struct 80c5bc3c
27번 줄 로그를 보면 idle-0이란 프로세스에서 kworker/0:1 프로세스로 스케쥴링됩니다. 이제 kworker/0:1이라는 워커 쓰레드가 실행되기 직전입니다.
27 <idle>-0 [000] d... 180.551574: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:1 next_pid=29 next_prio=120
28번 줄 로그는 console_work를 실행하기 직전 동작을 표현합니다.
28 kworker/0:1-29 [000] .... 180.551582: workqueue_execute_start: work struct 80c5bc3c: function console_callback
가장 왼쪽에 보이는 “kworker/0:1-29” 는 현재 실행 중인 프로세스 이름은 kworker/0:1이고 pid는 29이라는 의미입니다. 워크는 워커 쓰레드가 실행함을 알 수 있습니다. 이때 console_work 워크 핸들러는 console_callback() 함수입니다.
29~33번 줄 로그를 보면 worker_thread()이라는 워커 쓰레드 핸들 함수가 process_one_work() 함수를 호출해서 console_callback() 워크 핸들러 함수를 호출합니다.
29 kworker/0:1-29 [000] .... 180.551585: console_callback <-process_one_work
30 kworker/0:1-29 [000] .... 180.551603: <stack trace>
31 => worker_thread
32 => kthread
33 => ret_from_fork
34번 로그는 console_work가 종료된 시점을 표현합니다.
28 kworker/0:1-29 [000] .... 180.551582: workqueue_execute_start: work struct 80c5bc3c: function console_callback
34 kworker/0:1-29 [000] .... 180.551616: workqueue_execute_end: work struct 80c5bc3c
console_work가 실행된 시점을 기록한 28번 로그에 출력된 타임스탬프와 비교하면 워크 핸들러 실행 시간(0.034 밀리 초)을 알 수 있습니다.
0.000034 = 180.551616 - 180.551582
여기까지 간단히 워크를 쓰는 드라이버와 ftrace 로그를 간단히 분석했습니다. 각각 로그가 어떤 코드에서 실행하는지는 다음에 상세히 다룰 예정입니다.
* 유튜브 강의 동영상도 있으니 같이 들으시면 좋습니다.
#Reference 워크큐
워크큐 소개
워크큐 종류 알아보기
워크란
워크를 워크큐에 어떻게 큐잉할까?
워크를 큐잉할 때 호출하는 워크큐 커널 함수 분석
워커 쓰레드란
워크큐 실습 및 디버깅
ftrace로 워크큐 동작 확인
인터럽트 후반부로 워크큐 추가 실습 및 로그 분석
Trace32로 워크큐 자료 구조 디버깅하기
딜레이 워크 소개
딜레이 워크는 누가 언제 호출할까?
라즈베리파이 딜레이 워크 실습 및 로그 확인
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
최근 덧글