Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

111187
803
94440


[Linux][Kernel] ftrace - Workqueue 워크큐 로그 분석 - 1 8장. 워크큐

리눅스 커널의 매우 중요한 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
 => 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 로그를 코어 덤프와 병행해서 어떻게 디버깅할 수 있을까요?
 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]
     
     
우선 "work struct 0xed845d58" 로그에 주소가 보이죠?
crash> struct work_struct 0xed845d58
struct work_struct {
  data = {
    counter = 0xffffffe0
  },
  entry = {
    next = 0xedf1b9d4,
    prev = 0xedf1b9d4
  },
  func = 0xc03e9dc8 <touch_update_work>
}

struct work_struct.data 필드는 워크 상태를 알려주는 중요한 필드이거든요.

그런데 struct work_struct.data 값이 0xffffffe0이네요.
위 경우 INIT_WORK() 콜이 어디선가 불렀다는 걸 유추할 수 있어요.

#define INIT_WORK(_work, _func) \
do { \
__INIT_WORK((_work), (_func), 0); \
} while (0)

#define __INIT_WORK(_work, _func, _onstack) \
do { \
static struct lock_class_key __key; \
\
__init_work((_work), _onstack); \
(_work)->data = (atomic_long_t) WORK_DATA_INIT(); \  // #define WORK_DATA_INIT() ATOMIC_LONG_INIT(WORK_STRUCT_NO_POOL)
lockdep_init_map(&(_work)->lockdep_map, #_work, &__key, 0); \
INIT_LIST_HEAD(&(_work)->entry); \
(_work)->func = (_func); \
} while (0)
#else

struct work_struct.data 필드에 대해서 조금 더 정리하면요.
WORK_STRUCT_NO_POOL = 0xFFFFFFE0 -> INIT_WORK 호출 후 설정
WORK_STRUCT_PENDING = 0x1, -> queue_delayed_work_on() 함수 호출 후 설정
WORK_STRUCT_DELAYED = 0x2

WORK_STRUCT_PENDING을 설정하는 코드를 보세요.
bool queue_delayed_work_on(int cpu, struct workqueue_struct *wq,
   struct delayed_work *dwork, unsigned long delay)
{
struct work_struct *work = &dwork->work;
bool ret = false;
unsigned long flags;

/* read the comment in __queue_work() */
local_irq_save(flags);

if (!test_and_set_bit(WORK_STRUCT_PENDING_BIT, work_data_bits(work))) {


Appendix [1]
우선 아래와 같이 ftrace를 세팅하면 됩니다.
"echo 1 > /d/tracing/events/workqueue/workqueue_activate_work/enable"
"sleep 1"

"echo 1 > /d/tracing/events/workqueue/workqueue_queue_work/enable"
"sleep 1"

"echo 1 > /d/tracing/events/workqueue/workqueue_execute_start/enable"
"sleep 1"

"echo 1 > /d/tracing/events/workqueue/workqueue_execute_end/enable"
"sleep 1"

"echo 1 > /d/tracing/events/sched/sched_switch/enable"
"sleep 1"

"echo 1 > /d/tracing/events/irq/irq_handler_entry/enable"

"echo 1 > d/tracing/tracing_on"
"sleep 1"

로그는 "echo 0 > d/tracing/tracing_on"로 ftrace 로깅을 잠시 멈추어 주시고, "cat d/tracing/trace"을 하면 볼 수 있죠.

Reference(워크큐)
워크큐(Workqueue) Overview


Reference(프로세스 관리)
4.9 프로세스 컨택스트 정보는 어떻게 저장할까?
 4.9.1 컨택스트 소개
 4.9.2 인터럽트 컨택스트 정보 확인하기
 4.9.3 Soft IRQ 컨택스트 정보 확인하기
 4.9.4 선점 스케줄링 여부 정보 저장
4.10 프로세스 디스크립터 접근 매크로 함수
 4.10.1 current_thread_info()
 4.10.2 current 매크로란
4.11 프로세스 디버깅
 4.11.1 glibc fork 함수 gdb 디버깅
 4.11.2 유저 프로그램 실행 추적 

    덧글

    댓글 입력 영역