4장 process 로그 확인

책 “디버깅을 통해.. 리눅스 커널” 148 페이지 예제를 실행했다. 잘 따라 해야 한다. trace 를 죽이고 살리는 과정에 오타로 살짝 헷갈렸다. 책은 /sys/kernel/debug/tracing/trace를 복사하는 script를 만들었다. 디버그 메세지를 보려면 이벤트 발생 후 바로 복사해야지, 타이핑한다고 늦게 하면 이전 기록을 시스템이 지워버린다. trace 파일을 지울 수 없다. 초기화 하려면 tracing_on에 0을 다시 써줘야 한다. 아래와 같은 기록을 뽑아 냈다. 다 적을 수 없어, 중요한 부분만 추출했다. 생각이 맞는지 모르겠다.

5825  => sys_clone+0x18/0x3c
5826  => ret_fast_syscall+0x0/0x28
5827  => 0xbed826b0
5828             bash-1921  [002] .... 32848.024289: _do_fork+0x14/0x41c <-sys_clone+0x34/0x3c
5829             bash-1921  [002] .... 32848.024299: <stack trace>
5830  => _do_fork+0x18/0x41c
5831  => sys_clone+0x34/0x3c
5832  => ret_fast_syscall+0x0/0x28
5833  => 0xbed826b0
5834           <idle>-0     [000] dns. 32848.024300: sched_wakeup: comm=kworker/u8:3 pid=2958 prio=120 target_cpu=000
5835             bash-1921  [002] .... 32848.024301: copy_process.part.0+0x14/0x1ac4 <-_do_fork+0xc4/0x41c
5836           <idle>-0     [000] d... 32848.024307: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:3 next_pid=2958 next_prio=120
5837             bash-1921  [002] .... 32848.024310: <stack trace>
5838  => copy_process.part.0+0x18/0x1ac4
5839  => _do_fork+0xc4/0x41c
5840  => sys_clone+0x34/0x3c
5841  => ret_fast_syscall+0x0/0x28
5842  => 0xbed826b0
5843     kworker/u8:3-2958  [000] d... 32848.024324: sched_switch: prev_comm=kworker/u8:3 prev_pid=2958 prev_prio=120 prev_state=I ==> next_comm=swapper/0 next_pid=0 next_prio=120
5844             bash-1921  [002] .... 32848.024940: sched_process_fork: comm=bash pid=1921 child_comm=bash child_pid=3043
5845           <idle>-0     [003] d... 32848.024981: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=3043 next_prio=120
5846    raspbian_proc-3043  [003] d... 32848.025568: sched_switch: prev_comm=bash prev_pid=3043 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
5847           <idle>-0     [003] dnh. 32848.025595: sched_wakeup: comm=bash pid=3043 prio=120 target_cpu=003
5848           <idle>-0     [003] d... 32848.025608: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=3043 next_prio=120
5849             bash-1921  [002] d... 32848.025727: sched_switch: prev_comm=bash prev_pid=1921 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
5850           <idle>-0     [000] dnh. 32848.026664: sched_wakeup: comm=irq/36-mmc1 pid=82 prio=49 target_cpu=000
5851           <idle>-0     [000] d... 32848.026684: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=irq/36-mmc1 next_pid=82 next_prio=49
5852      irq/36-mmc1-82    [000] d.s. 32848.026720: sched_wakeup: comm=irq/36-mmc1 pid=82 prio=49 target_cpu=000
5853      irq/36-mmc1-82    [000] d.s. 32848.026763: sched_wakeup: comm=irq/36-mmc1 pid=82 prio=49 target_cpu=000
5854      irq/36-mmc1-82    [000] d.s. 32848.026806: sched_wakeup: comm=irq/36-mmc1 pid=82 prio=49 target_cpu=000
5855      irq/36-mmc1-82    [000] d... 32848.026823: sched_wakeup: comm=kworker/u8:3 pid=2958 prio=120 target_cpu=000
5856      irq/36-mmc1-82    [000] d... 32848.026840: sched_switch: prev_comm=irq/36-mmc1 prev_pid=82 prev_prio=49 prev_state=S ==> next_comm=kworker/u8:3 next_pid=2958 next_prio=120
5857     kworker/u8:3-2958  [000] d.s. 32848.026900: sched_wakeup: comm=kworker/u8:3 pid=2958 prio=120 target_cpu=000
5858     kworker/u8:3-2958  [000] d.s. 32848.026946: sched_wakeup: comm=kworker/u8:3 pid=2958 prio=120 target_cpu=000
...
8445     kworker/u8:0-2918  [001] d... 32866.110752: sched_switch: prev_comm=kworker/u8:0 prev_pid=2918 prev_prio=120 prev_state=I ==> next_comm=bash next_pid=3013 next_prio=120
8446             bash-3013  [001] d... 32866.110848: signal_generate: sig=9 errno=0 code=0 comm=raspbian_proc pid=3043 grp=1 res=0
8447           <idle>-0     [003] dnh. 32866.110856: sched_wakeup: comm=raspbian_proc pid=3043 prio=120 target_cpu=003
8448           <idle>-0     [003] d... 32866.110870: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=raspbian_proc next_pid=3043 next_prio=120
8449    raspbian_proc-3043  [003] d... 32866.110880: signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0
8450    raspbian_proc-3043  [003] .... 32866.110883: do_exit+0x14/0xbd4 <-do_group_exit+0x50/0xe8
8451    raspbian_proc-3043  [003] .... 32866.110909: <stack trace>
8452  => do_exit+0x18/0xbd4
8453  => do_group_exit+0x50/0xe8
8454  => get_signal+0x160/0x85c
8455  => do_signal+0x360/0x4a4
8456  => do_work_pending+0xd4/0xec
8457  => slow_work_pending+0xc/0x20
8458  => 0xb6e1969c
8459    raspbian_proc-3043  [003] .... 32866.111230: sched_process_exit: comm=raspbian_proc pid=3043 prio=120
8460    raspbian_proc-3043  [003] d... 32866.111296: signal_generate: sig=17 errno=0 code=2 comm=bash pid=1921 grp=1 res=0
8461           <idle>-0     [002] dnh. 32866.111311: sched_wakeup: comm=bash pid=1921 prio=120 target_cpu=002
8462             bash-3013  [001] dn.. 32866.111313: sched_wakeup: comm=kworker/u8:0 pid=2918 prio=120 target_cpu=001
8463           <idle>-0     [002] d... 32866.111327: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=1921 next_prio=120
8464    raspbian_proc-3043  [003] d... 32866.111330: sched_switch: prev_comm=raspbian_proc prev_pid=3043 prev_prio=120 prev_state=Z ==> next_comm=kworker/u8:0 next_pid=2918 next_prio=120
8465           <idle>-0     [000] dnh. 32866.111359: sched_wakeup: comm=sshd pid=3010 prio=120 target_cpu=000
8466             bash-3013  [001] d... 32866.111362: sched_switch: prev_comm=bash prev_pid=3013 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
8467     kworker/u8:0-2918  [003] d... 32866.111364: sched_switch: prev_comm=kworker/u8:0 prev_pid=2918 prev_prio=120 prev_state=I ==> next_comm=swapper/3 next_pid=0 next_prio=120
8468           <idle>-0     [000] d... 32866.111374: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sshd next_pid=3010 next_prio=120
8469           <idle>-0     [003] dnh. 32866.111531: sched_wakeup: comm=kworker/u8:0 pid=2918 prio=120 target_cpu=003
8470           <idle>-0     [003] d... 32866.111539: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:0 next_pid=2918 next_prio=120
8471             sshd-3010  [000] d... 32866.111572: sched_switch: prev_comm=sshd prev_pid=3010 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120

• bash pid는 1921이다.
• 5844행에서 child_pid 3043으로 자식 프로세스를 만들었다.
• 5846행에서 raspbian_proce를 볼 수 있다.
• 이 전에 5836행에서 다음 프로세스 id 2958을 가지고 거꾸로 sys_clone -> _do-fork -> copy_process를 실행했다.
• 5836 행에서 next pid 2958(5857행)로 넘어가야 하는데 fork 하느라 다음 행을 실행했다.

Linux process states

As in every Unix flavour, in Linux a process can be in a number of states. It’s easiest to observe it in tools like ps or top: it’s usually in the column named S. The documentation of ps describes the possible values:

PROCESS STATE CODES
   R  running or runnable (on run queue)
   D  uninterruptible sleep (usually IO)
   S  interruptible sleep (waiting for an event to complete)
   Z  defunct/zombie, terminated but not reaped by its parent
   T  stopped, either by a job control signal or because
      it is being traced
   [...]

A process starts its life in an R “running” state and finishes after its parent reaps it from the Z “zombie” state.

• 8449행에서 signo 9번을 받았다.
• 시그널 9번을 받아 시그널 17 발생 시켰다.
• slow_work_pending -> do_work_pending -> do_signal -> get_signal -> do_group_exit -> do_exit 순으로 실행한다.