커널은 ftrace에서 워크큐 동작을 디버깅할 수 있는 이벤트를 지원합니다. 이번 시간에 워크큐 실행 흐름을 추적하는 ftrace 이벤트 분석 방법을 소개합니다.
다음은 ftrace에서 지원하는 워크큐 이벤트입니다.
workqueue_queue_work: 워크를 워크큐에 큐잉함
workqueue_activate_work: 워크를 활성화
workqueue_execute_start: 워크 핸들러 실행 시작
workqueue_execute_end: 워크 핸들러 실행 마무리
먼저 ftrace 이벤트를 활성화하는 방법을 알아보고 ftrace에서 각 로그를 분석해보겠습니다.
워크큐 ftrace 이벤트 키기
워크큐 이벤트는 다음 명령어로 활성화할 수 있습니다.
"echo 1 > /sys/kernel/debug/tracing/events/workqueue/workqueue_activate_work/enable"
"echo 1 > /sys/kernel/debug/tracing/events/workqueue/workqueue_queue_work/enable"
"echo 1 > /sys/kernel/debug/tracing/events/workqueue/workqueue_execute_start/enable"
"echo 1 > /sys/kernel/debug/tracing/events/workqueue/workqueue_execute_end/enable"
이전 장에 소개한 ftrace 이벤트를 키는 방법과 유사합니다.
워크큐 ftrace 이벤트 로그 패턴와 실행 코드 확인하기
이어서 워크큐 ftrace 이벤트를 포멧을 소개합니다.
먼저 워크큐를 워크큐에 큐잉할 때 workqueue_queue_work와 workqueue_activate_work 이벤트를 포멧을 보겠습니다.
그림 7.15 ftrace: workqueue_queue_work와 workqueue_activate_work 이벤트 메시지
일반적인 상황에서 워크를 워크큐를 처음 큐잉할 때 두 이벤트가 나란히 출력됩니다.
이어서 워크를 실행할 때 동작을 출력하는 workqueue_execute_start와 workqueue_execute_end 이벤트 메시지 포멧을 보겠습니다.
그림 7.16 ftrace: workqueue_execute_start와 workqueue_execute_end 이벤트 메시지
workqueue_execute_start와 workqueue_execute_end 이벤트 메시지에서 보이는 타임 스탬프를 참고하면 워크 핸들러가 실행한 시간을 알 수 있습니다.
각각 메시지의 의미와 메시지를 출력하는 함수 이름은 다음 테이블과 같습니다.
이벤트 종류 동작 실행 함수
workqueue_queue_work 워크를 워크큐에 큐잉함 __queue_work()
workqueue_activate_work 워크를 활성화 __queue_work()
workqueue_execute_start 워크 핸들러 실행 시작 process_one_work()
workqueue_execute_end 워크 핸들러 실행 종료 process_one_work()
이번에는 각각 이벤트를 실행하는 커널 코드를 소개합니다.
먼저 workqueue_queue_work와 workqueue_activate_work 이벤트를 출력하는 코드를 보겠습니다.
https://elixir.bootlin.com/linux/v4.19.30/source/kernel/workqueue.c
01 static void __queue_work(int cpu, struct workqueue_struct *wq,
02 struct work_struct *work)
03 {
04 struct pool_workqueue *pwq;
05 struct worker_pool *last_pool;
...
06 /* pwq determined, queue */
07 trace_workqueue_queue_work(req_cpu, pwq, work);
...
08 if (likely(pwq->nr_active < pwq->max_active)) {
09 trace_workqueue_activate_work(work);
10 pwq->nr_active++;
11 worklist = &pwq->pool->worklist;
12 if (list_empty(worklist))
13 pwq->pool->watchdog_ts = jiffies;
14 } else {
15 work_flags |= WORK_STRUCT_DELAYED;
16 worklist = &pwq->delayed_works;
18 }
19
20 insert_work(pwq, work, worklist, work_flags);
07번째 줄 코드를 실행할 때 workqueue_queue_work 이벤트 메시지를 출력합니다.
07 trace_workqueue_queue_work(req_cpu, pwq, work);
이어서 09번째 줄 코드를 실행하면 workqueue_activate_work 이벤트 메시지를 출력합니다.
08 if (likely(pwq->nr_active < pwq->max_active)) {
09 trace_workqueue_activate_work(work);
리눅스 드라이버에서 max_active 값과 같이 255개 이상의 워크를 큐잉한 상태가 아니면 09번째 줄 코드를 실행합니다.
다음 workqueue_execute_start와 workqueue_execute_end ftrace 이벤트를 출력하는 코드를 봅시다.
https://elixir.bootlin.com/linux/v4.19.30/source/kernel/workqueue.c
01 static void process_one_work(struct worker *worker, struct work_struct *work)
02 __releases(&pool->lock)
03 __acquires(&pool->lock)
04 {
05 struct pool_workqueue *pwq = get_work_pwq(work);
06 struct worker_pool *pool = worker->pool;
...
07 worker->current_work = work;
08 worker->current_func = work->func;
09 worker->current_pwq = pwq;
...
10 trace_workqueue_execute_start(work);
11 worker->current_func(work);
12
13 trace_workqueue_execute_end(work);
워크큐를 디버깅할 때 workqueue_execute_start와 workqueue_execute_end 이벤트 메시지를 참고합니다.
실전 리눅스 드라이버에서 ftrace 메시지 정보로 진행했던 워크 디버깅 사례를 소개합니다.
* 1번째 상황: 워크 핸들러 실행 시간이 오래 걸린 경우
workqueue_execute_start ftrace 로그가 찍히고 3초 후 workqueue_execute_end가 출력됐다면 워크 핸들러 함수의 실행 시간을 점검할 필요가 있습니다. 또한 워크 핸들러 실행 빈도를 점검할 필요가 있습니다. 워크를 큐잉한 빈도가 너무 높으면 워크 핸들러 실행 시간이 오래 걸릴 수도 있습니다.
*2 번째 상황: 워크 핸들러에서 휴면에 진입한 경우
워크 핸들러를 실행할 때 workqueue_execute_start 로그 이후 workqueue_execute_end 이벤트 로그가 안 보이면 해당 워크 핸들러에서 휴면에 빠졌다고 판단할 수 있습니다.
워크 핸들러는 프로세스 레벨에서 휴면에 진입할 수 있지만 실행 시간이 너무 오래 걸리면 이상 동작을 할 수 있습니다.
워크큐 ftrace 이벤트 로그 분석하기
이번에는 ftrace에서 워크큐 이벤트를 분석하는 방법을 소개합니다.
분석할 ftrace 로그는 다음과 같습니다.
01 <idle>-0 [002] d.s. 149.153334: workqueue_queue_work: work struct=ba372d70 function=vmstat_update workqueue=b9e33500 req_cpu=2 cpu=2
02 <idle>-0 [002] d.s. 149.153336: workqueue_activate_work: work struct ba372d70
03 <idle>-0 [002] dns. 149.153402: sched_wakeup: comm=kworker/2:2 pid=122 prio=120 target_cpu=002
04 <idle>-0 [002] d... 149.153443: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/2:2 next_pid=122 next_prio=120
05 kworker/2:2-122 [002] .... 149.153452: workqueue_execute_start: work struct ba372d70: function vmstat_update
06 kworker/2:2-122 [002] .... 149.153458: workqueue_execute_end: work struct ba372d70
먼저 01~02 번째 줄 로그를 보겠습니다.
01 <idle>-0 [002] d.s. 149.153334: workqueue_queue_work: work struct=ba372d70 function=vmstat_update workqueue=b9e33500 req_cpu=2 cpu=2
02 <idle>-0 [002] d.s. 149.153336: workqueue_activate_work: work struct ba372d70
워크를 워크큐에 큐잉하는 동작입니다.
다음 03~04번째 줄 로그입니다.
03 <idle>-0 [002] dns. 149.153402: sched_wakeup: comm=kworker/2:2 pid=122 prio=120 target_cpu=002
04 <idle>-0 [002] d... 149.153443: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==>
03 번째 줄은 워커 스레드인 “kworker/2:2” 프로세스를 깨우는 동작입니다.
다음 05~06 번째 줄입니다.
05 kworker/2:2-122 [002] .... 149.153452: workqueue_execute_start: work struct ba372d70: function vmstat_update
06 kworker/2:2-122 [002] .... 149.153458: workqueue_execute_end: work struct ba372d70
워크 핸들러를 실행하는 동작입니다. 로그를 해석하면 다음과 같습니다.
149.153452 초: 워크 핸들러인 vmstat_update() 함수 실행 시작
149.153458 초: 워크 핸들러인 vmstat_update() 함수 실행이 종료
이렇게 워크 실행 흐름을 추적하는 ftrace 이벤트 메시지를 잘 활용하면 워크와 관련된 동작을 디버깅할 수 있습니다.
워크를 제대로 워크큐에 큐잉했는지
워크 핸들러 실행 시간이 오래 걸렸는지
이번 소절에서는 워크 실행 흐름을 추적해주는 ftrace 이벤트를 소개했습니다. 다음 소절에서는 라즈베리파이에서 ftrace로 워크큐 동작을 확인하는 실습을 이어갑니다.
Edited: 04/19/2020
최근 덧글