Now, let me look into the spinlock implmentation in more details.

After analyzing the assembly code, R2 is key debugging signature which is the original value of spinlock owner.


Code Review: arch_spin_lock(part 1) -> If the spinlock is acquired sucessfully.

Let me assume tickets.next=0x0, tickets.owner=0x0(spinlock is not held) before _raw_spin_lock() is executed

[1]: R2: (raw_spinlock_t *)lock is loaded from R0.

[2]: +1 increament struct raw_spinlock_t.raw_lock.tickets.next of R2 and save it into R3(0x1, raw_spinlock_t.raw_lock.tickets.next+1)

[3]: Save the incremented +0x1 next element into lock value

If "strex" insruction is executed successfully, r1=0x0, otherwise, r1=0x1

[4]: if R1 is 0x0, jump to 0xc0ee8c60, else go to [1]0xc0ee8c4c.

[5]: R3(0x0) is holding struct raw_spinlock_t.raw_lock.tickets.owner from R2(original spinlock)

Please be reminded that R2 holds original struct raw_spinlock_t* lock;

[6]: R2(0x0) contains struct raw_spinlock_t.raw_lock.tickets.next from R2

[7]: Compare R2(tickets.next) and R3(tickets.owner)

[8]: In this case, tickets.next == tickets.owner(spinlock is not held before this funtion is called), jump to 0xc0ee8c80 for function termination.

0xc0ee8c30 <_raw_spin_lock>:    mov     r2, sp

0xc0ee8c34 <_raw_spin_lock+0x4>:        bic     r3, r2, #8128   ; 0x1fc0

0xc0ee8c38 <_raw_spin_lock+0x8>:        bic     r3, r3, #63     ; 0x3f

0xc0ee8c3c <_raw_spin_lock+0xc>:        ldr     r2, [r3, #4]

0xc0ee8c40 <_raw_spin_lock+0x10>:       add     r2, r2, #1

0xc0ee8c44 <_raw_spin_lock+0x14>:       str     r2, [r3, #4]

0xc0ee8c48 <_raw_spin_lock+0x18>:       pldw    [r0]

0xc0ee8c4c <_raw_spin_lock+0x1c>:       ldrex   r2, [r0]  //<<--[1]

0xc0ee8c50 <_raw_spin_lock+0x20>:       add     r3, r2, #65536  ; 0x10000  //<<--[2]

0xc0ee8c54 <_raw_spin_lock+0x24>:       strex   r1, r3, [r0] //<<--[3]

0xc0ee8c58 <_raw_spin_lock+0x28>:       teq     r1, #0 //<<--[4]

0xc0ee8c5c <_raw_spin_lock+0x2c>:       bne     0xc0ee8c4c <_raw_spin_lock+28>

0xc0ee8c60 <_raw_spin_lock+0x30>:       uxth    r3, r2  //<<--[5]

0xc0ee8c64 <_raw_spin_lock+0x34>:       ubfx    r2, r2, #16, #16  //<<--[6]

0xc0ee8c68 <_raw_spin_lock+0x38>:       cmp     r2, r3  //<<--[7]

0xc0ee8c6c <_raw_spin_lock+0x3c>:       beq     0xc0ee8c80 <_raw_spin_lock+80> //<<--[8]

0xc0ee8c70 <_raw_spin_lock+0x40>:       wfe

0xc0ee8c74 <_raw_spin_lock+0x44>:       ldrh    r3, [r0]

0xc0ee8c78 <_raw_spin_lock+0x48>:       uxth    r3, r3

0xc0ee8c7c <_raw_spin_lock+0x4c>:       b       0xc0ee8c68 <_raw_spin_lock+56>

0xc0ee8c80 <_raw_spin_lock+0x50>:       dmb     ish

0xc0ee8c84 <_raw_spin_lock+0x54>:       bx      lr


Code Review: arch_spin_lock(part 2) -> If the spinlock is held by someone, so it waits for it to released.

Let me assume tickets.next=0x1, tickets.owner=0x0(the spinlock is already held) before _raw_spin_lock() is executed.

[1]: R2: (raw_spinlock_t *)lock is loaded from R0.

[2]: +1 increament struct raw_spinlock_t.raw_lock.tickets.next of R2 and save it into R3(0x2, raw_spinlock_t.raw_lock.tickets.next+1)

[3]: Save the incremented +0x1 next element into lock value(raw_spinlock_t.raw_lock.tickets.next is updated as 0x2)

If "strex" insruction is executed successfully, r1=0x0, otherwise, r1=0x1

[4]: if R1 is 0x0, jump to 0xc0ee8c60, else go to [1]0xc0ee8c4c.

[5]: R3(0x0) is holding struct raw_spinlock_t.raw_lock.tickets.owner from R2

Please be reminded that R2 holds original struct raw_spinlock_t* lock;

[6]: R2(0x1) contains struct raw_spinlock_t.raw_lock.tickets.next from R2

[7]: Compare R2(tickets.next: 0x1) and R3(tickets.owner: 0x0)

[8]: The tickets.next > tickets.owner means spinlock is already held, this code is executed.

R3 is loaded from (raw_spinlock_t *) lock which is the spinlock **instance**(which can be accessed other processes)

[9]: R3 is updated as struct raw_spinlock_t.raw_lock.tickets.owner. And then jump to [7] 0xc0ee8c68.

0xc0ee8c30 <_raw_spin_lock>:    mov     r2, sp

0xc0ee8c34 <_raw_spin_lock+0x4>:        bic     r3, r2, #8128   ; 0x1fc0

0xc0ee8c38 <_raw_spin_lock+0x8>:        bic     r3, r3, #63     ; 0x3f

0xc0ee8c3c <_raw_spin_lock+0xc>:        ldr     r2, [r3, #4]

0xc0ee8c40 <_raw_spin_lock+0x10>:       add     r2, r2, #1

0xc0ee8c44 <_raw_spin_lock+0x14>:       str     r2, [r3, #4]

0xc0ee8c48 <_raw_spin_lock+0x18>:       pldw    [r0]

0xc0ee8c4c <_raw_spin_lock+0x1c>:       ldrex   r2, [r0]  //<<--[1]

0xc0ee8c50 <_raw_spin_lock+0x20>:       add     r3, r2, #65536  ; 0x10000  //<<--[2]

0xc0ee8c54 <_raw_spin_lock+0x24>:       strex   r1, r3, [r0] //<<--[3]

0xc0ee8c58 <_raw_spin_lock+0x28>:       teq     r1, #0 //<<--[4]

0xc0ee8c5c <_raw_spin_lock+0x2c>:       bne     0xc0ee8c4c <_raw_spin_lock+28>

0xc0ee8c60 <_raw_spin_lock+0x30>:       uxth    r3, r2  //<<--[5]

0xc0ee8c64 <_raw_spin_lock+0x34>:       ubfx    r2, r2, #16, #16  //<<--[6]

0xc0ee8c68 <_raw_spin_lock+0x38>:       cmp     r2, r3  //<<--[7]

0xc0ee8c6c <_raw_spin_lock+0x3c>:       beq     0xc0ee8c80 <_raw_spin_lock+80>

0xc0ee8c70 <_raw_spin_lock+0x40>:       wfe

0xc0ee8c74 <_raw_spin_lock+0x44>:       ldrh    r3, [r0] //<<--[8]

0xc0ee8c78 <_raw_spin_lock+0x48>:       uxth    r3, r3  //<<--[9]

0xc0ee8c7c <_raw_spin_lock+0x4c>:       b       0xc0ee8c68 <_raw_spin_lock+56>

0xc0ee8c80 <_raw_spin_lock+0x50>:       dmb     ish

0xc0ee8c84 <_raw_spin_lock+0x54>:       bx      lr


Code Review: arch_spin_lock(part 2.1): if process is waiting for spinlock to be released.

Running [7]-[8]-[9] loop until struct raw_spinlock_t.raw_lock.tickets.owner is increated 0x1(which means spinlock is released)

0xc0ee8c68 <_raw_spin_lock+0x38>:       cmp     r2, r3  //<<--[7]

0xc0ee8c6c <_raw_spin_lock+0x3c>:       beq     0xc0ee8c80 <_raw_spin_lock+80>

0xc0ee8c70 <_raw_spin_lock+0x40>:       wfe

0xc0ee8c74 <_raw_spin_lock+0x44>:       ldrh    r3, [r0] //<<--[8]

0xc0ee8c78 <_raw_spin_lock+0x48>:       uxth    r3, r3  //<<--[9]

Please be reminded that R2 holds original struct raw_spinlock_t* lock.ticker.owner;


Code Review: arch_spin_lock(part 2.2): Exit this function after the spinlock is released.


After running [7]-[8]-[9] loop...

[8]: R3 is loaded from (raw_spinlock_t *) lock which is the spinlock **instance**(which can be accessed other processes)

[9]: At this point, if other process releases spinlock, R3 is updated as 0x1 (as struct raw_spinlock_t.raw_lock.tickets.owner is increamented).

[7]: Since R2 == R3(spinlock is released), exit this function.

0xc0ee8c68 <_raw_spin_lock+0x38>:       cmp     r2, r3  //<<--[7]

0xc0ee8c6c <_raw_spin_lock+0x3c>:       beq     0xc0ee8c80 <_raw_spin_lock+80>

0xc0ee8c70 <_raw_spin_lock+0x40>:       wfe

0xc0ee8c74 <_raw_spin_lock+0x44>:       ldrh    r3, [r0] //<<--[8]

0xc0ee8c78 <_raw_spin_lock+0x48>:       uxth    r3, r3  //<<--[9]


To wrap up the spinlock operation in easy way, let me picture the following scenario.

1. Scenario: next: 0x0, owner:0x0(before spinlock is called)

[1]. Increament next +1(next: 0x1)

[2]: Exit spinlock

2. Scenario: next: 0x1, owner:0x0(before spinlock is called)

[1]. Increament next +1(next: 0x2)

[2]: Original next(0x1) is saved R2

[3]: Loop until the owner of spinlock instance is updated as 0x1(by other process)

[4]: Exit spinlock(next: 0x2, owner:0x1)

3. Scenario: next: 0x45, owner:0x41(before spinlock is called): it means the spinlock is held by 4 times.

[1]. Increament next +1(next: 0x46)

[2]: Original next(0x45) is saved R2

[3]: Loop until the owner of spinlock instance is updated as 0x45(by other process)

[4]: Exit spinlock(next: 0x46, owner:0x45)


Kernel panic occurs with defective device under the following call trace.

crash> bt -I C01002D8 -S  E7AABC08 0xE1804200

PID: 2285   TASK: e1804200  CPU: 5   COMMAND: "python"

bt: WARNING:  stack address:0xe7aabd80, program counter:0xc0ee5b60

 #0 [<c01002d8>] (do_DataAbort) from [<c010ad58>]

    pc : [<c01d7308>]    lr : [<c01d72ec>]    psr: 60020193

    sp : e7aabcf8  ip : c193e69c  fp : edf34bf4

    r10: 00000000  r9 : 0000001f  r8 : 00000002

    r7 : c1938280  r6 : c1938200  r5 : 00000010  r4 : ef4bddb4

    r3 : ef4bddb4  r2 : 00000100  r1 : 00000000  r0 : ef4bdda0

    Flags: nZCv  IRQs off  FIQs on  Mode SVC_32  ISA ARM

 #1 [<c010ad58>] (__dabt_svc) from [<c01d72ec>]

 #2 [<c01d7308>] (rmqueue_bulk.constprop.11) from [<c01d7540>]  //<<-- kernel panic

 #3 [<c01d7540>] (get_page_from_freelist) from [<c01d79c4>]

 #4 [<c01d79c4>] (__alloc_pages_nodemask) from [<c01f7bf4>]

 #5 [<c01f7bf4>] (handle_mm_fault) from [<c011525c>]

 #6 [<c011525c>] (do_page_fault) from [<c01002d8>]

 #7 [<c01002d8>] (do_DataAbort) from [<c010b03c>]


The data abort is raised since page.lru->next(R2) holds invalid address 0x100.

0xc01d72f4 <rmqueue_bulk.constprop.11+0x58>:    cmp     r10, #0

0xc01d72f8 <rmqueue_bulk.constprop.11+0x5c>:    add     r3, r0, #20

0xc01d72fc <rmqueue_bulk.constprop.11+0x60>:    ldreq   r2, [r4]

0xc01d7300 <rmqueue_bulk.constprop.11+0x64>:    ldrne   r2, [r4, #4]

0xc01d7304 <rmqueue_bulk.constprop.11+0x68>:    strne   r3, [r4, #4]

0xc01d7308 <rmqueue_bulk.constprop.11+0x6c>:    streq   r3, [r2, #4]  //<<-- data abort

crash> struct page.lru  0xEF4BDDA0  -px

    lru = {

      next = 0x100,  //<<--

      prev = 0x200

    }


After having code review, I have figured out that attribute of page is pcp(per-cpu page frame cache: buddy system, 0 order page)

static int rmqueue_bulk(struct zone *zone, unsigned int order,

   unsigned long count, struct list_head *list,

   int migratetype, bool cold)

{

 int i;


 spin_lock(&zone->lock);

 for (i = 0; i < count; ++i) {

  struct page *page;


//snip

  if (likely(!cold))

   list_add(&page->lru, list);  //<<--

  else

   list_add_tail(&page->lru, list);


To find out pcp address for CPU5, the following command s are used.

crash> p contig_page_data.node_zones[1].pageset

$5 = (struct per_cpu_pageset *) 0xc177ebdc


crash> struct per_cpu_pages  EDF34BDC

struct per_cpu_pages {

  count = 0x1,

  high = 0xba,

  batch = 0x1f,

  lists = {{

      next = 0xef51fc74,  //<<--MIGRATE_UNMOVABLE

      prev = 0xef51fc74

    }, {

      next = 0xedf34bf0, //<<--MIGRATE_RECLAIMABLE

      prev = 0xedf34bf0

    }, {

      next = 0xef4bdcd4,//<<--MIGRATE_MOVABLE

      prev = 0xef4bddf4

    }, {

      next = 0xedf34c00, //<<--MIGRATE_PCPTYPES

      prev = 0xedf34c00

    }}

}


(where) 0xEDF34BDC = 0xc177ebdc+0x2c7b6000

crash> p  __per_cpu_offset[5]

$7 = 0x2c7b6000


BTW the listed list 0xef4bdcd4 address is found to be corrupted as follows. 

crash> list 0x0 0xef4bdcd4

ef4bdcd4

ef4bdcf4

ef4bdd14

ef4bdd34

ef4bdd54

ef4bdd74

ef4bddb4

100

(where)

 #0 [<c01002d8>] (do_DataAbort) from [<c010ad58>]

    pc : [<c01d7308>]    lr : [<c01d72ec>]    psr: 60020193

    sp : e7aabcf8  ip : c193e69c  fp : edf34bf4

    r10: 00000000  r9 : 0000001f  r8 : 00000002

    r7 : c1938280  r6 : c1938200  r5 : 00000010  r4 : ef4bddb4

    r3 : ef4bddb4  r2 : 00000100  r1 : 00000000  r0 : ef4bdda0

    Flags: nZCv  IRQs off  FIQs on  Mode SVC_32  ISA ARM

 #1 [<c010ad58>] (__dabt_svc) from [<c01d72ec>]

 #2 [<c01d7308>] (rmqueue_bulk.constprop.11) from [<c01d7540>]  //<<-- kernel panic

 #3 [<c01d7540>] (get_page_from_freelist) from [<c01d79c4>]


After the device is disassembled again with another PMIC, the crash disappears.


특정 시점부터 갑자기 디바이스가 락업되는 현상이 리포트가 되었거든요. 엄청 락업된 디바이스가 쏟아 졌었는데요.


이번 시간에는 그 때 어떻게 디버깅을 해서 문제를 해결했는지 업데이트하고자 해요.


락업이 된 상태에서 디바이스를 받아 강제로 코어 덤프를 뜬 다음에 콜 트레이스를 봤는데요.

아래 콜 스택이 확인되었어요. 프로세스 이름은 "atd" 이에요.


reboot 시스템콜을  trigger한 다음에 각 종 시스템 드라이버를 종료하는 과정에서 mutex lock을 계속 기다리는 현상이 확인되네요.

-000|context_switch(inline)

-000|__schedule()

-001|schedule_preempt_disabled()

-002|spin_lock(inline)

-002|__mutex_lock_common(inline)

-002|__mutex_lock_slowpath(lock_count = 0xC1327164)

-003|current_thread_info(inline)

-003|mutex_set_owner(inline)

-003|mutex_lock(lock = 0xC1327164)  // cpu_add_remove_lock

-004|cpu_hotplug_disable()

-005|migrate_to_reboot_cpu()

-006|kernel_restart(cmd = 0x0)

-007|SYSC_reboot(inline)

-007|sys_reboot(magic1 = -18751827, ?, cmd = 19088743, arg = 0)

-008|ret_fast_syscall(asm)

 -->|exception

-009|__reboot(asm)  // android/bionic/libc/arch-arm/syscalls/__reboot.S|9

-010|restart(?)  

-011|__pthread_start(arg = 0xB55F7930)

-012|__start_thread(?, ?)


뮤텍스 데드락 현상이 의심되네요. 어떤 프로세스가 뮤텍스 락을 잡고 나서 실행 도중 잠들어버려 다른 프로세스가 그 뮤텍스 락을 못잡는 시나리오를 생각해볼 수 있는데요.


뮤텍스 락을 잡고 슬립에 빠지거나 뮤텍스 락을 기다리리며 잠들어 있는 프로세스들은 Interrupt을 받으면 안되기 때문에, 프로세스 상태가 Uninterruptible 상태(struct task_struct->state = TASK_UNINTERRUPTIBLE)이거든요. 


이럴 때 "ps -l | grep UN" 명령어를 입력하면 Uninterruptbile 상태 프로세스를 확인할 수 있어요.

흠, 그런데 "simpleperf" 프로세스가 보이네요.

crash> ps -l | grep UN

[33341014778844] [UN]  PID: 16965  TASK: c3362f40  CPU: 0   COMMAND: "atd" // <<--

[ 3069103232273] [UN]  PID: 8919   TASK: d4bfb9c0  CPU: 0   COMMAND: "simpleperf"  // <<--

[     727796356] [UN]  PID: 123    TASK: df6e9500  CPU: 1   COMMAND: "mdss_dsi_event"

 

"simpleperf" 프로세스(PID: 8919)의 콜스택을 살펴보니, 뮤텍스 락을 잡고 잠들어버리고 있네요.

세부 디버깅 정보는 콜 스택 옆에 있는 주석문을 참고하세요.

-00 |context_switch(inline)

-00 |__schedule()

-01 |schedule_preempt_disabled()

-02 |spin_lock(inline)

-02 |__mutex_lock_common(inline)

-02 |__mutex_lock_slowpath(lock_count = 0xDD05A008)

-03 |current_thread_info(inline)

-03 |mutex_set_owner(inline)

-03 |mutex_lock(lock = 0xDD05A008)  // <<-- mutex lock

-04 |SYSC_perf_event_open(inline)  // /data/misc/perfprofd/perferr.txt 파일을 오픈

-04 |sys_perf_event_open(?, pid = 3, cpu = 0, ?, flags = 0)

-05 |ret_fast_syscall(asm)

--> |exception

-06 |syscall(asm)  // <<-- userspace  system calls

-07 |perf_event_open(inline)

-07 |EventFd::OpenEventFile(?, pid = 8919, cpu = -1)  // <<-- android/system/extras/simpleperf/event_fd.cpp|37

-08 |EventFd::OpenEventFileForProcess(attr = (typ //<<-- android/system/extras/simpleperf/event_fd.cpp|41

-09 |operator bool(inline)

-09 |operator!=<EventFd, std::__1::default_delete<EventFd> >(inline)

-09 |IsEventTypeSupportedByKernel(inline)

-09 |IsSupportedByKernel(inline)

-09 |EventTypeFactory::FindEventTypeByName(?, ?)

-10 |SetMeasuredEventType(inline)

-10 |RecordCommandImpl::Run(this = 0xBEB08848, ?)

-11 |RecordCommand::Run(?, args = (std::__1::__vector_base<std::__1::basic_strin

-12 |main(?, ?)

-13 |__libc_init(?, ?, slingshot = 0xB6F9AB45, ?)

-14 |start(asm)

 

mutex_lock(lock = 0xDD05A008)에서 보이는 mutex lock 디버깅 좀 해볼께요.

뮤텍스 락을 획득하기 위해 기다리는 프로세스는 struct mutex->wait_list 리스트에 자신의 뮤텍스(Mutex) 인스턴스를 등록하고 잠들어거든요.

 (struct mutex*)0xDD05A008 = 0xDD05A008 -> (

    count = (counter = 0xFFFFFFFF),

    wait_lock = (rlock = (raw_lock = (slock = 0x00010001, tickets = (owner = 0x1

    wait_list = (

      next = 0xD1611EBC -> (

        next = 0xDD05A010,

        prev = 0xDD05A010),

      prev = 0xD1611EBC),

    owner = 0xD4BFB9C0,  // <<-- "simpleperf", PID: 8919 프로세스의 task descriptor

    spin_mlock = 0x0)

 

container_of(출처: http://rousalome.egloos.com/9963702) 란 매크로를 써서 뮤텍스 락을 디버깅을 좀 더 해봤더니, "simpleperf" 란 프로세스가 뮤덱스 락을 한번 획득하고 난 다음에 또 다시 획득하려다가 잠들어 버린 디버깅 정보가 확인되네요.  

wait_list.next=0xD1611EBC

  (struct mutex *) container_of(0xD1611EBC,struct mutex,wait_list) = 0xD1611EB4

  // snip

    (struct task_struct *) owner = 0xD4BFB9C0 //<<--"simpleperf", PID: 8919 프로세스의 task descriptor


wait_list.next.next=0xDD05A010

  (struct mutex *) container_of(0xDD05A010,struct mutex,wait_list) = 0xDD05A008

    (atomic_t) count = ((int) counter = -1 = 0xFFFFFFFF = '....'),

//snip

    (struct task_struct *) owner = 0xD4BFB9C0 // <<-- "simpleperf", PID: 8919 프로세스의 task descriptor

 

코드 리뷰를 해보니 정말로 mutex lock을 두 번 잡고 있네요. 

어떤 분이 커널 마이그레이션을 하다가 conflict이 나서 실수로 mutex lock 코드를 추가한 것 같아요. 

SYSCALL_DEFINE5(perf_event_open,

        struct perf_event_attr __user *, attr_uptr,

        pid_t, pid, int, cpu, int, group_fd, unsigned long, flags)

{

// .. 생략..

    if (move_group) {

        gctx = group_leader->ctx;


        /*

         * See perf_event_ctx_lock() for comments on the details

         * of swizzling perf_event::ctx.

         */

        mutex_lock_double(&gctx->mutex, &ctx->mutex);


        perf_remove_from_context(group_leader, false);


        perf_event__state_init(group_leader);

        list_for_each_entry(sibling, &group_leader->sibling_list,

                    group_entry) {

            perf_remove_from_context(sibling, false);

            perf_event__state_init(sibling);

            put_ctx(gctx);

        }

    } else {

        mutex_lock(&ctx->mutex);  //<<--

    }


    WARN_ON_ONCE(ctx->parent_ctx);

    mutex_lock(&ctx->mutex);  //<<-


위에 보이는 mutex_lock을 삭제하니 문제는 사라졌어요. 커널 마이그레이션 할 때 conflict나면 살 떨려서 어떻게 하죠? 조심해야 겠어요.

스케줄링(scheduling)/스케줄러(schedule)란 무엇일까? 


여러분들은 리눅스 시스템이 탑재된 휴대폰이나 라즈베리파이를 쓰면 동시에 여러 프로그램을 실행할 수 있습니다. 휴대폰을 보면 다양한 프로그램이 동시에 실행하는 것을 확인할 수 있습니다. 예를 들면 브라우저를 실행하면서 음악을 듣거나 메신저를 하면서 어플리케이션을 다운로드 할 수 있습니다.

그래서 사람들은 여러 프로세스들이 동시에 CPU에서 실행한다고 느낄 수 있습니다. 하지만 CPU는 여러 개의 프로세스를 절대로 동시에 실행할 수는 없습니다. 리눅스 커널을 포함한 다양한 운영체제에서 스케줄링과 멀티 태스킹 기법이 생겨난 이유는 다음과 같습니다.
CPU는 한 순간에 한 개의 프로세스의 코드만을 실행할 수 있습니다.

여러 개의 프로세스들이 효율적으로 번갈아 CPU에서 실행할 수 있게 규칙을 부여하고 프로세스들을 관리하는 소프트웨어 모듈을 스케줄러라고 말합니다.

하나의 프로세스는 CPU에서 실행을 시작하면 계속 CPU에서 실행하는 것이 아니라 실행을 하다가 잠깐 멈추고 다시 실행하는 방식으로 동작합니다. 즉, 프로세스는 CPU를 점유하면서 실행 중인 상태와 실행 대기하는 상태로 계속 변경하는 것입니다.

메모리에 존재하는 여러 프로세스 중에서 실제 CPU에서 실행될 프로세스를 선택하는 일을 스케줄링이라고 말합니다. 이 때 어떤 프로세스를 어떤 방식으로 선택할지를 결정해야 합니다. 

스케줄링 동작은 다음 그림으로 표현할 수 있습니다.
 

CPU에서 실행하려고 대기 중인 Process A ~ Process D 프로세스 중 하나를 선택해서 CPU에서 실행시키는 동작입니다.

스케줄링 동작을 다른 각도에서 살펴보겠습니다. 다음 그림은 프로세스 상태 변화 다이어그램입니다.
 

커널은 프로세스에게 프로세스 상태를 부여합니다. 프로세스가 생성 및 실행된 후 종료할 때까지 위와 같은 상태 변화로 동작합니다.

프로세스가 CPU에서 실행하기 위해서는 실행 대기(TASK_RUNNING) 상태로 변경한 다음 커널 스케줄링에 의해 CPU 실행(TASK_RUNNING) 상태로 변경되어야 합니다.

대부분 보통 프로세스 실행 상태 변화 흐름을 프로세스 1인칭으로 바라볼 때가 많습니다.
이번에는 시스템 전체 관점으로 프로세스 상태 변화 다이어그램을 살펴봅시다.

 

커널에서 실행 중인 전체 프로세스가 각각 어떤 상태로 실행 중인지를 보여주는 그림입니다. 원형으로 표시된 A~N는 각각 프로세스를 의미합니다.

A~D 프로세스들은 실행 대기(TASK_RUNNING) 상태에 있습니다. CPU에서 실행하기 위해 대기 중인 프로세스입니다.

CPU 실행(TASK_RUNNING) 상태를 보면 E 프로세스가 CPU에서 실행 중입니다.

다른 관점으로 스케줄링 동작을 다음과 같이 설명할 수 있습니다.
실행 대기(TASK_RUNNING) 상태에 있는 프로세스 중 하나를 선택해서 CPU 실행(TASK_RUNNING) 상태로 바꿔주는 동작

커널 스케줄링은 프로세스 상태 기준으로 실행 대기 중에 있는 프로세스를 어떤 방식으로 실행할지를 결정합니다. 따라서 프로세스 상태 정보는 매우 중요합니다.

대부분 드라이버 코드를 작성할 때 프로세스 상태를 변경하는 코드를 작성할 필요는 없습니다. 하지만, 커널 스레드 핸들 함수를 구현할 때 프로세스 상태를 변경하는 코드를 입력할 때가 있습니다. 이 때 반드시 set_current_state() 함수를 써서 프로세스 상태를 변경해야 합니다.

그 이유는 다음과 같이 set_current_state() 함수 코드를 보면 알 수 있습니다.
[https://elixir.bootlin.com/linux/v4.14.70/source/include/linux/sched.h]
1 #define set_current_state(state_value) \
2 do { \
3 WARN_ON_ONCE(is_special_task_state(state_value));\
4 current->task_state_change = _THIS_IP_; \
5 smp_store_mb(current->state, (state_value)); \
6 } while (0)

5 번째 줄을 보면 smp_store_mb() 함수를 호출해서 메모리 배리어를 실행합니다.
메모리 배리어 코드를 추가하면 GCC 컴파일러가 코드 최적화를 위해 코드 위치를 변경하는 것을 방지합니다.


임베디드 개발에서 T32-Trace32 장비를 많이 써서 소스 코드 디버깅을 합니다.


이번 시간에는 리눅스 커널에서 웨이크락(wake lock)을 잡는 모듈이 누구인지 파악하는 디버깅(Debugging) 방법을 소개합니다.


리눅스 커널는 wakeup_sources이란 연결 리스트를 통해 wakelock 정보를 확인할 수 있습니다.


리눅스 커널 개발자 중에 crash-utility을 잘 쓰는 분이 있습니다.

하지만 임베디드 개발에선 Trace32도 더 많이 활용하는 것 같습니다.

개발자는 다양한 툴을 써야 한 가지 툴에 종속된 노예 개발자가 되는 것을 피할 수 있습니다.

또한 각 툴의 장점을 잘 활용할 수도 있습니다.


먼저, 다음 T32 명령어를 입력해서 offsetof와 container_of 매크로를 생성합시다.

sYmbol.NEW.MACRO offsetof(type,member) ((int)(&((type*)0)->member))

sYmbol.NEW.MACRO container_of(ptr,type,member) ((type *)((char *)(ptr)-offsetof(type,member)))


리눅스 커널 소스 코드에서 구현된 그래도 매크로를 선언하는 것입니다.

#define container_of(ptr, type, member) ({ \

void *__mptr = (void *)(ptr); \

((type *)(__mptr - offsetof(type, member))); })


#define offsetof(TYPE, MEMBER) ((size_t)&((TYPE *)0)->MEMBER)


우선 wakeup_sources 변수를 봅시다.

v.v %h %t wakeup_sources

  (static struct list_head) wakeup_sources = (

    (struct list_head *) next = 0xFFFFFFC5FD92EA88 -> (

      (struct list_head *) next = 0xFFFFFFC5FD92FC88 -> (

        (struct list_head *) next = 0xFFFFFFC541226488,

        (struct list_head *) prev = 0xFFFFFFC5FD92EA88),

      (struct list_head *) prev = 0xFFFFFF97D92B4D00),

    (struct list_head *) prev = 0xFFFFFFC62D3EDB88)


wakelock을 잡은 모듈들은 wakeup_sources 이란 전역 변수에 등록돼 있습니다.

계속 struct list_head->next로 리스트들이 연결돼 있다는 사실을 파악할 수 있습니다.


이제 앞에서 생성한 container_of 매크로를 쓸 순간입니다. 다음과 같이 명령어를 입력합시다.

v.v %h %t %s  container_of(0xFFFFFFC5FD92EA88,struct wakeup_source,entry)

  (struct wakeup_source *) container_of(0xFFFFFFC5FD92EA88,struct wakeup_source,entry) = 0xFFFFFFC5FD92EA80 -> (

    (char *) name = 0xFFFFFFC55DEE3280 -> "ipc00001269_1988_HwBinder:682_1",

    (struct list_head) entry = ((struct list_head *) next = 0xFFFFFFC5FD92FC88, (struct list_head *) prev = 0xFFF

    (spinlock_t) lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u16) owner = 0x298F, (u16)

    (struct wake_irq *) wakeirq = 0x0,

    (struct timer_list) timer = ((struct hlist_node) entry = ((struct hlist_node *) next = 0x0, (struct hlist_nod

    (long unsigned int) timer_expires = 0x0,

    (ktime_t) total_time = ((s64) tv64 = 0x0),

    (ktime_t) max_time = ((s64) tv64 = 0x0),

    (ktime_t) last_time = ((s64) tv64 = 0x000040E1FC6B0DF2),

    (ktime_t) start_prevent_time = ((s64) tv64 = 0x0),

    (ktime_t) prevent_sleep_time = ((s64) tv64 = 0x0),

    (long unsigned int) event_count = 0x0,

    (long unsigned int) active_count = 0x0,

    (long unsigned int) relax_count = 0x0,

    (long unsigned int) expire_count = 0x0,

    (long unsigned int) wakeup_count = 0x0,

    (long unsigned int) pending_count = 0x0,

    (bool:1) active = FALSE,

    (bool:1) autosleep_enabled = FALSE)


위 멤버 변수 중 active 변수가 FALSE이니 "ipc00001269_1988_HwBinder:682_1"이란 wakeup source가 wakelock을 잡고 있지 않습니다.


v.v %h %t %s  container_of(0xFFFFFFC5FD92EA88,struct wakeup_source,entry)


위와 같은 명령어를 쓴 이유는, struct wakeup_source이란 구조체에 entry이란 struct list_head 타입 멤버 변수가

wakeup_sources이란 링크드 리스트 전역 변수 wakeup_sources->next로 등록됐기 때문입니다.


해당 구조체를 봅시다.

struct wakeup_source {

const char *name;

struct list_head entry;

spinlock_t lock;

struct wake_irq *wakeirq;

struct timer_list timer;

unsigned long timer_expires;

ktime_t total_time;

ktime_t max_time;

ktime_t last_time;

ktime_t start_prevent_time;

ktime_t prevent_sleep_time;

unsigned long event_count;

unsigned long active_count;

unsigned long relax_count;

unsigned long expire_count;

unsigned long wakeup_count;

bool active:1;

bool autosleep_enabled:1;

};


쉽게 설명하면 아래 방식으로 wakeup_source가 wakeup_sources 리스트에 등록합니다.

1st wakeup source 등록

wakeup_sources->next = struct wakeup_source->entry


2nd wakeup source등록

wakeup_sources->next->next = struct wakeup_source->entry


개발자분들이여, 임베디드 동네의 최강의 툴인 Trace32를 잘 활용해서 일찍 퇴근합시다.

임베디드 개발자들의 성격

2009년 스마트폰 시대 부터 비에스피(BSP: Embedded Linux driver/Linux kernel)개발을 시작한 지 어언 9년이 흘렀다. 정말 9년 동안 수 많은 이슈를 만났고 이 놈들을 해결하면서 정말 고생도 많이 했다. 그런데 9년의 시간이 흐른 시점에서 한 가지 아쉬운 점은 나의 체험으로 느낀 점을 글로 남기지 못했다. 사실 그 당시 몸도 가누기 힘들 정도로 체력이 방전되어 어떤 글을 남긴다는 것은 상상도 하지 못했다. 이제 조금 나를 뒤돌아 볼 시점인 것 같다. 사실 요즘 조금 한가하기도 하다.

사실 난 원래 풤에어 혹은 비에스피(firmware, BSP)출신 개발자가 아니다. 난 2005년부터 휴대폰을 개발을 했는데 당시 피쳐폰(feature phone)의 유아이 혹은 미들웨어 유지 보수을 담당했었다. 구체적으로 벡터 폰트, 플레시 라이트 등등을 유아이 플렛폼에 맞게 포팅을 했다. 포팅한 함수들을 묶어서 SMS, Call, Camera 등등과 같은 어플리케이션(application) 담당자들에게 API를 제공했다. 이후 에디터 및 플레시 플러그인 까지 개발을 했었다.

그 당시 가끔 펌웨어 개발자(지금 임베디드, BSP개발자)들과 함께 논의를 하면서 디버깅을 할 일이 종종 있었다. 그런데 내 기억 속에서 펌웨어 개발자들은 성질이 참 더러웠다. 상당히 까칠하고 대화가 잘 되지 않는 놈들이었다.

그런데 지금 동료들의 99%는 임베디드 소프트웨어 개발자들이다. 9년 전 내가 생각했던 까칠하고 대화가 잘 안 되는 놈이라고 기억했던 놈들이 나와 내 동료들인 것이다.

우선 기술적인 내용을 적기 앞서 임베디드 개발자들에 인간적인 면 - 성격, 특징 등등-에 대해서 느낀 점에 대해서 할 말이 참 많다.

사실 난 요즘에도 직장 동료들(임베디드 개발자들)과 대화를 나눌 때 정말 답답하다. 이 녀석들은 차를 마시거나 술을 마실 때에도 대부분 기술적인 어떤 사실, 내용 및 생각에 대해서 말하기를 정말 좋아한다. 가끔 보면 상대방이 자신이 말을 듣고 어떤 반응을 보이는 지 개의치 않는 놈들도 볼 수 있다. 정말로 로보트가 갱스터 랩을 하는 것 같이 느낄 때가 많다.
 
가령 아래와 같은 소리를 40분 동안 숨도 쉬지 않고 열정적으로 말 하는 것이다.
"어제 코어덤프에서 스팩 오버플로우(stack overflow) 흔적을 본 것 같은데 프레임 포인터(frame pointer) 주소 근처의 덤프의 패턴이 일정하지 않는 것 같더라구. 그런데 스택이 깨져도 바로 커널 패닉이 발생하지는 않잖어? 스택이 깨질 때의 정확한 순간을 포착 해야 하는데 이를 위한 스팩 프로파일러란 패치가 있더라고. run queue에 쌓여 있는 프로세스에 대응되는 태스트 디스크립터(task descriptor)의 last_arrival이란 변수의 순서대로 정렬을 한 다음에 각각 프로세스 별로 스택 바운더리에 대한 스캔을 하면 좋을 것 같어. 이런 매카니즘으로 디버깅을 하면 사이드 이팩트나 시스템 성능 저하로 인한 커널 패닉이 일어나지는 않을 것 같다.

아니면 arm gcc에서 릴리즈하는 __builtin_return_frame이란 매크로 함수를 사용하는 것도 생각해 볼 수 있지. schedule 시 자주 호출하는 함수에 __builtin_return_frame(0)이란 함수를 추가해서 current란 매크로를 통해 현재 프로세스의 스택 경계 주소를 넘어섰는 지를 알아 볼 수도 있어."

물론 이런 종류의 주제에 대해 대화를 나누는 것은 반드시 필요하다. 우리와 같은 임베디드 개발자들이 업무이자 삶이기 때문이다. 그런데 만날 때 마다 이런 이야기만 하면 어떤까?

내가 쉬는 시간에 직장 동료들과 차를 마시며서 나누고 싶은 대화는 하고 있는 일이 힘든지, 주말에 뭐 했는지, 캠핑으로 갈 곳은 어떤지 등등이다. 인간 대 인간으로 소통하고 싶은 것이다. 그런데 문제는 70%정도 나의 직장동료들은 자신들이 좋아하는 기술적인 주제에 대해서만 끊임없이 이야기를 하고 싶어 한다. 이럴 때 난 도무지 로봇이랑 이야기를 하고 있는 것 같다.

아무리 많은 시간 이런 주제들에 대해서 서로 떠들어댄다고 해도 서로에게 어떤 친밀감이 생길 수 있을까? 다만 서로 어떤 기술에 대한 관심사가 있는 지에 대해서 알 수 있는 것이다. 이런 유형의 임베디드 개발자들은 감성이 매우 메말라있거나 사람을 어떻게 대해야 할 지 모르는 경우가 많다.

저번에 팀 회식에서 한 주임 연구원이 "요즘 정말 힘들다"라고 한 숨을 쉬며 말했다. 내가 봐도 그 친구가 엄청난 업무량과 압박감으로 스트레스를 많이 받고 있다는 것을 한 눈에 알 수 있었다. 일할 때 그 친구의 표정, 담배를 필 때의 고뇌에 찬 눈빛을 보기도 했지만, 그 친구가 처해 있는 상황(처음 엠베디드 개발 업무를 맡았는데 멘토가 없음)을 알고 있었기 때문이다. 난 처음 임베디드 개발을 할 때 그 아찔한 느낌을 아직도 생생히 기억한다. 한 겨울에 목욕탕에 들어가자 마자 바로 80도의 펄펄 끓는 온탕에 바로 들어가는 느낌.

그런데 그 친구의 넋두리를 듣던 내 직장 동료와 부서장이 정말로 예술적이면서도 창의적인 질문을 했다.
"니가 힘든 이유에 대한 백데이터(근거 자료, back data)가 뭐야? 한번 제시해 봐."

뜨악! 술이 확 깨는 순간이다. 커널에 로그가 남듯이 사람의 감정에도 로그가 남는 다고 생각하나? 정말 전두엽에 빵꾸가 난 놈이 아닐까? 정말로 내 상식으로 도저히 이해가 가지 않았다. 뭐 이 때의 느낌을 설명할 만한 단어가 떠오르지 않는다. 충격적이고 파괴적이라고 해야 할까. 내가 좀 극단적인 예시를 든 것 같지만 임베디드 개발에 과몰입한 개발자들의 모습을 볼 수 있는 하나의 그림자라고 봐야 겠다.

이렇게 팀동료의 입장에서 생각을 하지 못하고 오직 기술적으로 세상을 바라보다 보니, 다른 동료들과 업무 상 의사소통을 제대로 할 수 없다. 그래서 이들은 사람들과 제대로 어울릴 줄을 모르고 어울린 다고 해도 코드가 맞는 한 두명의 개발자들하고만 소통한다.  

그래서 다른 분야 개발자들은 임베디드 개발자들과 일하기 어렵다는 말을 종종한다. 대부분 의사소통 문제다. 



tst 명령어를 실행하면 ARM CPSR 레지스터가 어떻게 변경될까?


tst 명령어는 연산자와 비연산자 사이 AND 비트 연산을 수행합니다.


AND 비트 연산 결과에 따라 CPSR 레지스터 Z 비트는 다음과 같이 변경됩니다.

Z: 0 ( AND 비트 연산 결과가 1인 경우)

Z: 1 ( AND 비트 연산 결과가 0인 경우)


tst 명령어가 위와 같이 동작하는지 증명하기 위해 T32 디버거를 실행해 보겠습니다.

다음 화면은 tst 명령어를 실행하기 직전입니다. 

NSR:80107E6C|ret_to_user_from_irq:        ldr     r2,[r9,#0x8]

NSR:80107E70|                             cmp     r2,#0x7F000000   ; r2,#2130706432

NSR:80107E74|                             blne    0x8010B5FC       ; addr_limit_check_failed

NSR:80107E78|                             ldr     r1,[r9]

NSR:80107E7C|_____________________________tst_____r1,#0x0F_________;_r1,#15

NSR:80107E80|                             bne     0x80107E48       ; slow_work_pending

NSR:80107E84|no_work_pending:             bl      0x801E9CE8       ; trace_hardirqs_on


N _  R0          0  R8          0   

Z Z  R1          2  R9          0

C _  R2          0  R10         0

V _  R3          0  R11         0

Q _  R4   00020000  R12         0

     R5          0  R13  C000D000

0 _  R6          0  R14         0

1 _  R7          0  PC   80107E7C

2 _  SPSR       10  CPSR 400001D3


R1가 2(이진수 10)이니 0xF와 AND 비트 연산을 하면 1이 될 것입니다.

1111 (0xF)

  10 (2: R1) 

------

   1 (연산 결과)


다음은 "tst r1,#0x0F" 명령어를 실행한 후 결과입니다.

NSR:80107E6C|ret_to_user_from_irq:        ldr     r2,[r9,#0x8]

NSR:80107E70|                             cmp     r2,#0x7F000000   ; r2,#2130706432

NSR:80107E74|                             blne    0x8010B5FC       ; addr_limit_check_failed

NSR:80107E78|                             ldr     r1,[r9]

NSR:80107E7C|                             tst     r1,#0x0F         ; r1,#15

NSR:80107E80|_____________________________bne_____0x80107E48_______;_slow_work_pending

NSR:80107E84|no_work_pending:             bl      0x801E9CE8       ; trace_hardirqs_on


N _  R0          0  R8          0   

Z _  R1          2  R9          0

C _  R2          0  R10         0

V _  R3          0  R11         0

Q _  R4   00020000  R12         0

     R5          0  R13  C000D000

0 _  R6          0  R14         0

1 _  R7          0  PC   80107E80

2 _  SPSR       10  CPSR     01D3


여기서 눈을 크게 뜨고 봐야 할 중요한 정보는 ARM CPSR 레지스터입니다.

CPSR 레지스터가 0x1D3으로 변경됐습니다. CPSR 레지스터 Z 비트가 0이란 이야기입니다.


bne 명령어는 'branch not equal'이란 뜻입니다. Z가 0이면 브랜치하겠다는 의미입니다.

bne 0x80107E48 ;slow_work_pending


CPSR 레지스터 Z 비트가 0이니 slow_work_pending 레이블로 브랜치 할 것입니다.

NSR:80107E80|_____________________________bne_____0x80107E48_______;_slow_work_pending


이 결과를 예상하면서 위 "bne 0x80107E48 ;slow_work_pending" 코드를 실행하니 

slow_work_pending 레이블로 브랜치했습니다.

NSR:80107E48|E1A0000D__slow_work_pending:__cpy_____r0,r13

NSR:80107E4C|E1A02008                      cpy     r2,r8

NSR:80107E50|EB000D82                      bl      0x8010B460       ; do_work_pending

NSR:80107E54|E3500000                      cmp     r0,#0x0          ; r0,#0

NSR:80107E58|0A000009                      beq     0x80107E84       ; no_work_pending

NSR:80107E5C|B3A07000                      movlt   r7,#0x0          ; r7,#0

NSR:80107E60|E89D007F                      ldm     r13,{r0-r6}

NSR:80107E64|EA000032                      b       0x80107F34       ; local_restart


이번엔 r1 레지스터가 0x1000 일 때 tst 명령어가 어떤 동작을 하는지 확인해봅시다.

NSR:80107E6C|ret_to_user_from_irq:        ldr     r2,[r9,#0x8]

NSR:80107E70|                             cmp     r2,#0x7F000000   ; r2,#2130706432

NSR:80107E74|                             blne    0x8010B5FC       ; addr_limit_check_failed

NSR:80107E78|                             ldr     r1,[r9]

NSR:80107E7C|_____________________________tst_____r1,#0x0F_________;_r1,#15

NSR:80107E80|                             bne     0x80107E48       ; slow_work_pending

NSR:80107E84|no_work_pending:             bl      0x801E9CE8       ; trace_hardirqs_on


N _  R0          0  R8          0   

Z _  R1       1000  R9          0

C _  R2          0  R10         0

V _  R3          0  R11         0

Q _  R4   00020000  R12         0

     R5          0  R13  C000D000

0 _  R6          0  R14         0

1 _  R7          0  PC   80107E7C

2 _  SPSR       10  CPSR     01D3


위 명령어를 실행하기 전 CPSR 레지스터는 0x1D3이고 R1이 0x1000이란 사실을 기억합시다.

0xF는 이진수로 1111이고 R1가 저장하고 있는 0x1000은 이진수로 1111_0000_0000_0000 일 것입니다.


따라서 AND 비트 연산 결과는 0일 것입니다.

1111_0000_0000_0000  ( 0x1000: R1)

               1111  ( 0xF)

--------------------------------------------- AND 연산

            0    (결과)


이 사실을 염두해두고 "tst r1,#0x0F" 명령어를 T32로 실행하겠습니다.

결과 화면은 다음과 같습니다.


NSR:80107E6C|ret_to_user_from_irq:        ldr     r2,[r9,#0x8]

NSR:80107E70|                             cmp     r2,#0x7F000000   ; r2,#2130706432

NSR:80107E74|                             blne    0x8010B5FC       ; addr_limit_check_failed

NSR:80107E78|                             ldr     r1,[r9]

NSR:80107E7C|                             tst     r1,#0x0F         ; r1,#15

NSR:80107E80|_____________________________bne_____0x80107E48_______;_slow_work_pending

NSR:80107E84|no_work_pending:             bl      0x801E9CE8       ; trace_hardirqs_on


[레지스터 세트]

N _  R0          0  R8          0   

Z Z  R1       1000  R9          0

C _  R2          0  R10         0

V _  R3          0  R11         0

Q _  R4   00020000  R12         0

     R5          0  R13  C000D000

0 _  R6          0  R14         0

1 _  R7          0  PC   80107E80

2 _  SPSR       10  CPSR 400001D3


CPSR 레지스터가 400001D3 이고 Z 비트가 1이 됐습니다.

레지스터 세트에서 붉은색으로 표시된 부분을 눈으로 따라가 보시기 바랍니다.

N _  R0          0  R8          0   

Z Z  R1       1000  R9          0


Z 필드가 켜져 있습니다.


Z 비트가 1인데 다음 bne 명령어를 실행하면 어떻게 실행할까요? 

NSR:80107E80|_____________________________bne_____0x80107E48_______;_slow_work_pending

NSR:80107E84|no_work_pending:             bl      0x801E9CE8       ; trace_hardirqs_on


당연히 slow_work_pending 레이블로 브랜치하지 않고 80107E84 주소로 브랜치할 것입니다.

NSR:80107E6C|ret_to_user_from_irq:        ldr     r2,[r9,#0x8]

NSR:80107E70|                             cmp     r2,#0x7F000000   ; r2,#2130706432

NSR:80107E74|                             blne    0x8010B5FC       ; addr_limit_check_failed

NSR:80107E78|                             ldr     r1,[r9]

NSR:80107E7C|                             tst     r1,#0x0F         ; r1,#15

NSR:80107E80|                             bne     0x80107E48       ; slow_work_pending

NSR:80107E84|no_work_pending:_____________bl______0x801E9CE8_______;_trace_hardirqs_on

- 시스템 콜은 누가 언제 실행할까요?


시스템 콜은 유저 모드에서 실행 중인 어플리케이션에서 커널에게 어떤 서비스를 요청할 때 실행합니다. 유저 어플리케이션에서 파일 시스템에 접근해서 파일을 읽고 쓰거나 PID와 같은 프로세스 정보를 얻으려 할 때 주어진 규약에 맞게 커널에 서비스를 요청을 하는 것입니다. 이를 위해 시스템 콜을 발생해서 유저 공간에서 커널 공간으로 실행 흐름을 이동합니다.


이 동작은 다음 그림으로 표현할 수 있습니다.



이번에 시스템 콜 세부 동작을 왜 잘 알아야 하는지 생각해봅시다.

시스템 콜은 리눅스 시스템에서 당연히 잘 동작하는데 왜 알아야 할까요? 그 이유는 문제 해결 능력을 키우기 위해서입니다. 리눅스 시스템 저수준 함수를 써서 응용 어플리케이션 코드는 누구나 작성할 수 있습니다. 하지만 시스템 콜이 유저 공간에서 커널 공간까지 어떤 흐름으로 동작하는지 모르면 어디부터 문제 원인을 분석해야 할지 알 수 없습니다.


 시스템 콜이 어떤 흐름으로 동작하는지 잘 모르고 매뉴얼에 있는 내용만 참고해서 코드 작성하는 분보다 시스템 콜 전체 흐름을 제대로 이해한 분이 더 안정적인 코드를 작성할 가능성이 높습니다. 특정 리눅스 시스템 함수를 호출했는데 갑자기 에러 코드를 음수로 반환한다고 가정합시다. 시스템 인터페이스 구조를 알면 어느 코드부터 분석을 시작할지 판단할 수 있습니다.


리눅스에서는 실행 공간을 메모리 접근과 실행 권한에 따라 유저 공간과 커널 공간으로 분류합니다. 


먼저 커널 공간이 무엇인지 알아봅시다. 

커널 코드가 실행할 때는 모든 커널 함수 호출이 가능하며 제약 없이 메모리 공간에 접근해서 하드웨어를 제어할 수 있습니다. 이런 시스템 상태와 메모리 접근을 커널 공간이라고 부릅니다. 


다음은 유저 공간을 소개하겠습니다. 유저 어플리케이션 코드가 구동하는 동작과 상태를 유저 공간이라고 합니다. 유저 어플리케이션은 유저 공간에서 실행하며 메모리 공간 접근에 제한이 있고 하드웨어에 직접 접근할 수 없습니다. 


     

유저 어플리케이션에서 권한이 없는 메모리 공간에 접근하면 커널은 오류를 감지해서 해당 프로세스를 종료시킵니다.



다음 소절에 이어 시스템 콜 전체 흐름도와 동작에 대해서 살펴보겠습니다.


- 시스템 콜(시스템 호출)은 왜 필요할까?


시스템 콜은 유저 모드에서 커널 모드로 진입하는 동작입니다. 다른 관점으로 시스템 콜은 유저 공간과 커널 공간 사이 가상 계층이자 인터페이스라고 볼 수도 있습니다. 이 계층은 다음과 같은 특징이 있습니다.

1. 시스템 안정성과 보안을 지킬 수 있습니다. 유저모드에서 어플리케이션이 커널 공간에 아무런 제약없이 접근한다고 가정합시다. 실수로 어플리케이션이 커널 코드 영역 메모리를 오염을 시키면 시스템은 오동작할 가능성이 높습니다.


2. 유저 어플리케이션에서 추상화된 하드웨어 인터페이스를 제공합니다. 유저 모드에서 구동 중안 어플리케이션 입장에서 하나의 파일 시스템 위에서 구동 중인 것으로 착각하게 합니다.


3. 시스템 콜 구현으로 유저 어플리케이션의 호환성과 이식성을 보장할 수 있습니다. 리눅스 시스템은 시스템 콜 인터페이스는 POSIX(Portable Operating System Interface) 이란 유닉스 표준 규약에 맞게 구현되어 있기 때문입니다. 이로 유저 어플리케이션 코드를 라즈베리파이, 안드로이드 등 리눅스 계열의 시스템과 유닉스 운영체제에서도 구동할 수 있습니다.


4. 유저 공간에서 실행하는 어플리케이션에서 커널 공간으로 진입하는 인터페이스를 두고 커널과 독립적으로 구동합니다. 유저 어플리케이션 입장에서 파일 시스템과 프로세스 생성과 같은 내부 동작에 신경 쓸 필요가 없습니다.


리눅스 디바이스 드라이버와 가상 파일 시스템 함수도 시스템 콜을 통해 시스템 콜 핸들러를 통해 관련 코드를 실행합니다.  


또한 시스템 콜은 ARM 아키텍처와 연관이 깊은 동작입니다. ARM 프로세서는 시스템 콜을 익셉션의 한 종류인 소프트웨어 인터럽트로 실행하기 때문입니다. ARM 프로세스 관점으로 시스템 콜을 어떻게 처리하는지 알아볼 필요가 있습니다.


- 시스템 콜 전체 흐름도 소개


이전에 소개한 시스템 콜 흐름도와 시스템 콜 동작은 그리 간단하지 않습니다. 시스템 콜 세부 동작을 알려면 다음 시스템 전체 흐름도를 이해해야 합니다.


다음 그림은 이번에 다룰 전체 시스템 콜 흐름도입니다.




open(), write() 그리고 read() 함수는 파일을 열고 읽어서 쓰는 파일 입출력 동작이고, fork()와 exit() 함수는 프로세스 생성과 종료와 연관된 동작을 실행합니다. 이를 리눅스 저수준 함수라고 부릅니다. 다른 관점으로 GNU C 라이브러리로 진입하는 함수이며 이를 API(Application Programming Interface) 라고 부릅니다.


리눅스 시스템에서는 390여 개의 표준 함수들이 있는데 위 그림에서 대표적인 함수 5개를 표현한 것입니다.


라즈베리파이에서 다음 파일을 열어보면 시스템 콜 번호를 확인할 수 있습니다.

[/usr/include/arm-linux-gnueabihf/asm/unistd.h]

#define __NR_restart_syscall (__NR_SYSCALL_BASE+  0)

#define __NR_exit (__NR_SYSCALL_BASE+  1)

#define __NR_fork (__NR_SYSCALL_BASE+  2)

...

#define __NR_pkey_mprotect (__NR_SYSCALL_BASE+394)

#define __NR_pkey_alloc (__NR_SYSCALL_BASE+395)

#define __NR_pkey_free (__NR_SYSCALL_BASE+396)


시스템 콜을 제대로 이해하려면 시스템 콜을 발생하는 유저 공간부터 시스템 콜을 실행하는 커널 공간 계층까지 전체 흐름도를 살펴볼 필요가 있습니다.


시스템 콜 실행 흐름은 4단계로 나눌 수 있습니다.


1 단계: 리눅스 저수준 표준 함수 호출

유저 어플리케이션에서 파일시스템에 접근해서 파일을 열고 읽고 쓰려고 할 때 open(), write(), read() 함수를 호출해야 합니다. 혹은 프로세스를 생성하거나 종료할 때 fork() 나 exit() 함수를 호출합니다. 이 함수들은 API(Application Programming Interface)라고 말합니다. 유저 어플리케이션에서 리눅스 커널에서 제공하는 기능을 쓰기 위해 만든 인터페이스를 의미합니다. 이 인터페이스는 모두 리눅스 시스템에서 제공하는 GNU C 라이브러리 내부에 구현돼 있습니다.


2 단계: 유저 공간에서 시스템 콜 실행

리눅스 시스템 저수준 함수를 호출하면 리눅스 시스템에서 제공하는 GNU C 라이브러리 내 코드가 실행합니다. 라이브러리 내부 ARM 어셈블리 코드 실행으로 시스템 콜을 발생합니다. 이 과정을 제대로 이해하려면 ARM에서 시스템 콜을 어떻게 처리하는지 살펴볼 필요가 있습니다.


3 단계: 커널 공간에서 시스템 콜 실행

시스템 콜이 실행하면 커널 공간으로 이동해서 시스템 테이블에 접근한 후 각 리눅스 저수준 함수(API) 종류별로 대응하는 시스템 콜 핸들러 함수로 분기합니다. sys_open(), sys_write() 그리고 sys_read() 함수들은 가상 파일 시스템을 통해 파일 시스템에 접근합니다. sys_clone() 그리고 sys_exit() 함수들은 프로세스 생성과 종료와 연관된 커널 드라이버에 있는 계층에 접근합니다.

시스템 콜 핸들러 함수는 리눅스 저수준 함수 앞에 sys_ 접두사가 붙는 경우가 대부분입니다. write() 함수는 sys_write() 함수, read() 함수는 sys_read() 함수에 대응합니다. 하지만 모든 시스템 콜 핸들러 함수가 이 규칙을 따르지는 않습니다. 리눅스 저수준 함수 fork()는 sys_clone() 시스템 콜 핸들러가 실행합니다.


4단계: 커널 공간에서 시스템 콜 핸들러 실행

시스템 콜 핸들러에서는 유저 공간에서 전달한 매개 인자에 오류를 점검 후 시스템 콜 종류에 따라 가상 파일 시스템 계층이나 프로세스 관리 함수에 접근합니다.


시스템 콜 핸들러에서는 유저 공간에서 전달한 매개 인자에 오류를 점검 후 시스템 콜 종류에 따라 가상 파일 시스템 계층이나 프로세스 관리 함수에 접근합니다.


여기까지 유저 공간에서 커널 공간까지 시스템 콜 처리 과정입니다.


시스템 콜 인터페이스 동작을 더 정확하게 이해하려면 ARM 프로세스에서 시스템 콜을 어떻게 처리하는지 알아야 합니다. 이 내용은 다음에 다룹니다.

유저 프로세스 입장에서 시그널이란 


시그널이란 무엇일까요?

커널 입장에서 시그널은 프로세스에게 보내는 단순한 형태의 메시지라고 할 수 있습니다.

시그널 정보와 PID를 프로세스에게 전달하는 것입니다.


유저 프로세스 입장에서 프로세스는 무엇일까요? 유저 프로세스 관점으로 시그널은 실행 흐름을 제어하는 비동기적인 중단입니다. 이렇게 유저 프로세스와 커널 입장에서 시그널은 약간 다른 관점에서 볼 수 있습니다.


이번에 먼저 유저 프로세스 관점으로 시그널을 살펴보겠습니다.

여러분이 너무 보고 싶은 책이 있다고 가정하겠습니다. 

3시간 동안 읽을 수 있는 책 분량이라 주말에 책을 읽기 시작했습니다. 3시간 동안 아무런 방해를 받지 않고 책을 읽을 수 있으면 좋겠지만 이런 상황은 이상적인 환경입니다. 집에서 인터폰 벨리 울리던가 전화가 온다던가 여러 종류 중단이 발생 수 있기 때문입니다.


이런 중단은 예상하지 않았던 상황에서 발생하며 소프트웨어에서는 비동기적인 이벤트라고도 말합니다.


인터폰이 울리거나 회사나 친구한테 전화가 오면 우리는 보통 적절한 대응을 합니다. 보통 전화를 받거나 인터폰을 받고 대화를 합니다. 만약 여러분이 임베디드 리눅스 개발자인데 주말에 회사에서 전화가 왔다면 어떻게 할까요? 대부분 전화를 받을 것입니다. 시급한 문제가 생겼을 때 회사에서 개발자에게 전화를 하기 때문입니다. 하지만 가끔 중요하지 않은 다른 전화(광고, 부동산 투자)가 오면 전화를 안 받을 수도 있습니다.


프로세스도 마찬가지입니다. 유저 레벨 프로세스 기준으로 우리가 책을 읽는 것과 마찬가지로 정해진 시나리오에 따라 어떤 작업을 수행한다고 가정합시다. 책을 끝가지 방해 받지 않고 읽었으면 좋겠으나 유저 레벨 프로세스도 마찬가지로 예상치 못한(비동기적인) 중단으로 작업 흐름이 끊어 질 수 있습니다.


이렇게 인터폰이 울리거나 전화가 오는 것과 같이 유저 프로세스도 일을 하다가 비동기적인 중단을 겪을 수 있습니다. 이를 리눅스에서는 시그널이라고 하며 유저 프로세스는 시그널에 대해 이미 정해진 처리를 해줘야 합니다.


이런 유형의 다른 대표적인 중단은 인터럽트를 들 수 있습니다. 유저 프로세스 입장에서 시그널도 예상치 않았던 비동기적인 이벤트라고 볼 수 있습니다. 


대표적인 비동기적인 이벤트로 시그널이 발생하는 상황을 생각해봅시다.

1.리눅스 터미널에서 Ctl+C 키를 눌러서 프로세스를 종료

2.리눅스 터미널에서 다음 커맨드로 프로세스를 강제 종료

kill -9 [PID]

3.리눅스 커널에서 특정 조건에서 해당 프로세스를 종료


이렇게 언제 발생할지 모르는 비동기적인 중단(이벤트)에 대해 적절한 처리를 해줘야 합니다.


리눅스 커널에서도 자체적으로 시그널을 발생할 수 있습니다. 한 가지 예로 OOM(Out-of-memory) Killer를 들 수 있습니다. 잔여 메모리가 매우 부족할 때 OOM Killer 모듈은 프로세스를 강제 종료시켜서 메모리를 확보합니다. 종료할 프로세스에게 시그널을 전달합니다. 


안드로이드 시스템에서 OOM Killer가 실행하기 전 메모리 부족을 방지하기 위해 Lowmemory Killer란 모듈을 실행합니다. OOM Killer와 마찬가지로 프로세스를 종료시켜서 메모리를 확보합니다. 이 때도 종료할 프로세스에게 시그널을 전달합니다. 이 내용은 다음 소절에서 자세히 다룹니다.


시그널 번호와 동작 알아보기


책을 읽다가 발생하는 여러 비동기적인 이벤트(인터폰, 전화)가 있듯이, 유저 레벨 프로세스 동작 중에 발생할 수 있는 시그널도 여러 가지가 있습니다. 유닉스나 리눅스 커널 버전이 달라도 시그널 종류는 비슷합니다. 시그널은 POSIX 규약으로 정의된 표준이며 이제 맞게 리눅스 시스템 개발자가 구현하기 때문입니다. 다음은 라즈베리파이 리눅스 커널 4.14.70 버전에서 지원하는 시그널 번호를 확인한 결과입니다.

pi@raspberrypi:~ $ kill -l

 1) SIGHUP 2) SIGINT 3) SIGQUIT 4) SIGILL 5) SIGTRAP

 6) SIGABRT 7) SIGBUS 8) SIGFPE 9) SIGKILL 10) SIGUSR1

11) SIGSEGV 12) SIGUSR2 13) SIGPIPE 14) SIGALRM 15) SIGTERM

16) SIGSTKFLT 17) SIGCHLD 18) SIGCONT 19) SIGSTOP 20) SIGTSTP

21) SIGTTIN 22) SIGTTOU 23) SIGURG 24) SIGXCPU 25) SIGXFSZ

26) SIGVTALRM 27) SIGPROF 28) SIGWINCH 29) SIGIO 30) SIGPWR

31) SIGSYS 34) SIGRTMIN 35) SIGRTMIN+1 36) SIGRTMIN+2 37) SIGRTMIN+3

38) SIGRTMIN+4 39) SIGRTMIN+5 40) SIGRTMIN+6 41) SIGRTMIN+7 42) SIGRTMIN+8

43) SIGRTMIN+9 44) SIGRTMIN+10 45) SIGRTMIN+11 46) SIGRTMIN+12 47) SIGRTMIN+13

48) SIGRTMIN+14 49) SIGRTMIN+15 50) SIGRTMAX-14 51) SIGRTMAX-13 52) SIGRTMAX-12

53) SIGRTMAX-11 54) SIGRTMAX-10 55) SIGRTMAX-9 56) SIGRTMAX-8 57) SIGRTMAX-7

58) SIGRTMAX-6 59) SIGRTMAX-5 60) SIGRTMAX-4 61) SIGRTMAX-3 62) SIGRTMAX-2

63) SIGRTMAX-1 64) SIGRTMAX


시그널은 POSIX(Portable Operating System Interface) 규약에 정한 표준입니다. 어플리케이션 이식성을 높이기 위한 시도로 어플리케이션이 다양한 유닉스 계열 운영체제에서 구동할 수 있게 정한 것입니다. 리눅스 시스템 개발자들은 POSIX 규약에 따라 시스템 코드를 설계하고 코드를 구현합니다. 


1~34번까지는 유닉스 계열 운영체제(리눅스 포함)에서 같은 시그널 종류와 번호를 확인할 수 있습니다. 이를 정규 시그널이라고도 말합니다. 대신 35~63 시그널은 리얼 타임 시그널입니다.


정규 시그널과 리얼 타임 시그널의 차이점은 무엇일까요? 가장 큰 차이는 시그널 큐 처리 방식입니다. 정규 시그널은 같은 종류의 시그널을 연달아 보내면 프로세스는 한 가지 시그널만 받아 처리하지만 리얼 타임 시그널은 모듀 큐에 쌓아서 처리를 합니다.


각각 시그널은 int 형 정수로 선언되어 있는데 라즈베리파이에서 다음 해더 파일에서 시그널 종류별 int형 정수 번호를 확인할 수 있습니다.

root@raspberrypi:/usr/include # cat arm-linux-gnueabihf/asm/signal.h

#define SIGHUP          1

#define SIGINT           2

#define SIGQUIT         3

#define SIGILL            4

#define SIGTRAP         5

#define SIGABRT         6

#define SIGIOT           6

#define SIGBUS          7

#define SIGFPE           8

#define SIGKILL          9

#define SIGUSR1        10

#define SIGSEGV        11


유저 어플리케이션에서 시그널을 처리하는 함수를 작성하면 위와 같이 각 시그널 종류 별로 정의된 정수 값으로 시그널을 처리합니다.


유저 공간에서 정의된 시그널 번호는 리눅스 커널에서도 같은 번호로 관리합니다. 

[https://elixir.bootlin.com/linux/v4.14.70/source/arch/arm/include/uapi/asm/signal.h]

#define SIGHUP 1

#define SIGINT 2

#define SIGQUIT 3

#define SIGILL 4

#define SIGTRAP 5

#define SIGABRT 6

#define SIGIOT 6

#define SIGBUS 7

#define SIGFPE 8

#define SIGKILL 9

#define SIGUSR1 10

#define SIGSEGV 11


32개 시그널 중 자주 활용하는 시그널을 정리하면 다음과 같습니다.

시그널 동작

SIGHUP 프로세스 제어 터미널이 종료될 때 세션 리더에게 전달, 터미널을 읽어버렸을때 발생

SIGINT 터미널 인터럽트 신호로(Ctl+C)키나 DELETE 키를 입력했을때 발생

SIGQUIT 사용자가 종료 문자(Ctl-\) 실행

SIGILL 유저가 유효하지 않은 명령어 실행 시도

SIGTRAP 트레이스 혹은 브레이크 포인트 실행

SIGABRT 프로세스가 비정상적인 종료 시중단 신호로 abort()에서 보냄

SIGIOT 비동기적인 I/O 이벤트 처리 시 보냄

SIGBUS 유효하지 않은 메모리 공간에 접근하거나 하드웨어 장애를 일으킬 때 커널이 생성

SIGFPE 부동 소수점을 연산 도중 오버플로우나 언더플로우가 발생하면 익셉션으로 발생하는 시그널

SIGKILL kill() 함수를 호출하면 프로세스를 종료시킴

SIGUSR1

SIGUSR2 유저 공간에서 처리하기 위해 정의하며 커널은 이 시그널을 쓰지 않음

SIGSEGV 유효하지 않은 메모리 접근을 시도할 때 커널이 해당 프로세스에 전달함

읽기나 쓰기 권한이 없는 메모리 공간에 접근하거나 실행할 수 없는 코드를 실행할 때 발생함

SIGUSR2 유저 공간에서 처리하기 위해 정의하며 커널은 이 시그널을 쓰지 않음

SIGPIPE 닫힌 파이프에 열고 쓸 때 실행

SIGALRM alarm() 함수가 자신을 실행한 프로세스에게 전달

SIGCHLD 프로세스가 종료할 때 커널은 해당 프로세스의 부모 프로세스에게 전달


유저 레벨 프로세스가 리눅스 저수준 표준 함수를 호출해서 시그널을 발생할 수 있습니다. 또한 어떤 프로세스가 종료할 때 부모 프로세스에게 자식 프로세스가 종료한다는 정보를 SIGCHLD 시그널로 알립니다.


만약 특정한 프로세스에게 시그널을 전달하고 싶을 때 어떻게 하면 될까요? 리눅스 터미널에서 kill 명령어를 쓰면 됩니다.


라즈베리파이에서 X-Terminal을 2개 열고 다음 명령어를 입력합시다.

1 root@raspberrypi:/usr/include # ps -ely | grep bash

2 S 1000 500 432 0 80 0 4096 1645 poll_s tty1 00:00:00 bash

3 S 1000 1150 1146 0 80 0 4192 1628 wait pts / 0 00:00:00 bash

4 S 0 1355 1350 0 80 0 3376 1433 wait pts / 0 00:00:00 bash

5 S 1000 1386 1146 0 80 0 3964 1628 poll_s pts / 1 00:00:00 bash

6 root@raspberrypi:# kill -SIGKILL 1386


위에서 5번 출력 결과를 보면 가장 마지막에 실행된 bash 프로세스의 PID가 1386이니 위와 같이 kill 명령어에 -SIGKILL 옵션을 줘서 실행하니 프로세스는 강제 종료합니다.



라즈베리파이 리눅스 시스템에서 kill 명령어 메뉴얼을 확인하면 다음과 같습니다.

root@raspberrypi:/home/pi# info kill

Up: Process control


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.


kill은 프로세스에게 시그널을 전달하는 명령어인데 대부분 프로세스를 종료하거나

시그널 종류에 따라 정해진 동작을 처리한다는 사실을 알 수 있습니다.


커널에서 시그널은 어떻게 처리할까? 


리눅스 커널 입장에서 시그널은 프로세스 간 통신을 위한 간단한 인터페이스입니다. 커널은 상황에 따라 시그널을 생성하고 전달해주는 역할을 수행합니다.


리눅스 커널에서 시그널에 대한 처리는 2단계로 나눌 수 있습니다.


1> 시그널 생성

유저 공간에서 시그널을 설정하면 커널은 해당 프로세스의 태스크 디스크립터에 시그널 정보를 써줍니다. 시그널을 받을 프로세스 스택 최상단 주소에 있는 struct thread_info flags 멤버에 _TIF_SIGPENDING 매크로를 써 줍니다. 시그널을 받을 프로세스에게 누군가 시그널을 생성했고 해당 시그널이 전달될 것이라고 알려주는 것입니다. 이후 시그널을 받을 프로세스를 깨웁니다.


2> 시그널 처리

시그널을 받을 프로세스가 시스템 콜이나 인터럽트 처리를 마무리한 이 후 시그널을 처리합니다.


커널은 시그널 종류에 따라 유저 프로세스가 정해진 동작을 수행하도록 다음 동작을 합니다.

 - 시그널 핸들러를 설정 안했을 경우

   : SIGINT, SIGKILL 시그널인 경우 프로세스를 종료시킵니다.

 - 시그널 핸들러를 설정했을 경우

   :  시그널 핸들러 주소를 ARM 프로그램 카운터 정보에 써줘서 시그널 핸들러를 실행시킵니다.


커널은 시그널 핸들러를 실행시켜 줄 뿐 시그널 종류에 따라 세부적인 처리를 할 수가 없습니다. 프로세스에게 전달하는 정보는 시그널 번호가 전부이며 표준 시그널에는 인자나 메시지 또는 그외 정보를 전달할 수 없습니다.


커널은 시그널을 대부분 프로세스를 종료할 때 프로세스나 스레드 그룹에 전달하는 메시지 형태로 사용합니다.


시그널을 발생했으나 아직 전달되지 않은 시그널을 펜딩 중인 시그널(pending signal)이라고 합니다. 특정 타입의 펜딩 시그널은 프로세스당 항상 하나만 존재합니다. 같은 시그널을 동일한 프로세스에게 전달하면 시그널 큐에서 대기하는 것이 아니라 그냥 폐기됩니다. 

기본 유저 레벨 프로세스 실행 실습 및 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
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() 커널 함수가 호출된다는 점을 확인했습니다.

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



+ Recent posts