Arm Linux Kernel Hacks : [Linux][Kernel] ftrace - Workqueue 워크큐 로그 분석

리눅스 커널의 매우 중요한 Subsystem인 워크큐.

이번에는 잠깐 ftrace 로그에서 workqueue에 대해 분석을 해보려고 해요.

ftrace 세팅은 Appendix [1]을 참고하시구요.

아래 로그는 보자마자 느낄 수 있는 건 irq/225-touch-279란 irq_thread에서 워크 큐를 큐잉하고 이 후 워크큐가 실행된다는 걸 알 수 있죠.

irq/225-touch-279 [006] 53516.537609: workqueue_queue_work: work struct=0xed845d58 function=touch_update_work workqueue=0xed80cc00 req_cpu=8 cpu=6 //<<--[1]

irq/225-touch-279 [006] 53516.537613: workqueue_activate_work: work struct 0xed845d58 //<<--[2]

irq/225-touch-279 [006] 53516.537633: sched_wakeup: comm=kworker/6:2 pid=19595 prio=120 success=1 target_cpu=006

irq/225-touch-279 [006] 53516.537674: sched_wakeup: comm=InputReader pid=1856 prio=112 success=1 target_cpu=004

HeapTaskDaemon-15004 [004] 53516.537695: sched_switch: prev_comm=HeapTaskDaemon prev_pid=15004 prev_prio=120 prev_state=R+ ==> next_comm=InputReader next_pid=1856 next_prio=112

irq/225-touch-279 [006] 53516.537704: sched_switch: prev_comm=irq/225-touch-279 prev_pid=279 prev_prio=49 prev_state=S ==> next_comm=kworker/6:2 next_pid=19595 next_prio=120

kworker/6:2-19595 [006] 53516.537713: workqueue_execute_start: work struct 0xed845d58: function touch_update_work //<<--[3]

kworker/6:2-19595 [006] 53516.537718: workqueue_execute_end: work struct 0xed845d58 //<<--[4]

ftrace log 로그 분석

1> workqueue_queue_work

이 로그는 아래 __queue_work() 함수에서 찍는데요.

static void __queue_work(int cpu, struct workqueue_struct *wq,

struct work_struct *work)

{

struct pool_workqueue *pwq;

struct worker_pool *last_pool;

struct list_head *worklist;

// .. 생략..

/* pwq determined, queue */

trace_workqueue_queue_work(req_cpu, pwq, work);

ftrace stack trace로 콜 트래이스를 찍어보면 아래 정보 확인이 가능해요.

queue_work_on() -> __queue_work() 이런 콜트레이스

=> __queue_work

=> queue_work_on

=> queue_release_one_tty

=> tty_kref_put

=> release_tty

=> tty_release

=> __fput

=> ____fput

=> task_work_run

=> do_work_pending

=> work_pending

delayed_work_timer_fn() -> __queue_work() 이런 콜트레이스. 음 딜레이 워크큐이네요.

=> __queue_work

=> delayed_work_timer_fn

=> call_timer_fn

=> run_timer_softirq

=> __do_softirq

=> irq_exit

=> __handle_domain_irq

=> gic_handle_irq

=> __irq_svc

=> lpm_cpuidle_enter

=> cpuidle_enter_state

=> cpuidle_enter

=> cpu_startup_entry

=> secondary_start_kernel

=> rest_init

=> start_kernel

주로 schedule_work() 함수 호출로 아래 콜 스트레이스로 workqueue에 큐잉할 때 찍힙니다.

2> workqueue_activate_work

두 군데 함수에서 출력해요. __queue_work(), pwq_activate_delayed_work()

__queue_work()는 보통 schedule_work() API를 써서 호출되는 워크큐이구요,

pwq_activate_delayed_work는 delayed_work()을 쓸 때 호출되요.

static void __queue_work(int cpu, struct workqueue_struct *wq,

struct work_struct *work)

{

struct pool_workqueue *pwq;

struct worker_pool *last_pool;

// .. 생략..

pwq->nr_in_flight[pwq->work_color]++;

work_flags = work_color_to_flags(pwq->work_color);

if (likely(pwq->nr_active < pwq->max_active)) {

trace_workqueue_activate_work(work); //<<--

pwq->nr_active++;

static void pwq_activate_delayed_work(struct work_struct *work)

{

struct pool_workqueue *pwq = get_work_pwq(work);

trace_workqueue_activate_work(work);

#ftrace log

kworker/3:2-851 [003] d..2 191.820204: process_one_work <-worker_thread

kworker/3:2-851 [003] d..2 191.820213: <stack trace>

=> process_one_work

=> worker_thread

=> kthread

=> ret_from_fork

2> workqueue_execute_start/workqueue_execute_end

worker->current_func(work); 함수 전후로 이 로그를 찍네요.

워크큐를 디버깅할 때 가장 많이 보는 로그이거든요.

static void process_one_work(struct worker *worker, struct work_struct *work)

__releases(&pool->lock)

__acquires(&pool->lock)

{

struct pool_workqueue *pwq = get_work_pwq(work);

struct worker_pool *pool = worker->pool;

bool cpu_intensive = pwq->wq->flags & WQ_CPU_INTENSIVE;

// .. 생략..

lock_map_acquire(&lockdep_map);

trace_workqueue_execute_start(work); //<<--

worker->current_func(work);

* While we must be careful to not use "work" after this, the trace

* point will only record its address.

trace_workqueue_execute_end(work); //<<--

콜 트래이스는 아주 많이 본 거 같죠? kworker/3:2-851는 워커 쓰래드라는 걸 알 수 있어요.

kworker/3:2-851 [003] d..2 191.820204: process_one_work <-worker_thread

kworker/3:2-851 [003] d..2 191.820213: <stack trace>

=> process_one_work

=> worker_thread

=> kthread

=> ret_from_fork

디버깅

아래 ftrace 로그를 코어 덤프와 병행해서 어떻게 디버깅할 수 있을까요?