보통 커널 크래시나 와치독 리셋으로 시스템이 다운된 경우 세밀하게 디버깅해야 할 때가 있어요.
그런데 가끔 각 프로세스가 마지막에 어떤 순서로 실행이 됐는지 확인하고 싶을 경우가 가끔 있거든요.
이 순서가 가끔 정말 중요한 순간이 가끔 있어요.
아래는 런큐에서 돌고 있는 프로세스 목록이거든요. 그럼 각각 프로세스가 어떤 순서로 실행이 되었는지 알 수 있을까요?
crash64> runq -m
CPU 0: [0 07:36:22.901] PID: 585 TASK: ffffffc071eb8b80 COMMAND: "android.hardwar"
CPU 1: [0 07:36:22.901] PID: 726 TASK: ffffffc0f6e3f300 COMMAND: "DispSync"
CPU 2: [0 07:36:22.900] PID: 18654 TASK: ffffffc089b82280 COMMAND: "dm_router"
CPU 3: [0 07:36:22.901] PID: 16266 TASK: ffffffc089b85c00 COMMAND: "iptables"
런큐 Structure를 보면 struct rq->clock 변수가 있거든요. 이게 타임 스탬프인데 이 값으로 프로세스가 실행된 순서를
확인할 수 있어요.
crash64> struct rq
struct rq {
raw_spinlock_t lock;
unsigned int nr_running;
// .. 생략..
struct mm_struct *prev_mm;
u64 clock;
u64 clock_task;
왜냐면요, CPU별로 Runqueue(런큐)가 실행된 시간은 Runqueue struct rq.curr 구조체로 등록이 되어
돌고 있는 아래 프로세스의 시간이라고 볼 수 있거든요.
crash64> runq -m
CPU 0: [0 07:36:22.901] PID: 585 TASK: ffffffc071eb8b80 COMMAND: "android.hardwar"
CPU 1: [0 07:36:22.901] PID: 726 TASK: ffffffc0f6e3f300 COMMAND: "DispSync"
CPU 2: [0 07:36:22.900] PID: 18654 TASK: ffffffc089b82280 COMMAND: "dm_router"
CPU 3: [0 07:36:22.901] PID: 16266 TASK: ffffffc089b85c00 COMMAND: "iptables"
CPU0, CPU1, CPU2, CPU3부터 하나 하나 씩 점검해볼까요?
우선 각 per-cpu별 Runqueue 주소를 확인해볼께요.
CPU 0 RUNQUEUE: ffffffc0fe30e900
CURRENT: PID: 585 TASK: ffffffc071eb8b80 COMMAND: "android.hardwar"
//..생략..
CPU 1 RUNQUEUE: ffffffc0fe31d900
CURRENT: PID: 726 TASK: ffffffc0f6e3f300 COMMAND: "DispSync"
//..생략..
CPU 2 RUNQUEUE: ffffffc0fe32c900
CURRENT: PID: 18654 TASK: ffffffc089b82280 COMMAND: "dm_router"
//..생략..
CPU 3 RUNQUEUE: ffffffc0fe33b900
CURRENT: PID: 16266 TASK: ffffffc089b85c00 COMMAND: "iptables"
자 이제, 시작
crash64> struct rq.clock ffffffc0fe30e900
clock = 27382901302089
crash64> struct rq.clock ffffffc0fe31d900
clock = 27382901206517
crash64> struct rq.clock ffffffc0fe32c900
clock = 27382900987194
crash64> struct rq.clock ffffffc0fe33b900
clock = 27382901150527
ftrace 마지막 로그을 참고하면 타임 스탬프를 알 수 있거든요.
DispSync-726 [001] 27382.901292: sched_migrate_task: comm=EventThread pid=773 prio=97 load=0 orig_cpu=1 dest_cpu=0
DispSync-726 [001] 27382.901312: sched_enq_deq_task: cpu=0 enqueue comm=EventThread pid=773 prio=97 nr_running=6 cpu_load=4 rt_nr_running=1 affine=f demand=74448 pred_demand=74448
DispSync-726 [001] 27382.901323: sched_wakeup: comm=EventThread pid=773 prio=97 success=1 target_cpu=000
// end of ftrace log
가장 마지막에 실행된 프로세스 순서로 줄을 세우면 아래와 같네요.
CPU0: 27382.901302089, "android.hardwar"
CPU1: 27382.901206517, "DispSync"
CPU3: 27382.901150527, "iptables"
CPU2: 27382.900987194, "dm_router"
이제 정리하면, struct rq.clock 멤버 변수로 Runqueue가 실행되기 직전 시간 정보를 확인수 있는데요. 어느 코드에서 확인할 수 있을까요?
Runqueue에 프로세스를 큐잉할 때 enqueue_task -> update_rq_clock 흐름으로, update_rq_clock() 함수에서 업데이트가 되네요.
static void enqueue_task(struct rq *rq, struct task_struct *p, int flags)
{
update_rq_clock(rq); // <<--
sched_info_queued(rq, p);
p->sched_class->enqueue_task(rq, p, flags);
trace_sched_enq_deq_task(p, 1, cpumask_bits(&p->cpus_allowed)[0]);
}
void update_rq_clock(struct rq *rq)
{
s64 delta;
if (rq->skip_clock_update > 0)
return;
delta = sched_clock_cpu(cpu_of(rq)) - rq->clock;
if (delta < 0)
return;
rq->clock += delta;
update_rq_clock_task(rq, delta);
}
# Reference (ARM Processor)
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
최근 덧글