Arm Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

37120
1703
402252


[리눅스커널] 워크큐: ftrace 워크큐 이벤트 소개 7. 워크큐(Workqueue)

커널은 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



덧글

  • 폭8 2022/04/05 14:00 # 삭제 답글

    안녕하세요 좋은 내용 감사드립니다
    추가로 각 event에서 필터 설정하여 원하는 항목만 볼 수 있습니다
    예시로 /sys/kernel/debug/tracing/events/workqueue/workqueue_execute_start 디렉토리 내에 enable 이외에 format, filter 파일이 있습니다.
    cat format 입력하면 해당 이벤트에서 다루는 데이터 형식을 볼 수 있고 이걸 참조하여 filter에 조건식을 넣게 됩니다.
    관심있는 워크를 filter에 지정하는 방법은 다음과 같습니다. (전체 workqueue event trace 한 것에서 해당 work 주소 찾아야 할 듯합니다)
    # echo "work==0xba372d70" > filter
    제 경우 watchdog 드라이버가 workqueue 사용하여 와치독 초기화 소요시간 측정을 위해 사용하였습니다.
    감사합니다
    https://community.silabs.com/s/article/linux-kernel-events-tracing?language=en_US (다음의 사이트 참고 하였습니다)
  • AustinKim 2022/04/06 21:12 #

    유익한 정보 감사합니다.
댓글 입력 영역