책 “디버깅을 통해.. 리눅스 커널” 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 순으로 실행한다.