Why I added new features to crash tool?

Sometimes, some linux kernel in another platform are missing struct task_struct.sched_info.last_arrival element. For this matter, it is hard to know how the processes are executed at the time of order.

The "ps -e" command allows for listing the process at the time of order based on execution launching time.

crash> ps -e

ps: exec_start - task_struct.se.exec_start will be displayed at the time of order

   2123      1   4  e2d8ca40  IN   0.2   33324   7556  Aat_key_press

     36      2   4  eb5d9440  IN   0.0       0      0  [ksoftirqd/4]

   2118      1   4  e203c380  UN   0.2   33324   7556  func_keypress

    904      1   4  d0f04380  IN   0.1   57988   3148  thermal-engine

   1783      1   4  e59e9b00  UN   0.3   50144  13760  wireless_cmdmgr

   1250      1   4  e6eaaf40  UN   0.0   14724   1668  mtsd

    347      2   4  c4f9e540  UN   0.0       0      0  [mmc-cmdqd/0]

    713      2   4  ccdee540  IN   0.0       0      0  [kworker/u16:9]

   1701   1677   4  e58f86c0  UN   0.0    3944   1672  kernel_logger

    342      2   4  c4f98000  IN   0.0       0      0  [cfinteractive]

>   545      1   7  e91bc380  RU   0.4  127608  15532  Binder:482_2

   1793      1   5  e58fbcc0  IN   0.1   19544   2832  MSensorControl

>  1901      1   5  e4bf6540  RU   0.1   64628   5348  TouchLocation

    544      1   5  e91baf40  IN   0.4  127608  15532  DispSync

    616      1   5  e92d2880  IN   0.4  127608  15532  EventThread

   1878      1   5  e4ba3cc0  IN   0.1   82996   5608  SensorEventAckR


As sanity-test, it proves that output of "ps -e" command is the same as that of "ps -l" command.

crash> ps -l

[303201734830] [IN]  PID: 2123   TASK: e2d8ca40  CPU: 4   COMMAND: "Aat_key_press"

[303200690976] [IN]  PID: 36     TASK: eb5d9440  CPU: 4   COMMAND: "ksoftirqd/4"

[303163325351] [UN]  PID: 2118   TASK: e203c380  CPU: 4   COMMAND: "func_keypress"

[303160294830] [IN]  PID: 904    TASK: d0f04380  CPU: 4   COMMAND: "thermal-engine"

[303113625611] [UN]  PID: 1783   TASK: e59e9b00  CPU: 4   COMMAND: "wireless_cmdmgr"

[303113595247] [UN]  PID: 1250   TASK: e6eaaf40  CPU: 4   COMMAND: "mtsd"

[303113557955] [UN]  PID: 347    TASK: c4f9e540  CPU: 4   COMMAND: "mmc-cmdqd/0"

[303113325299] [IN]  PID: 713    TASK: ccdee540  CPU: 4   COMMAND: "kworker/u16:9"

[303112047955] [UN]  PID: 1701   TASK: e58f86c0  CPU: 4   COMMAND: "kernel_logger"

[303111794049] [IN]  PID: 342    TASK: c4f98000  CPU: 4   COMMAND: "cfinteractive"

[303090714882] [RU]  PID: 1901   TASK: e4bf6540  CPU: 5   COMMAND: "TouchLocation"

[303090673424] [IN]  PID: 1793   TASK: e58fbcc0  CPU: 5   COMMAND: "MSensorControl"

[303084315090] [IN]  PID: 544    TASK: e91baf40  CPU: 5   COMMAND: "DispSync"

[303084262278] [IN]  PID: 616    TASK: e92d2880  CPU: 5   COMMAND: "EventThread"

[303083165715] [IN]  PID: 1878   TASK: e4ba3cc0  CPU: 5   COMMAND: "SensorEventAckR"


As for this project, "ps -l" does not work as below.

crash> ps -l

ps: last-run timestamps do not exist in this kernel

Usage:

  ps [-k|-u|-G] [-s] [-p|-c|-t|-[l|m][-C cpu]|-a|-g|-r|-S]

     [pid | task | command] ...

Enter "help ps" for details.


crash> ps -e

crash> ps -e

ps: exec_start - task_struct.se.exec_start will be displayed at the time of order

> 31114      2   3  c2385280  RU   0.0       0      0  [kworker/u8:0]

> 21723      2   0  eb33bc80  RU   0.0       0      0  [kworker/u8:3]

  20759      1   1  d243b700  IN   0.0   42688   1536  atd

> 29684      1   2  c1c31080  RU   0.0       0      0  thread-pool-0

  31741      2   0  c2888580  IN   0.0       0      0  [kworker/0:0]

  32030      2   0  cd6c5d80  IN   0.0       0      0  [kworker/u8:2]

    757      1   1  dccfb700  IN   0.0   50520   1248  thermal-engine

    701      1   1  e4624d00  IN   0.0   10848    904  gbmd

  30403      2   3  e6decd00  IN   0.0       0      0  [kworker/3:2]

     10      2   0  ee45b180  IN   0.0       0      0  [rcuop/0]

      7      2   0  ee45a100  IN   0.0       0      0  [rcu_preempt]

    700      1   0  e4623180  IN   0.0   10848    904  gbmd

    699      1   0  e4623c80  IN   0.0   10848    904  gbmd

  32291      1   0  e6dee300  IN   0.4   70608  14952  cameraserver

    446      1   0  e9de3700  IN   0.0    4868    952  servicemanager

  23230      2   1  e6e41080  IN   0.0       0      0  [kworker/1:2]

    293      2   0  c3e47380  UN   0.0       0      0  [mmc-cmdqd/0]

    289      2   0  c3e45d80  IN   0.0       0      0  [irq/148-7824900]


Patches to add new feature listing the process at the time of order based upon "((struct task_struct).se.exec_start"

diff --git a/defs.h b/defs.h

index a1746cc..c5d26ea 100644

--- a/defs.h

+++ b/defs.h

@@ -952,6 +952,9 @@ struct vaddr_range {


 #define MAX_MACHDEP_ARGS 5  /* for --machdep/-m machine-specific args */


 struct machdep_table {

  ulong flags;

  ulong kvbase;

@@ -1719,6 +1722,11 @@ struct offset_table {                    /* stash of commonly-used offsets */

  long vcpu_struct_rq;

  long task_struct_sched_info;

  long sched_info_last_arrival;

+ long task_struct_sched_entity;

+ long se_exec_start;

+

  long page_objects;

  long kmem_cache_oo;

  long char_device_struct_cdev;

@@ -4426,9 +4434,18 @@ extern long _ZOMBIE_;

 #define PS_BY_REGEX    (0x8000)

 #define PS_NO_HEADER  (0x10000)

 #define PS_MSECS      (0x20000)

+#if 1

+#define PS_EXEC_START    (0x40000)

+#define PS_SUMMARY    (0x80000)

+#else

 #define PS_SUMMARY    (0x40000)

+#endif


+#if 1

+#define PS_EXCLUSIVE (PS_TGID_LIST|PS_ARGV_ENVP|PS_TIMES|PS_CHILD_LIST|PS_PPID_LIST|PS_LAST_RUN|PS_EXEC_START|PS_RLIMIT|PS_MSECS|PS_SUMMARY)

+#else

 #define PS_EXCLUSIVE (PS_TGID_LIST|PS_ARGV_ENVP|PS_TIMES|PS_CHILD_LIST|PS_PPID_LIST|PS_LAST_RUN|PS_RLIMIT|PS_MSECS|PS_SUMMARY)

+#endif


 #define MAX_PS_ARGS    (100)   /* maximum command-line specific requests */


@@ -5102,6 +5119,9 @@ ulong task_state(ulong);

 ulong task_mm(ulong, int);

 ulong task_tgid(ulong);

 ulonglong task_last_run(ulong);

+#if 1

+ulonglong task_exec_start(ulong);

+#endif

 ulong vaddr_in_task_struct(ulong);

 int comm_exists(char *);

 struct task_context *task_to_context(ulong);

diff --git a/filesys.c b/filesys.c

index 9b59998..68452f5 100644

--- a/filesys.c

+++ b/filesys.c

@@ -3671,7 +3671,7 @@ get_live_memory_source(void)

   sprintf(modname1, "%s.o", pc->memory_module);

                 sprintf(modname2, "%s.ko", pc->memory_module);

          while (fgets(buf, BUFSIZE, pipe)) {

-   if (strstr(buf, "invalid option") &&

+   if (strstr(buf, "invalid option: filesys.c 3674") &&

        (uname(&utsname) == 0)) {

     sprintf(buf,

         "/lib/modules/%s/kernel/drivers/char/%s",

diff --git a/main.c b/main.c

index 821bb4e..3985448 100644

--- a/main.c

+++ b/main.c

@@ -408,7 +408,7 @@ main(int argc, char **argv)

    break;


   default:

-   error(INFO, "invalid option: %s\n",

+   error(INFO, "main.c @411, invalid option: %s\n",

     argv[optind-1]);

    program_usage(SHORT_FORM);

   }

diff --git a/memory.c b/memory.c

index 216038d..0b97477 100644

--- a/memory.c

+++ b/memory.c

@@ -1756,9 +1756,11 @@ cmd_wr(void)

  long size;

  struct syment *sp;


+// Guillermo would like to update memory content. 11/22/2016

+#if 0

  if (DUMPFILE())

   error(FATAL, "not allowed on dumpfiles\n");

-

+#endif

  memtype = 0;

  buf = NULL;

  addr = 0;

diff --git a/symbols.c b/symbols.c

index a8d3563..6d80834 100644

--- a/symbols.c

+++ b/symbols.c

@@ -8497,6 +8497,11 @@ dump_offset_table(char *spec, ulong makestruct)

                 OFFSET(sched_rt_entity_run_list));

  fprintf(fp, "       sched_info_last_arrival: %ld\n",

                 OFFSET(sched_info_last_arrival));

+ error(INFO, "dump_offset_table: Initializing task_struct.se.exec_start\n");

+ fprintf(fp, "       se_exec_start: %ld\n",

+                OFFSET(se_exec_start));

         fprintf(fp, "       task_struct_thread_info: %ld\n",

                 OFFSET(task_struct_thread_info));

         fprintf(fp, "           task_struct_nsproxy: %ld\n",

@@ -12518,7 +12523,7 @@ OFFSET_verify(long offset, char *func, char *file, int line, char *item)

  if (offset < 0) {

   void *retaddr[NUMBER_STACKFRAMES] = { 0 };

   SAVE_RETURN_ADDRESS(retaddr);

-  sprintf(errmsg, "invalid structure member offset: %s",

+  sprintf(errmsg, "Guillermo: invalid structure member offset: %s",

    item);

   datatype_error(retaddr, errmsg, func, file, line);

  }

diff --git a/task.c b/task.c

index b857cf6..ee3ac45 100644

--- a/task.c

+++ b/task.c

@@ -268,6 +268,23 @@ task_init(void)

          strcpy(buf, "alias last ps -l");

          alias_init(buf);

  }

+

+ MEMBER_OFFSET_INIT(task_struct_sched_entity, "task_struct", "se");

+ error(INFO, "Guillermo: Initializing task_struct.se.exec_start\n");

+ if (VALID_MEMBER(task_struct_sched_entity)) {

+  STRUCT_SIZE_INIT(sched_entity, "sched_entity");

+  MEMBER_OFFSET_INIT(se_exec_start, "sched_entity", "exec_start");

+  char buf[BUFSIZE];

+         strcpy(buf, "alias last ps -e");

+

+  alias_init(buf);

+  if (VALID_MEMBER(se_exec_start)) {

+   error(INFO, "Guillermo:VALID task_struct.se.exec_start\n");

+  }

+ }

+

  MEMBER_OFFSET_INIT(pid_link_pid, "pid_link", "pid");

  MEMBER_OFFSET_INIT(pid_hash_chain, "pid", "hash_chain");


@@ -2471,6 +2488,35 @@ sort_by_pid(const void *arg1, const void *arg2)

                         t1->pid == t2->pid ? 0 : 1);

 }


+static int

+sort_by_exec_start(const void *arg1, const void *arg2)

+{

+ ulong task_last_run_stamp(ulong);

+ struct task_context *t1, *t2;

+ ulonglong lr1, lr2;

+

+ t1 = (struct task_context *)arg1;

+ t2 = (struct task_context *)arg2;

+

+ lr1 = task_exec_start(t1->task);

+ lr2 = task_exec_start(t2->task);

+

+        return (lr2 < lr1 ? -1 :

+  lr2 == lr1 ? 0 : 1);

+}

+

+static void

+sort_context_array_by_exec_start(void)

+{

+        ulong curtask;

+

+ curtask = CURRENT_TASK();

+ qsort((void *)tt->context_array, (size_t)tt->running_tasks,

+  sizeof(struct task_context), sort_by_exec_start);

+ set_context(curtask, NO_PID);

+}


 static int

 sort_by_last_run(const void *arg1, const void *arg2)

@@ -2897,8 +2943,11 @@ cmd_ps(void)

  BZERO(&psinfo, sizeof(struct psinfo));

  cpuspec = NULL;

  flag = 0;

-

+#if 1

+ while ((c = getopt(argcnt, args, "SgstcpkuGlemarC:")) != EOF) {

+#else

         while ((c = getopt(argcnt, args, "SgstcpkuGlmarC:")) != EOF) {

+#endif

                 switch(c)

   {

   case 'k':

@@ -2978,7 +3027,18 @@ cmd_ps(void)

    check_ps_exclusive(flag, PS_LAST_RUN);

    flag |= PS_LAST_RUN;

    break;

-

+  case 'e':

+   if (INVALID_MEMBER(se_exec_start)) {

+    error(INFO,

+                            "exec_start timestamps do not exist in this kernel\n");

+    argerrs++;

+    break;

+   }

+   check_ps_exclusive(flag, PS_EXEC_START);

+   flag |= PS_EXEC_START;

+   break;

   case 's':

    flag |= PS_KSTACKP;

    break;

@@ -3010,6 +3070,12 @@ cmd_ps(void)


  if (flag & (PS_LAST_RUN|PS_MSECS))

   sort_context_array_by_last_run();

+ else if (flag & PS_EXEC_START) {

+  error(INFO, "exec_start - task_struct.se.exec_start will be displayed at the time of order\n");

+  sort_context_array_by_exec_start();

+ }

  else if (psinfo.cpus) {

   error(INFO, "-C option is only applicable with -l and -m\n");

   goto bailout;

@@ -5299,6 +5365,26 @@ task_tgid(ulong task)

         return (ulong)tgid;

 }


+ulonglong

+task_exec_start(ulong task)

+{

+        ulong exec_start;

+ ulonglong timestamp;

+

+ timestamp = 0;

+        fill_task_struct(task);

+

+ if (VALID_MEMBER(se_exec_start)) {

+  timestamp = tt->last_task_read ?  ULONGLONG(tt->task_struct +

+   OFFSET(task_struct_sched_entity) +

+   OFFSET(se_exec_start)) : 0;

+ }

+

+        return timestamp;

+}

+

 ulonglong

 task_last_run(ulong task)

 {



저작자표시

'리눅스 커널의 구조와 원리 > 3. 커널 디버깅과 코드 학습' 카테고리의 다른 글

[LinuxKernel] Trace32(T32) How to use offsetof/container_of macro?  (0) 2019.03.09

기본 유저 레벨 프로세스 실행 실습 및 ftrace 로그 분석

라즈베리파이에서 X-terminal 프로그램을 실행해서 셸을 엽시다. 

root@raspberrypi:/boot# ps -ely | grep bash
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S  1000   541   443  0  80   0  4024  1645 poll_s tty1     00:00:00 bash
S  1000   880   878  0  80   0  4008  1628 wait   pts/0    00:00:00 bash
S     0   977   972  0  80   0  3284  1416 wait   pts/0    00:00:00 bash
S  1000   993   989  0  80   0  3960  1628 poll_s pts/1    00:00:00 bash

grep bash 명령어로 현재 실행 중인 프로세스 중에 bash 프로세스를 출력합니다. 출력 결과 4개 bash 프로세스 목록을 볼 수 있습니다.

이 상태에서 X-terminal 셸을 하나 더 실행하고 다음 명령어를 입력해서 bash 프로세스 목록을 확인합시다.
root@raspberrypi:/boot# ps -ely | grep bash
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S  1000   541   443  0  80   0  4024  1645 poll_s tty1     00:00:00 bash
S  1000   880   878  0  80   0  4008  1628 wait   pts/0    00:00:00 bash
S     0   977   972  0  80   0  3284  1416 wait   pts/0    00:00:00 bash
S  1000   993   989  0  80   0  3960  1628 poll_s pts/1    00:00:00 bash
S  1000  1027   878  3  80   0  4036  1628 poll_s pts/2    00:00:00 bash

이전에 출력한 결과와 비교해봅시다. 맨 마지막 줄 로그를 보면 pid가 1027인 bash 프로세스가 보입니다. 셸을 하나 더 열고 “ps –ely” 명령어를 입력하니 bash(pid:1027)과 같이 새로 생성된 프로세스를 볼 수 있습니다. 이렇게 새로운 프로그램을 실행하면 이에 해당하는 프로세스가 생성됩니다.

라즈베리파이 X-Terminal 셸 화면을 마우스로 더블 클릭하는 순간 라즈베리파이 배경 화면을 처리하는 프로세스가 이벤트를 받아서 bash라는 프로세스를 생성합니다. 이 때 리눅스 저수준 함수인 fork()를 호출합니다. 이렇게 유저 레벨 프로세스는 셸이나 다른 프로세스를 통해서 실행을 시작합니다. 유저 레벨 프로세스는 혼자서 실행할 수 없습니다.

이번에는 라즈베리파이에서 소스 에디터로 많이 쓰는 Geany란 프로그램을 열겠습니다.
root@raspberrypi:/boot# ps -ely | grep geany
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S  1000   989   671  1  80   0 28276 25827 poll_s ?        00:00:06 geany

Geany 프로그램을 하나 더 열고 다음 명령어를 입력합시다.
root@raspberrypi:/boot# ps -ely | grep geany
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S  1000   989   671  1  80   0 28276 25827 poll_s ?        00:00:06 geany
S  1000  1297   671 38  80   0 25204 13533 poll_s ?        00:00:01 geany

PID가 1297인 geany 프로세스가 생성됐습니다.

프로세스를 어렵게 생각할 필요가 없습니다. 셸이나 geany이란 프로그램을 실행하면 메모리에서 실행하는 것이 프로세스입니다. 유저 레벨에서 실행하는 프로세스는 이렇게 유저 동작으로 생성됩니다.

이번에 리눅스 시스템 프로그래밍으로 프로세스를 생성해 봅시다. 소스 코드는 다음과 같으니 같이 입력해 봅시다.
1 #include <stdio.h>
2 #include <unistd.h>
3
4 #define PROC_TIMES 500
5 #define SLEEP_DURATION 3  // second unit
6
7 int main() 
8 {
9 int proc_times = 0;
10
11 for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
12 printf("raspbian tracing \n");
13 sleep(SLEEP_DURATION);
14 }
15
16 return 0;
17 }

위와 같은 프로그램을 리눅스 시스템 프로그램이라고 합니다. 리눅스 시스템을 관리하는 sleep()이나 fork() 함수를 직접 호출하기 때문에 응용 프로그램 입장에서 저수준 프로그래밍이라고도 합니다. 위 함수를 리눅스 시스템 저수준 함수(API)라고 부르겠습니다.

위 코드는 다음 코드 이외에 다른 동작을 하지 않습니다.
11 for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
12 printf("raspbian tracing \n");
13 sleep(SLEEP_DURATION);
14 }

소스 코드를 잠깐 봅시다.

12번째 줄 코드와 같이 “raspbian tracing”이란 메시지를 셸로 출력하고 13번째 줄 코드와 같이 3초 동안 휴면에 들어갈 뿐입니다.

위 코드를 입력한 다음 raspbian_test.c 란 이름으로 저장합시다. 컴파일을 쉽게 하기 위해 다음과 같이 코드를 작성하고 파일 이름을 Makefile으로 저장합시다.
raspbian_proc: raspbian_test.c
gcc -o raspbian_proc raspbian_test.c

“make” 명령어로 위와 같은 메이크 파일을 실행하면 raspbian_proc이란 실행 파일이 생성됩니다.

메이크 파일은 여러 모듈을 일일이 컴파일 명령어를 입력하기 어려우니 컴파일 설정 속도를 빠르게 하기 위해 고안된 겁니다. 실전 프로젝트에서 메이크 파일은 자주 쓰니 잘 알아둡시다.

make란 명령어를 입력해서 raspbian_test.c 파일을 컴파일하면 raspbian_proc이란 프로그램을 생성할 수 있습니다.

raspbian_proc 이란 프로세스가 어떻게 생성되고 실행되는지 파악하려면 다음과 같이 ftrace 로그를 설정할 필요가 있습니다. 코드를 봅시다.
1  #!/bin/sh
2 
3  echo 0 > /sys/kernel/debug/tracing/tracing_on
4  sleep 1
5  echo "tracing_off"
6
7 echo 0 > /sys/kernel/debug/tracing/events/enable
8 sleep 1
9 echo "events disabled"
10
11 echo  secondary_start_kernel  > /sys/kernel/debug/tracing/set_ftrace_filter
12 sleep 1
13 echo "set_ftrace_filter init"
14 
15 echo function > /sys/kernel/debug/tracing/current_tracer
16 sleep 1
17 echo "function tracer enabled"
18
19 echo SyS_clone do_exit > /sys/kernel/debug/tracing/set_ftrace_filter
20 echo _do_fork copy_process* >> /sys/kernel/debug/tracing/set_ftrace_filter
21
22 sleep 1
23 echo "set_ftrace_filter enabled"
24
25 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
26 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
27 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable
28 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable
29
30 echo 1 > /sys/kernel/debug/tracing/events/signal/enable
31
32 sleep 1
33 echo "event enabled"
34
35 echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
36 echo 1 > /sys/kernel/debug/tracing/options/sym-offset
37 echo "function stack trace enabled"
38
39 echo 1 > /sys/kernel/debug/tracing/tracing_on
40 echo "tracing_on"
조금 더 알아보기
ftrace 에서 시스템 콜 핸들러 함수 심볼(이름)을 Alias 심볼로 씁니다.

예를 들어 sys_write() 함수에 대한 alias 심볼은 SyS_write와 같습니다.
다음 전처리 코드는 fs/read_write.c 파일에 위치한 write 시스템 콜 핸들러 함수 선언부입니다.
[out/fs/.tmp_read_write.i]
1 long sys_write(unsigned int fd, const char * buf, size_t count) __attribute__((alias("SyS_write")));
2
3 [https://elixir.bootlin.com/linux/v4.14.70/source/fs/read_write.c]
4 SYSCALL_DEFINE3(write, unsigned int, fd, const char __user *, buf,
5 size_t, count)
6 {
7 struct fd f = fdget_pos(fd);
8 ssize_t ret = -EBADF;

1번째 줄 코드를 보면 함수 인자 오른쪽에 다음과 같은 코드를 볼 수 있습니다.
__attribute__((alias("SyS_write")));

GCC 컴파일러가 함수 컴파일시 alias 심볼을 적용한 것인데 sys_write() 함수에 대한 alias 심볼이 SyS_write입니다.

ftrace 로그에서 SyS_xxx 로 어떤 함수를 표현하면 실제 함수 이름은 sys_xxx() 이라고 생각해도 좋습니다.

따라서 ftrace 로그 설정 시 set_ftrace_filter로 SyS_clone 함수로 지정한 겁니다.
19 echo SyS_clone do_exit > /sys/kernel/debug/tracing/set_ftrace_filter

이렇게 지정하면 ftrace는 실제 리눅스 커널 코드에서 sys_clone 함수를 추적(트레이싱)합니다.

위와 같이 코드를 작성한 후 clone_process_debug.sh 와 같은 이름을 저장한 후 다음과 같이 이 셸 스크립트를 실행합시다.
./clone_process_debug.sh

위 셸 스크립트를 실행하면 5~6초 내 ftrace 로그 설정이 끝납니다. 이후 raspbian_test.c 파일을 컴파일하면 생성되는 raspbian_proc이란 프로그램을 다음 명령어로 실행합시다. 
root@raspberrypi:/home/pi# ./raspbian_proc 
raspbian tracing 
raspbian tracing 
raspbian tracing 
raspbian tracing 
raspbian tracing 
raspbian tracing

raspbian_proc 이란 프로그램을 실행하니 3초 간격으로 “raspbian tracing”이란 메시지를 출력합니다. 소스 코드에서 구현한 대로 실행합니다.

raspbian_proc 프로그램을 실행했으니 이에 해당하는 프로세스가 생성됐을 것이라 예상할 수 있습니다. 이번에는 “ps -ely” 명령어를 입력해서 프로세스 목록을 확인합시다.
root@raspberrypi:/home/pi# ps -ely
1 S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
2 S     0     1     0  0  80   0  5956  6991 SyS_ep ?        00:00:02 systemd
3 S     0     2     0  0  80   0     0     0 kthrea ?        00:00:00 kthreadd
...
4
5 S     0   895   890  0  80   0  3420  1448 wait   pts/0    00:00:00 bash
6 S  1000   991   685  0  80   0  7500  7842 poll_s ?        00:00:00 ibus-engine-han
...
7  S     0  1078  1073  0  80   0  3244  1416 wait   pts/2    00:00:00 bash
8  I     0  1079     2  0  80   0     0     0 worker ?        00:00:00 kworker/3:2
9  I     0  2302     2  0  80   0     0     0 worker ?        00:00:00 kworker/0:1
10 S     0 17082   895  0  80   0   344   453 hrtime pts/0    00:00:00 raspbian_proc
11 I     0 17084     2  0  80   0     0     0 worker ?        00:00:00 kworker/u8:1
12 I     0 17085     2  0  80   0     0     0 worker ?        00:00:00 kworker/1:0
13 R     0 17086  1078  0  80   0  1156  1918 -      pts/2    00:00:00 ps

프로세스 목록 10번째 항목을 보면 pid가 17082인 raspbian_proc 프로세스가 보입니다. 리눅스 시스템에서 raspbian_proc 프로세스가 READY 상태이란 의미입니다. 
1 S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
5 S     0   895   890  0  80   0  3420  1448 wait   pts/0    00:00:00 bash
...
10 S     0 17082   895  0  80   0   344   453 hrtime pts/0    00:00:00 raspbian_proc

1번째 줄 로그에서 PPID가 보입니다. 이 정보는 부모 프로세스의 pid를 의미합니다. raspbian_proc 프로세스의 부모 프로세스는 pid가 895입니다. pid가 895인 프로세스를 확인하니 프로세스 목록 5번째 항목과 같이 bash 프로세스입니다. raspbian_proc 프로세스의 부모 프로세스는 bash임을 알 수 있습니다.

raspbian_proc 프로세스의 부모 프로세스는 왜 bash(pid:895) 일까요? raspbian_proc 프로세스를 실행할 때 X-Terminal bash 셸에서 다음 명령어로 실행했기 때문입니다.
root@raspberrypi:/home/pi# ./raspbian_proc 

이렇게 유저 레벨 프로세스는 셸이나 다른 프로세스를 통해서 실행을 시작합니다. 만약 라즈베리파이 바탕 화면에 있는 아이콘을 클릭해서 프로그램을 시작해서 유저 레벨 프로세스를 실행했다고 가정합시다. 이 경우 바탕화면을 제어하는 프로세스가 부모 프로세스가 됩니다.

raspbian_proc 프로세스를 이렇게 15초 동안 실행시킨 다음에 다른 x-terminal 셸을 실행을 실행해서 다음과 같이 raspbian_proc 프로세스를 강제 종료해봅시다.
root@raspberrypi:/home/pi# kill -9  17082

kill 명령어로 pid를 지정하면 강제로 지정한 프로세스를 종료합니다. -9는 강제로 프로세스를 종료시키는 옵션입니다.

다음 명령어를 입력해서 kill이란 명령어가 어떤 의미인지 확인합시다.
root@raspberrypi:/home/pi# info kill

24.1 ‘kill’: Send a signal to processes
=======================================

The ‘kill’ command sends a signal to processes, causing them to
terminate or otherwise act upon receiving the signal in some way.
Alternatively, it lists information about signals.  Synopses:

     kill [-s SIGNAL | --signal SIGNAL | -SIGNAL] PID...
     kill [-l | --list | -t | --table] [SIGNAL]...

   Due to shell aliases and built-in ‘kill’ functions, using an
unadorned ‘kill’ interactively or in a script may get you different
functionality than that described here.  Invoke it via ‘env’ (i.e., ‘env
kill ...’) to avoid interference from the shell.

매뉴얼 내용과 같이 kill 명령어는 프로세스를 종료하는 역할을 수행합니다.

이번에는 다음과 같은 셸 스크립트를 실행해서 ftrace 로그를 추출합시다.
#!/bin/sh

echo 0 > /sys/kernel/debug/tracing/tracing_on
echo "ftrace off"

sleep 3

cp /sys/kernel/debug/tracing/trace . 
mv trace ftrace_log.c

위 코드를 get_ftrace.sh 이름으로 저장해놓고 ftrace 로그를 받을 때 다음 명령어를 실행합니다.
root@raspberrypi:/home/pi#./get_ftrace.sh

그러면 같은 폴더에 ftrace.c이란 파일이 생성됐음을 확인할 수 있습니다.

이제까지 프로세스 생성과 종료 과정을 저장한 ftrace 로그를 추출하기 위해 진행한 과정을 정리하면 다음과 같습니다.
1. 다음 명령어로 프로세스 실행
root@raspberrypi:/home/pi# ./raspbian_proc 

2. ftrace 로그 설정 및 시작
3. ps 명령어로 프로세스 동작 확인

4. raspbian_proc 프로세스 종료
root@raspberrypi:/home/pi# kill -9  17082

5. ftrace 로그 추출

커널 공간에서 raspbian_proc 이란 프로세스가 어떤 코드 흐름으로 생성하고 종료했는지 ftrace 로그로 알아봅시다.

분석할 전체 ftrace 로그는 다음과 같습니다.
1 bash-895 [003] .... 909.253260: SyS_clone+0x14/0x38 <-ret_fast_syscall+0x0/0x28
2 bash-895 [003] .... 909.253295: <stack trace>
3 bash-895 [003] .... 909.253298: _do_fork+0x14/0x3ec <-SyS_clone+0x30/0x38
4 bash-895 [003] .... 909.253310: <stack trace>
5 lxpanel-730 [002] d.h.   909.253310: sched_wakeup: comm=ibus-x11 pid=717 prio=120 target_cpu=002
6 bash-895 [003] .... 909.253312: copy_process.part.5+0x14/0x17d8 <-_do_fork+0xb0/0x3ec
7 bash-895 [003] .... 909.253324: <stack trace>
8 => ret_fast_syscall+0x0/0x28
...
9 bash-895 [003] .... 909.253776: sched_process_fork: comm=bash pid=895 child_comm=bash child_pid=17082
10 <idle>-0 [002] d... 909.253809: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=17082 next_prio=120
11 bash-895 [003] d... 909.254159: sched_switch: prev_comm=bash prev_pid=895 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:0 next_pid=1047 next_prio=120
12 <idle>-0 [000] dnh. 909.254206: sched_wakeup: comm=lxterminal pid=876 prio=120 target_cpu=000
13 <idle>-0 [000] d... 909.254215: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=lxterminal next_pid=876 next_prio=120
14 kworker/u8:0-1047 [003] d... 909.254221: sched_switch: prev_comm=kworker/u8:0 prev_pid=1047 prev_prio=120 prev_state=t ==> next_comm=swapper/3 next_pid=0 next_prio=120
15 raspbian_proc-17082 [002] d.s. 909.254409: sched_wakeup: comm=rcu_sched pid=8 prio=120 target_cpu=002
16 raspbian_proc-17082 [002] d... 909.257817: sched_switch: prev_comm=raspbian_proc prev_pid=17082 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
...
17 <idle>-0 [002] dnh. 912.257874: sched_wakeup: comm=raspbian_proc pid=17082 prio=120 target_cpu=002
18 raspbian_proc-17082 [002] d... 912.257957: sched_switch: prev_comm=raspbian_proc prev_pid=17082 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
...
19 <idle>-0  [002] dnh. 915.258028: sched_wakeup: comm=raspbian_proc pid=17082 prio=120 target_cpu=002          
20 <idle>-0 [002] d... 915.258044: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=raspbian_proc next_pid=17082 next_prio=120          
21 <idle>-0     [003] dnh.   915.258098: sched_wakeup: comm=kworker/u8:1 pid=17084 prio=120 target_cpu=003   
22 raspbian_proc-17082 [002] d...   915.258110: sched_switch: prev_comm=raspbian_proc prev_pid=17082 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
...
23 raspbian_proc-17082 [002] d...   933.741224: signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0
24 kworker/u8:2-137 [001] d...   933.741230: sched_switch: prev_comm=kworker/u8:2 prev_pid=137 prev_prio=120 prev_state=t ==> next_comm=swapper/1 next_pid=0 next_prio=120
25 raspbian_proc-17082 [002] .... 933.741230: do_exit+0x14/0xc18 <-do_group_exit+0x50/0xe4
26 raspbian_proc-17082 [002] .... 933.741270: <stack trace>
27 => do_signal+0x300/0x3d4
28 => do_work_pending+0xb4/0xcc
29 => slow_work_pending+0xc/0x20
30 lxpanel-730 [000] d... 933.741295: sched_switch: prev_comm=lxpanel prev_pid=730 prev_prio=120 prev_state=S ==> next_comm=Xorg next_pid=454 next_prio=120
31 Xorg-454 [000] dn.. 933.741333: sched_wakeup: comm=openbox pid=723 prio=120 target_cpu=000
32 Xorg-454 [000] d... 933.741346: sched_switch: prev_comm=Xorg prev_pid=454 prev_prio=120 prev_state=R ==> next_comm=openbox next_pid=723 next_prio=120
33 raspbian_proc-17082 [002] .... 933.741609: sched_process_exit: comm=raspbian_proc pid=17082 prio=120
34 ibus-x11-717 [001] d... 933.741639: sched_switch: prev_comm=ibus-x11 prev_pid=717 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
35 openbox-723 [000] d... 933.741673: sched_switch: prev_comm=openbox prev_pid=723 prev_prio=120 prev_state=S ==> next_comm=Xorg next_pid=454 next_prio=120
36 raspbian_proc-17082 [002] d... 933.741693: signal_generate: sig=17 errno=0 code=2 comm=bash pid=895 grp=1 res=0

먼저 유저 공간에서 프로세스가 생성하면 다음 그림과 같은 흐름으로 _do_fork() 함수가 실행합니다.
                    
리눅스에서 실행 공간은 메모리 접근과 실행 권한 기준으로 유저 공간과 커널 공간으로 구분할 수 있습니다. 유저 공간은 유저 모드, 커널 공간은 커널 모드에서 각각 에서 실행하는 메모리 공간입니다. 유저 공간과 유저 모드는 거의 비슷한 의미로 씁니다.

리눅스 시스템 저수준 함수로 fork() 함수를 호출하면 유저 공간에서 코드 공간으로 실행 흐름 공간을 이동하는 시스템 콜이 발생하고 커널 모드로 실행 흐름이 변경됩니다. 이후 커널 모드에서 시스템 콜 번호에 해당하는 핸들러 함수가 호출됩니다. 이 함수가 sys_clone()입니다.

위 그림이 실제 ftrace 로그로 어떻게 출력하는지 확인합시다.

먼저 1~8번째 줄 로그를 분석하겠습니다.
1 bash-895 [003] .... 909.253260: SyS_clone+0x14/0x38 <-ret_fast_syscall+0x0/0x28
2 bash-895 [003] .... 909.253295: <stack trace>
3 bash-895 [003] .... 909.253298: _do_fork+0x14/0x3ec <-SyS_clone+0x30/0x38
4 bash-895 [003] .... 909.253310: <stack trace>
5 lxpanel-730 [002] d.h.   909.253310: sched_wakeup: comm=ibus-x11 pid=717 prio=120 target_cpu=002
6 bash-895 [003] .... 909.253312: copy_process.part.5+0x14/0x17d8 <-_do_fork+0xb0/0x3ec
7 bash-895 [003] .... 909.253324: <stack trace>
8 => ret_fast_syscall+0x0/0x28
조금 더 알아보기: ftrace 로그 한줄 한줄을 실행하는 주체는 프로세스입니다. 모든 ftrace 가장 왼쪽에서 프로세스 이름과 pid를 볼 수 있습니다.

위 ftrace 로그에서는 가장 왼쪽에 “bash-895” 메시지가 보이는데 이 정보를 어떻게 해석해야 할까요? 이 정보는 pid가 895인 bash 프로세스를 의미합니다. 5번째 줄 로그 가장 왼쪽에서도 “lxpanel-730”이란 메시지를 볼 수 있습니다. 역시 pid가 730인 lxpanel이란 프로세스를 의미합니다.

로그들이 어지럽게 섞여 있는데 위 로그는 “bash-895”이란 프로세스가 다음 함수 흐름(콜스택)으로 실행 중인 상태입니다.
1 => copy_process.part.5+0x14/0x17d8
2 => _do_fork+0x14/0x3ec
3 => SyS_clone+0x14/0x38
4 => ret_fast_syscall+0x0/0x28

함수 호출 방향은 4에서 1번 로그 방향입니다. 시스템 콜 함수인 SyS_clone() 함수에서 _do_fork() 함수를 호출합니다.

다음 9번째 줄 로그를 봅시다.
9 bash-895 [003] .... 909.253776: sched_process_fork: comm=bash pid=895 child_comm=bash child_pid=17082

sched_process_fork이란 ftrace 이벤트 메시지와 함께 디버깅 정보를 출력합니다. pid가 895인 bash 프로세스가 pid가 17082인 자식 프로세스를 생성한다는 의미입니다. 부모 프로세스가 자식 프로세스를 생성할 때는 프로세스 이름은 그대로 가져갑니다. 이후 프로세스 이름을 자식 프로세스 이름으로 변경합니다.

task_rename 이란 ftrace 이벤트를 키면 다음과 같은 정보를 볼 수 있습니다.
raspbian_proc-17083  [003] .... 909.253836 task_rename: pid=17082 oldcomm=bash newcomm=raspbian_proc oom_score_adj=0

15~23번째 줄 로그는 raspbian_proc(pid:17083) 프로세스가 실행하는 정보입니다. 
15 raspbian_proc-17082 [002] d.s. 909.254409: sched_wakeup: comm=rcu_sched pid=8 prio=120 target_cpu=002
16 raspbian_proc-17082 [002] d... 909.257817: sched_switch: prev_comm=raspbian_proc prev_pid=17082 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
...
17 <idle>-0 [002] dnh. 912.257874: sched_wakeup: comm=raspbian_proc pid=17082 prio=120 target_cpu=002
18 raspbian_proc-17082 [002] d... 912.257957: sched_switch: prev_comm=raspbian_proc prev_pid=17082 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
...
19 <idle>-0 [002] dnh. 918.258177: sched_wakeup: comm=raspbian_proc pid=17082 prio=120 target_cpu=002
20 <idle>-0 [002] d... 918.258193: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=raspbian_proc next_pid=17082 next_prio=120
21 raspbian_proc-17082 [002] d... 918.258250: sched_wakeup: comm=kworker/u8:1 pid=17084 prio=120 target_cpu=002
22 raspbian_proc-17082 [002] d... 918.258277: sched_switch: prev_comm=raspbian_proc prev_pid=17082 prev_prio=120 prev_state=S ==> next_comm=kworker/u8:1 next_pid=17084 next_prio=120

15번째 줄 로그를 보면 909.254409초에 raspbian_proc(pid: 17082) 프로세스가 "rcu_sched" 프로세스를 깨웁니다. 이후 909.257817초에 16번째 줄 로그와 같이 "swapper/2" 프로세스로 스케줄링됩니다.

17번째 로그를 보면, 약 3초 후인 912.257874 초에 idle-0이란 프로세스가 raspbian_proc(pid: 17082) 프로세스를 깨우고, 18번째 로그와 같이 912.257957 초에  "swapper/2" 프로세스로 스케줄링됩니다.

sched_wakeup 이란 ftrace 이벤트는 프로세스를 깨우는 동작을 표현합니다. 정확히 설명을 드리면 스케줄러에게 해당 프로세스 실행 요청을 하는 것입니다.

같은 패턴으로 19~22번째 줄 로그를 보면 915.258028 초에 raspbian_proc(pid: 17082) 프로세스가 깨어나 실행합니다.

raspbian_proc_test.c 파일에서 3초 간격으로 sleep() 함수를 호출하고 raspbian tracing 이란 메시지를 출력하는 코드가 동작하는 것입니다. 구현된 코드와 같이 다음 시간 간격으로 3초 주기로 raspbian_proc 프로세스가 실행합니다.
909.254409 -> 912.257874  -> 915.258028

프로세스가 생성하는 1단계부터 raspbian_proc 프로세스가 3초 간격으로 실행하는 로그를 분석했습니다.

정리하면 유저 모드에서 fork() 이란 리눅스 시스템 저수준 함수를 호출하면 커널 공간에서 fork() 에 대응하는 시스템 콜 핸들러인 sys_clone() 함수를 호출하는 것입니다. 이 후 sys_clone() 함수에서 _do_fork() 함수 호출로 프로세스를 생성(복제)합니다. 

프로세스는 생성 후 바로 실행을 시작하는데 3초 주기로 실행합니다.

이번에는 raspbian_proc 프로세스가 종료하는 2단계 로그를 분석할 차례입니다. 이 과정은 다음 그림에서 확인할 수 있습니다.


우리는 다음 명령어로 raspbian_proc(pid:17082) 프로세스를 강제 종료시켰습니다.
root@raspberrypi:/home/pi# kill -9  17082

유저 레벨 프로세스가 유저 모드에서 명시적으로 exit() 함수를 호출해 종료하지 않고 kill 당한 것입니다.

다음과 같은 형식으로 kill 명령어를 입력하면 유저 레벨 프로세스를 강제 종료시킬 수 있습니다. 여기서 PID는 프로세스 아이디로 정수형 숫자를 의미합니다.
kill -9 [PID]
조금 더 알아보기

위 명령어를 입력하면 리눅스 커널에서는 다음과 같은 동작을 수행합니다.
1. 유저 모드에서 kill() 함수를 호출해서 커널 모드에서 sys_kill() 함수를 실행합니다.
2. “kill -9 [PID]” 명령어에서 PID에 해당하는 프로세스를 스케줄러에게 깨워 달라고 요청합니다.
3. 스케줄러가 PID에 해당하는 프로세스를 컨택스트 스위칭하면 해당 프로세스는 유저 공간으로 복귀 직전 slow_work_pending 이란 레이블을 실행합니다.
4. 위 그림 화살표 방향에서 보이는 함수 흐름으로 do_exit() 함수를 실행해 프로세스를 종료합니다.

kill 명령어는 프로세스를 종료시키는 시그널을 전달하는 명령어입니다.

kill이란 명령어는 유저 레벨에서 시그널로 전달하고 있고 커널에서 kill 명령어 실행에 할 수 있습니다. 조금 어렵게 설명을 드리면 커널에서 kill 명령어에 대응하는 함수 조합으로 kill 명령어 실행과 같은 동작을 할 수 있다는 것입니다.

유저 프로세스가 종료하려면 exit() 이란 함수를 실행하면 됩니다. 이 함수를 호출하면 시스템 콜이 실행되어 커널 공간에서 do_exit() 이란 함수가 실행합니다. 이번 소절에서는 kill 이란 명령어를 입력해서 프로세스를 강제 종료했습니다. exit() 저수준 함수를 호출해서 프로세스를 종료할 때와 실행 흐름이 다릅니다. 

다음은 raspbian_proc-17082 프로세스가 종료할 때 로그입니다.
25 raspbian_proc-17082 [002] .... 933.741230: do_exit+0x14/0xc18 <-do_group_exit+0x50/0xe4
26 raspbian_proc-17082 [002] .... 933.741270: <stack trace>
27 => do_signal+0x300/0x3d4
28 => do_work_pending+0xb4/0xcc
29 => slow_work_pending+0xc/0x20
30 lxpanel-730 [000] d... 933.741295: sched_switch: prev_comm=lxpanel prev_pid=730 prev_prio=120 prev_state=S ==> next_comm=Xorg next_pid=454 next_prio=120
31 Xorg-454 [000] dn.. 933.741333: sched_wakeup: comm=openbox pid=723 prio=120 target_cpu=000
32 Xorg-454 [000] d... 933.741346: sched_switch: prev_comm=Xorg prev_pid=454 prev_prio=120 prev_state=R ==> next_comm=openbox next_pid=723 next_prio=120
33 raspbian_proc-17082 [002] .... 933.741609: sched_process_exit: comm=raspbian_proc pid=17082 prio=120
34 ibus-x11-717 [001] d... 933.741639: sched_switch: prev_comm=ibus-x11 prev_pid=717 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
35 openbox-723 [000] d... 933.741673: sched_switch: prev_comm=openbox prev_pid=723 prev_prio=120 prev_state=S ==> next_comm=Xorg next_pid=454 next_prio=120
36 raspbian_proc-17082 [002] d... 933.741693: signal_generate: sig=17 errno=0 code=2 comm=bash pid=895 grp=1 res=0

위 로그는 다음 명령어로 강제로 raspbian_proc(pid: 17082) 프로세스를 종료했을 때 출력합니다.
root@raspberrypi:/home/pi# kill -9  17082

25~29번째 줄 로그를 보면 raspbian_proc(pid: 17082)가 어떤 콜스택으로 종료하는지 알 수 있습니다.
25 raspbian_proc-17082 [002] .... 933.741230: do_exit+0x14/0xc18 <-do_group_exit+0x50/0xe4
26 raspbian_proc-17082 [002] .... 933.741270: <stack trace>
27 => do_signal+0x300/0x3d4
28 => do_work_pending+0xb4/0xcc
29 => slow_work_pending+0xc/0x20

raspbian_proc(pid:17082) 프로세스가 do_signal() 함수에서 do_exit() 함수를 호출해서 raspbian_proc(pid: 17082) 프로세스를 종료하는 동작입니다.

이번에 36번째 줄 로그를 보겠습니다.
36 raspbian_proc-17082 [002] d... 933.741693: signal_generate: sig=17 errno=0 code=2 comm=bash pid=895 grp=1 res=0

raspbian_proc(pid: 17082)가 자신이 종료한다는 정보를 시그널로 전달합니다. 
프로세스는 종료 과정에서 자신의 부모 프로세스에게 자신이 종료하고 있다는 시그널을 전달합니다.

프로세스가 생성할 때 SyS_clone() 이란 커널 함수가 호출되고 종료될 때 do_exit() 커널 함수가 호출된다는 점을 확인했습니다.

다음에 다른 리눅스 시스템 프로그램을 작성해서 유저 공간에서 생성된 프로세스가 어떤 과정으로 생성되고 소멸되는지 확인합시다.



'리눅스 커널의 구조와 원리 > 4. 프로세스(Process) 관리' 카테고리의 다른 글

[리눅스커널] 커널 스레드란 무엇인가  (0) 2019.03.10
[리눅스커널] 부모 프로세스가 자식 프로세스를 생성하는 과정 ftrace 로그로 분석해보기  (0) 2019.03.10
[리눅스커널][프로세스] 프로세스는 어떻게 생성하나?  (0) 2019.02.11
[리눅스커널][프로세스] ps 명령어로 프로세스 확인하기  (0) 2019.02.11
[리눅스커널[프로세스] 프로세스, 태스크란 무엇일까?  (0) 2019.02.11
리눅스 시스템 개발자(디바이스 드라이버, 데브옵스)로 오래 동안 실력을 인정 받으려면 리눅스 커널을 잘 알면 좋습니다. 하지만 리눅스 커널은 그 내용이 방대하고 깊이가 있어 단기간에 익히기 어려운 기술 영역입니다. "프로세스란 무엇인가"란 질문으로 리눅스 커널을 시작합니다. 성경이나 불경같이 근엄한 단어를 많이 보입니다.  안타깝게도 20페이지 정도 읽다가 포기합니다. 너무 이론으로 프로세스를 설명하기 때문입니다.

프로세스에 익숙해지려면 리눅스 시스템에 익숙해져야 합니다. 이번 장에서는 라즈베리파이에서 명령어를 입력하고 ftrace 로그에서 출력되는 로그로 프로세스 동작을 확인합니다.

먼저 다음 리눅스 명령어로 시스템에서 프로세스 목록을 확인합시다. 이를 위해 라즈베리파이에서 x-terminal 프로그램을 실행해서 셸을 열어야 합니다. 
root@raspberrypi:/home/pi# ps -ely
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S     0     1     0  0  80   0  5956  6991 SyS_ep ?        00:00:02 systemd
S     0     2     0  0  80   0     0     0 kthrea ?        00:00:00 kthreadd
...
S  1000   867   517  0  80   0  7720 12887 poll_s ?        00:00:00 gvfsd-trash
S  1000   876   730  0  80   0 20084 12108 poll_s ?        00:00:07 lxterminal
S  1000   877   876  0  80   0  1324   590 unix_s ?        00:00:00 gnome-pty-helpe
S  1000   878   876  0  80   0  4028  1628 wait   pts/0    00:00:00 bash
S     0   886   878  0  80   0  3380  1908 poll_s pts/0    00:00:00 sudo
S     0   890   886  0  80   0  3076  1818 wait   pts/0    00:00:00 su
리눅스 시스템에서 프로세스 목록을 보기 위해서는 "ps"라는 명령어를 입력하면 됩니다.

x-terminal 셸을 실행한 상태에서 "info ps" 명령어를 입력하면 ps 명령어의 의미를 알 수 있습니다.

-------
PS(1)                                   User Commands                                   PS(1)

NAME
       ps - report a snapshot of the current processes.

SYNOPSIS
       ps [options]

리눅스 시스템에서 돌고 있는 프로세스를 출력하는 명령어입니다. 리눅스 시스템에서 디버깅을 할 때 많이 쓰는 명령어이니 자주 활용합시다.

리눅스 시스템에서 생성된 모든 프로세스(유저 레벨, 커널 스레드)는 init 프로세스를 표현하는 전역 변수 init_tasks.next 멤버에 연결 리스트로 등록돼 있습니다. ps 명령어를 입력하면 이 연결 리스트를 순회하면서 프로세스 정보(struct task_struct)를 얻어 프로세스 정보를 출력하는 겁니다.

이번에는 ps 명령어에 "-ejH" 이란 옵션을 주고 프로세스를 부모 자식 프로세스 관계로 출력합시다.
1 root@raspberrypi:/home/pi # ps -ejH
2   PID  PGID   SID TTY          TIME CMD
3    2     0     0 ?        00:00:00 kthreadd
4    4     0     0 ?        00:00:00   kworker/0:0H
5    6     0     0 ?        00:00:00   mm_percpu_wq
6    7     0     0 ?        00:00:00   ksoftirqd/0
...
7  17103     0     0 ?     00:00:00   kworker/1:1
8  17108     0     0 ?     00:00:00   kworker/u8:0
9     1     1     1 ?        00:00:02 systemd
10   94    94    94 ?        00:00:00   systemd-journal
11  127   127   127 ?        00:00:00   systemd-udevd
12  274   274   274 ?        00:00:00   systemd-timesyn

4~6번 줄에 보이는 "kworker/0:0H", "mm_percpu_wq" 그리고 "ksoftirqd/0" 이란 프로세스의 부모 프로세스는 3번 줄에 있는 "kthreadd" 입니다. 

pid가 2이 "kthreadd" 프로세스는 커널 공간에서 실행 중인 프로세스를 생성하는 역할을 수행합니다. 위 출력 결과에서 4~8번 줄에 있는 프로세스들은 같은 행으로 정렬돼 있습니다. 이 목록에서 보이는 프로세스를 커널 스레드, 커널 프로세스라고 합니다. 커널 공간에서만 실행합니다. 

리눅스 커널에서는 프로세스 마다 PID(Process id)라는 int 형 ID를 부여합니다.
swapper 프로세스는 PID가 0이고 init 프로세스는 PID가 1 그리고 커널 스레드를 생성하는 kthreadd 프로세스는 PID가 2입니다.
새로운 프로세스를 생성할 때 커널이 부여하는 PID 정수값은 증가합니다. PID로 프로세스가 언제 생성됐는지 추정할 수 있습니다.

PID는 최댓값은 32768로 정해져 있습니다.

이번에는 9번째 줄 로그를 봅시다. pid가 1인 systemd 프로세스가 보입니다.
9     1     1     1 ?        00:00:02 systemd

pid가 1인 프로세스를 임베디드 리눅스에서는 init 프로세스라고 하며 모든 유저 공간에서 생성된 프로세스의 부모 프로세스 역할을 수행합니다.

프로세스는 인간을 객체화해서 고안한 내용이 많습니다. 프로세스는 각자 부모 자식 프로세스들이 있고 자식 프로세스가 종료할 때 부모 프로세스에게 신호를 알립니다.

만약 조부모, 부모, 자식 프로세스가 있다고 가정합니다. 예외 상황으로 부모 프로세스가 종료되면 자식 프로세스 입장에서 부모 프로세스가 사라집니다. 이 때 조부모가 부모 프로세스가 됩니다. 이런 상황에서 init 프로세스가 조부모 역할(새로운 부모 프로세스)을 수행합니다.

다음에 리눅스 커널 소스 코드를 열어서 프로세스를 생성할 때 어떤 함수가 실행하는지 살펴봅시다.


'리눅스 커널의 구조와 원리 > 4. 프로세스(Process) 관리' 카테고리의 다른 글

[리눅스커널] 커널 스레드란 무엇인가  (0) 2019.03.10
[리눅스커널] 부모 프로세스가 자식 프로세스를 생성하는 과정 ftrace 로그로 분석해보기  (0) 2019.03.10
[리눅스커널][프로세스] 기본 유저 레벨 프로세스 실행 실습 및 ftrace 로그 분석  (0) 2019.02.11
[리눅스커널][프로세스] 프로세스는 어떻게 생성하나?  (0) 2019.02.11
[리눅스커널[프로세스] 프로세스, 태스크란 무엇일까?  (0) 2019.02.11

+ Recent posts

티스토리툴바