Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

230224
1178
109352


Runqueue(런큐) Timestamp(실행 시간) 확인 4. Process Management

보통 커널 크래시나 와치독 리셋으로 시스템이 다운된 경우 세밀하게 디버깅해야 할 때가 있어요.
그런데 가끔 각 프로세스가 마지막에 어떤 순서로 실행이 됐는지 확인하고 싶을 경우가 가끔 있거든요.
이 순서가 가끔 정말 중요한 순간이 가끔 있어요.

아래는 런큐에서 돌고 있는 프로세스 목록이거든요. 그럼 각각 프로세스가 어떤 순서로 실행이 되었는지 알 수 있을까요?
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(프로세스 관리)
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 유저 프로그램 실행 추적 

    핑백

    덧글

    댓글 입력 영역