Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

96199
1107
135824


[리눅스커널] 가상파일시스템/디버깅: 파일 객체 함수 오퍼레이션 확인하기(2) 13. 가상 파일 시스템

ftrace 로그 분석해보기

분석할 ftrace 로그는 다음과 같습니다.
#open
01 vfs_file_proc-2102 [001] .... 3993.231746: sys_enter: NR 5 (76fe7ed8, 80000, 3, 76ffac90, 76fe7ed8, 7edfa524)
02 vfs_file_proc-2102 [001] .... 3993.231764: ext4_file_open+0x14/0x1dc <-do_dentry_open+0x240/0x3c4
03 vfs_file_proc-2102 [001] .... 3993.231798: <stack trace>
04 => ext4_file_open+0x18/0x1dc
05 => do_dentry_open+0x240/0x3c4
06 => vfs_open+0x3c/0x40
07 => path_openat+0x3a8/0x1000
08 => do_filp_open+0x84/0xf0
09 => do_sys_open+0x144/0x1f4
10 => sys_open+0x28/0x2c
11 => __sys_trace_return+0x0/0x10
12 => 0x7edfa434
13 vfs_file_proc-2102  [001] ....  3993.231809: sys_exit: NR 5 = 3
...
#read 
14 vfs_file_proc-2102 [001] .... 3993.231946: sys_enter: NR 3 (3, 7edfa080, 200, 0, 76ff7000, 0)
15 vfs_file_proc-2102 [001] .... 3993.231952: ext4_file_read_iter+0x10/0x54 <-__vfs_read+0x108/0x168
16 vfs_file_proc-2102 [001] .... 3993.231969: <stack trace>
17 => ext4_file_read_iter+0x14/0x54
18 => __vfs_read+0x108/0x168
19 => vfs_read+0x9c/0x164
20 => ksys_read+0x5c/0xbc
21 => sys_read+0x18/0x1c
22 => __sys_trace_return+0x0/0x10
23 => 0x7edf9fdc
24 vfs_file_proc-2102  [001] ....  3993.231977: sys_exit: NR 3 = 512
...
#write(x1)
25 vfs_file_proc-2102 [001] .... 3993.234630: sys_enter: NR 4 (3, 7edfa4a8, 10, 7edfa4a8, 1077c, 0)
26 vfs_file_proc-2102 [001] .... 3993.234636: ext4_file_write_iter+0x14/0x4c0 <-__vfs_write+0x10c/0x170
27 vfs_file_proc-2102 [001] .... 3993.234654: <stack trace>
28 => ext4_file_write_iter+0x18/0x4c0
29 => __vfs_write+0x10c/0x170
30 => vfs_write+0xb4/0x1c0
31 => ksys_write+0x5c/0xbc
32 => sys_write+0x18/0x1c
33 => __sys_trace_return+0x0/0x10
34 => 0x7edfa4a4
35 vfs_file_proc-2102 [001] .... 3993.234796: sys_exit: NR 4 = 16
...
#lseek
36 vfs_file_proc-2102 [001] .... 3993.234803: sys_enter: NR 19 (3, 0, 0, 7edfa4a8, 1077c, 0)
37 vfs_file_proc-2102 [001] .... 3993.234807: ext4_llseek+0x14/0x15c <-ksys_lseek+0xa8/0xd8
38 vfs_file_proc-2102 [001] .... 3993.234821: <stack trace>
39 => ext4_llseek+0x18/0x15c
40 => ksys_lseek+0xa8/0xd8
41 => sys_lseek+0x18/0x1c
42 => __sys_trace_return+0x0/0x10
43 => 0x7edfa4a4
44 vfs_file_proc-2102  [001] .... 3993.234825: sys_exit: NR 19 = 0
...
#write(x2)
45 vfs_file_proc-2102 [001] .... 3993.235673: sys_enter: NR 4 (3, 7edfa4a8, 10, 7edfa4a8, 1077c, 0)
46 vfs_file_proc-2102 [001] .... 3993.235677: ext4_file_write_iter+0x14/0x4c0 <-__vfs_write+0x10c/0x170
47 vfs_file_proc-2102 [001] .... 3993.235702: <stack trace>
48 => ext4_file_write_iter+0x18/0x4c0
49 => __vfs_write+0x10c/0x170
50 => vfs_write+0xb4/0x1c0
51 => ksys_write+0x5c/0xbc
52 => sys_write+0x18/0x1c
53 => __sys_trace_return+0x0/0x10
54 => 0x7edfa4a4
55 vfs_file_proc-2102 [001] .... 3993.235757: sys_exit: NR 4 = 16
...
#fsync 
56 vfs_file_proc-2102 [001] .... 3993.235767: sys_enter: NR 118 (3, 7edfa4a8, 10, 7edfa4a8, 1077c, 0)
57 vfs_file_proc-2102 [001] .... 3993.235770: ext4_sync_file+0x14/0x464 <-vfs_fsync_range+0x4c/0x8c
58 vfs_file_proc-2102 [001] .... 3993.235796: <stack trace>
59 => ext4_sync_file+0x18/0x464
60 => vfs_fsync_range+0x4c/0x8c
61 => do_fsync+0x4c/0x74
62 => sys_fsync+0x1c/0x20
63 => __sys_trace_return+0x0/0x10
64 => 0x7edfa4a4
... 
65 vfs_file_proc-2102 [001] .... 3993.247132: sys_exit: NR 118 = 0 
...
#close
66 vfs_file_proc-2102 [001] .... 3993.247156: sys_enter: NR 6 (3, 7edfa4a8, 10, 0, 1077c, 0)
67 vfs_file_proc-2102 [001] .... 3993.247162: __close_fd+0x10/0xa0 <-sys_close+0x30/0x58
68 vfs_file_proc-2102 [001] .... 3993.247197: <stack trace>
69 => __close_fd+0x14/0xa0
70 => sys_close+0x30/0x58
71 => __sys_trace_return+0x0/0x10
72 => 0x7edfa4a4
73 vfs_file_proc-2102  [001] ....  3993.247203: sys_exit: NR 6 = 0

위에서 소개한 ftrace 실행 흐름은 다음 그림과 같이 분류할 수 있습니다.
 
[그림 13.18] ftrace에서 시스템 콜 실행 순서

먼저 그림 왼쪽 부분을 눈으로 따라가봅시다. 유저 공간 어플리케이션에서 실행한 함수 이름입니다. 이번 소절에서 소개한 어플리케이션 예제 코드에서 호출된 함수입니다. 다음 가운데 부분을 보면 시스템콜이란 화살표가 보입니다. 유저 공간에서 커널 공간으로 진입하려면 이렇게 시스템 콜을 발생해야 합니다. 

이번에 오른쪽 화면 오른쪽 함수 목록을 보면 첫 번째 함수는 시스템 콜 핸들러 함수입니다. 다음 그 아래에 있는 함수는 파일시스템별 함수 오퍼레이션을 수행합니다. 예를 들어 유저 공간에서 open 시스템 콜을 발생하면 시스템 콜 핸들러는 sys_open() 함수이고 open() 함수에 대한 파일 객체 함수 오퍼레이션은 do_dentry_open() 함수에서 실행합니다.  

이번 소절에서 읽고 쓰기를 하는 파일은 /home/pi/sample_text.text입니다. 라즈비안에서 저장매체에 저장하는 파일은 ext4 파일 시스템에서 관리합니다. 따라서 ext4_xxx와 ext4 시작되는 함수들이 호출됩니다

만약 proc 파일시스템에서 관리하는 파일을 읽기 쓰기 연산을 하면 proc_xxx으로 시작하는 함수들이 호출될 것입니다.

open 파일 오퍼레이션 동작 함수 흐름 확인하기  

파일을 읽기 쓰기 위해서 먼저 파일을 먼저 열어야 합니다. 이를 위해 유저 공간에서 오픈이란 함수를 호출 해야 합니다. 유저 공간에서 open() 함수를 호출하면 커널 공간에서 시스템 콜 핸들러인 sys_open() 함수가 호출됩니다. 이점을 염두하면서 다음 ftrace 로그를 분석합시다.

분석할 ftrace 메시지는 다음과 같습니다.
#open
01 vfs_file_proc-2102 [001] .... 3993.231746: sys_enter: NR 5 (76fe7ed8, 80000, 3, 76ffac90, 76fe7ed8, 7edfa524)
02 vfs_file_proc-2102 [001] .... 3993.231764: ext4_file_open+0x14/0x1dc <-do_dentry_open+0x240/0x3c4
03 vfs_file_proc-2102 [001] .... 3993.231798: <stack trace>
04 => ext4_file_open+0x18/0x1dc
05 => do_dentry_open+0x240/0x3c4
06 => vfs_open+0x3c/0x40
07 => path_openat+0x3a8/0x1000
08 => do_filp_open+0x84/0xf0
09 => do_sys_open+0x144/0x1f4
10 => sys_open+0x28/0x2c
11 => __sys_trace_return+0x0/0x10
12 => 0x7edfa434
13 vfs_file_proc-2102  [001] ....  3993.231809: sys_exit: NR 5 = 3

복잡해 보이는 ftrace 로그에서 함수 실행 흐름을 정리하면 다음 그림과 같습니다.
 
[그림 13.19] ftrace: 파일 오픈 시 open 함수 오퍼레이션 실행 흐름도

유저 공간에서 open() 오픈 함수를 호출하면 커널 공간에서 시스템 콜 핸들러인 sys_open() 함수가 호출되는 실행 흐름입니다. 이후 do_dentry_open() 함수가 호출되어 파일 객체 함수 오퍼레이션을 수행합니다.

01번째 줄 로그를 보겠습니다.
01 vfs_file_proc-2102 [001] .... 3993.231746: sys_enter: NR 5 (76fe7ed8, 80000, 3, 76ffac90, 76fe7ed8, 7edfa524)

5번 open 시스템 콜이 발생했다는 정보입니다. 5번 시스템 콜 번호는 다음 코드에서 확인할 수 있습니다.
[https://elixir.bootlin.com/linux/v4.4.180/source/arch/arm/include/uapi/asm/unistd.h]
#define __NR_open (__NR_SYSCALL_BASE+  5)

2~11번째 줄 로그에서 open 시스템 콜이 발생한 다음 ext4_file_open() 함수 콜스택을 볼 수 있습니다.

이어서 ext4_file_open() 함수를 호출하는 코드를 같이 볼까요?
[https://elixir.bootlin.com/linux/v4.19.30/source/source/fs/open.c]
01 static int do_dentry_open(struct file *f,
02   struct inode *inode,
03   int (*open)(struct inode *, struct file *))
04 {
05 static const struct file_operations empty_fops = {};
06 int error;
...
07 f->f_mode |= FMODE_LSEEK | FMODE_PREAD | FMODE_PWRITE;
08 if (!open)
09 open = f->f_op->open;
10 if (open) {
11 error = open(inode, f);
12 if (error)
13 goto cleanup_all;
14 }
...

do_dentry_open() 함수 09번째 줄에서 파일 오퍼레이션 중 open 함수 포인터를 open에 저장합니다. 이후 11번째 줄에서 ext4_file_open() 함수를 호출합니다.

read 파일 오퍼레이션 동작 함수 흐름 확인하기  

이어서 유저 공간에서 read() 함수를 호출했을 때 커널 내부 함수 실행 흐름을 살펴보겠습니다.

분석할 ftrace 메시지는 다음과 같습니다.
#read 
14 vfs_file_proc-2102 [001] .... 3993.231946: sys_enter: NR 3 (3, 7edfa080, 200, 0, 76ff7000, 0)
15 vfs_file_proc-2102 [001] .... 3993.231952: ext4_file_read_iter+0x10/0x54 <-__vfs_read+0x108/0x168
16 vfs_file_proc-2102 [001] .... 3993.231969: <stack trace>
17 => ext4_file_read_iter+0x14/0x54
18 => __vfs_read+0x108/0x168
19 => vfs_read+0x9c/0x164
20 => ksys_read+0x5c/0xbc
21 => sys_read+0x18/0x1c
22 => __sys_trace_return+0x0/0x10
23 => 0x7edf9fdc
24 vfs_file_proc-2102  [001] ....  3993.231977: sys_exit: NR 3 = 512

ftrace 로그에서 함수 실행 흐름은 다음 그림과 같습니다.
 
[그림 13.20] ftrace: 파일을 읽을 때 read 함수 오퍼레이션 실행 흐름도

유저 공간에서 read() 오픈 함수를 호출하면 커널 공간에서 시스템 콜 핸들러인 sys_read() 함수가 호출되는 실행 흐름입니다. 이후 __vfs_read() 함수가 호출되어 파일 객체 read 함수 오퍼레이션을 수행합니다.

14번째 줄 로그를 보겠습니다.
14 vfs_file_proc-2102 [001] .... 3993.231946: sys_enter: NR 3 (3, 7edfa080, 200, 0, 76ff7000, 0)

3번 read 시스템 콜이 발생했다는 정보입니다. 3번 시스템 콜 번호는 다음 코드에서 확인할 수 있습니다.
[https://elixir.bootlin.com/linux/v4.4.180/source/arch/arm/include/uapi/asm/unistd.h]
#define __NR_read (__NR_SYSCALL_BASE+  3)

15~23번째 줄 로그에서 read 시스템 콜이 발생한 다음 ext4_file_read_iter() 함수 콜스택을 볼 수 있습니다.

이어서 ext4_file_read_iter() 함수를 호출하는 코드를 같이 볼까요?
[https://elixir.bootlin.com/linux/v4.19.30/source/source/fs/open.c]
01 static ssize_t new_sync_read(struct file *filp, char __user *buf, size_t len, loff_t *ppos)
02 {
03 struct iovec iov = { .iov_base = buf, .iov_len = len };
04 struct kiocb kiocb;
05 struct iov_iter iter;
06 ssize_t ret;
07
08 init_sync_kiocb(&kiocb, filp);
09 kiocb.ki_pos = *ppos;
10 iov_iter_init(&iter, READ, &iov, 1, len);
11
12 ret = call_read_iter(filp, &kiocb, &iter);
...

new_sync_read() 함수 11번째 줄과 같이 call_read_iter() 함수에서 ext4_file_open() 함수를 호출합니다.

write 파일 오퍼레이션 동작 함수 흐름 확인하기  

이어서 유저 공간에서 write() 함수를 호출했을 때 커널 내부 함수 실행 흐름을 살펴보겠습니다.

분석할 ftrace 메시지는 다음과 같습니다.
#write(x1)
25 vfs_file_proc-2102 [001] .... 3993.234630: sys_enter: NR 4 (3, 7edfa4a8, 10, 7edfa4a8, 1077c, 0)
26 vfs_file_proc-2102 [001] .... 3993.234636: ext4_file_write_iter+0x14/0x4c0 <-__vfs_write+0x10c/0x170
27 vfs_file_proc-2102 [001] .... 3993.234654: <stack trace>
28 => ext4_file_write_iter+0x18/0x4c0
29 => __vfs_write+0x10c/0x170
30 => vfs_write+0xb4/0x1c0
31 => ksys_write+0x5c/0xbc
32 => sys_write+0x18/0x1c
33 => __sys_trace_return+0x0/0x10
34 => 0x7edfa4a4
35 vfs_file_proc-2102 [001] .... 3993.234796: sys_exit: NR 4 = 16

ftrace 로그에서 함수 실행 흐름은 다음 그림과 같습니다.
 
[그림 13.21] ftrace: 파일을 쓸 때 write 함수 오퍼레이션 실행 흐름도

유저 공간에서 write() 오픈 함수를 호출하면 커널 공간에서 시스템 콜 핸들러인 sys_write() 함수가 호출되는 실행 흐름입니다. 이후 __vfs_write() 함수가 호출되어 파일 객체 write 함수 오퍼레이션을 수행합니다.

25번째 줄 로그를 보겠습니다.
25 vfs_file_proc-2102 [001] .... 3993.234630: sys_enter: NR 4 (3, 7edfa4a8, 10, 7edfa4a8, 1077c, 0)

4번 write 시스템 콜이 발생했다는 정보입니다. 4번 시스템 콜 번호는 다음 코드에서 확인할 수 있습니다.
[https://elixir.bootlin.com/linux/v4.4.180/source/arch/arm/include/uapi/asm/unistd.h]
#define __NR_write (__NR_SYSCALL_BASE+  4)

26~33번째 줄 로그에서 write 시스템 콜이 발생한 다음에 ext4_file_write_iter() 함수 콜스택을 볼 수 있습니다.

이어서 ext4_file_write_iter() 함수를 호출하는 코드를 같이 볼까요?
[https://elixir.bootlin.com/linux/v4.19.30/source/source/fs/read_write.c]
01 static ssize_t new_sync_write(struct file *filp, const char __user *buf, size_t len, loff_t *ppos)
02 {
03 struct iovec iov = { .iov_base = (void __user *)buf, .iov_len = len };
04 struct kiocb kiocb;
05 struct iov_iter iter;
06 ssize_t ret;
07
08 init_sync_kiocb(&kiocb, filp);
09 kiocb.ki_pos = *ppos;
10 iov_iter_init(&iter, WRITE, &iov, 1, len);
11
12 ret = call_write_iter(filp, &kiocb, &iter);
13 BUG_ON(ret == -EIOCBQUEUED);
14 if (ret > 0)
15 *ppos = kiocb.ki_pos;
16 return ret;
17 }

new_sync_write() 함수 12번째 줄과 같이 call_read_iter() 함수에서 ext4_file_write_iter() 함수를 호출합니다.

lseek 파일 오퍼레이션 동작 함수 흐름 확인하기 

유저 공간에서 파일을 읽고 쓰기 할 때 파일 포인터 위치를 바꿔야 할 때가 있습니다. 이럴 때 lseek() 함수를 호출하면 함수에 지정된 옵션에 따라 파일 포인터 위치를 반환합니다.

이번엔 파일 포인터 위치를 설정하기 위해 유저 공간에서 lseek() 함수를 호출할 때 커널 공간에서 함수 실행 흐름을 확인하겠습니다.

분석할 ftrace 메시지는 다음과 같습니다.
#lseek
36 vfs_file_proc-2102 [001] .... 3993.234803: sys_enter: NR 19 (3, 0, 0, 7edfa4a8, 1077c, 0)
37 vfs_file_proc-2102 [001] .... 3993.234807: ext4_llseek+0x14/0x15c <-ksys_lseek+0xa8/0xd8
38 vfs_file_proc-2102 [001] .... 3993.234821: <stack trace>
39 => ext4_llseek+0x18/0x15c
40 => ksys_lseek+0xa8/0xd8
41 => sys_lseek+0x18/0x1c
42 => __sys_trace_return+0x0/0x10
43 => 0x7edfa4a4
44 vfs_file_proc-2102  [001] .... 3993.234825: sys_exit: NR 19 = 0

ftrace 로그에서 함수 실행 흐름은 다음 그림과 같습니다.
 
 [그림 13.22] ftrace: 파일 포인터 위치를 설정할 때 lseek 함수 오퍼레이션 실행 흐름도

유저 공간에서 lseek() 오픈 함수를 호출하면 커널 공간에서 시스템 콜 핸들러인 sys_lseek() 함수가 호출되는 실행 흐름입니다. 이후 vfs_llseek() 함수가 호출되어 파일 객체 lseek 함수 오퍼레이션을 수행합니다.

36번째 줄 로그를 보겠습니다.
36 vfs_file_proc-2102 [001] .... 3993.234803: sys_enter: NR 19 (3, 0, 0, 7edfa4a8, 1077c, 0)

19번 write 시스템 콜이 발생했다는 정보입니다. 19번 시스템 콜 번호는 다음 코드에서 확인할 수 있습니다.
[https://elixir.bootlin.com/linux/v4.4.180/source/arch/arm/include/uapi/asm/unistd.h]
#define __NR_lseek (__NR_SYSCALL_BASE+ 19)

37~44번째 줄 로그에서 lseek 시스템 콜이 발생한 다음 ext4_llseek() 함수 콜스택을 볼 수 있습니다.

이어서 ext4_llseek() 함수를 호출하는 코드를 같이 볼까요?
[https://elixir.bootlin.com/linux/v4.19.30/source/source/fs/read_write.c]
01 loff_t vfs_llseek(struct file *file, loff_t offset, int whence)
02 {
03 loff_t (*fn)(struct file *, loff_t, int);
04
05 fn = no_llseek;
06 if (file->f_mode & FMODE_LSEEK) {
07 if (file->f_op->llseek)
08 fn = file->f_op->llseek;
09 }
10 return fn(file, offset, whence);
11 }
...

vfs_llseek() 함수 08번째 줄 코드에서 ext4_llseek() 함수를 호출합니다.

fsync 파일 오퍼레이션 동작 함수 흐름 확인하기  

어플리케이션에서 read()/write() 함수를 써서 파일을 변경하거나 저장합니다. 이 과정에서 커널 내부에서 버퍼를 잡아 변경된 파일을 처리합니다. 즉, 파일을 변경하면 그 내용이 바로 저장 매체에 저장되는 것은 아닙니다. 그래서 읽기 쓰기 동작 후 변경한 내용을 저장매체에 저장하려면 fsync() 함수를 호출해야 합니다. 이 점을 기억하고 다음 ftrace 로그를 분석합시다.

#fsync 
56 vfs_file_proc-2102 [001] .... 3993.235767: sys_enter: NR 118 (3, 7edfa4a8, 10, 7edfa4a8, 1077c, 0)
57 vfs_file_proc-2102 [001] .... 3993.235770: ext4_sync_file+0x14/0x464 <-vfs_fsync_range+0x4c/0x8c
58 vfs_file_proc-2102 [001] .... 3993.235796: <stack trace>
59 => ext4_sync_file+0x18/0x464
60 => vfs_fsync_range+0x4c/0x8c
61 => do_fsync+0x4c/0x74
62 => sys_fsync+0x1c/0x20
63 => __sys_trace_return+0x0/0x10
64 => 0x7edfa4a4
... 
65 vfs_file_proc-2102 [001] .... 3993.247132: sys_exit: NR 118 = 0

ftrace 로그에서 함수 실행 흐름은 다음 그림과 같습니다.
 
  [그림 13.23] ftrace: 파일 fsync 함수 오퍼레이션 실행 흐름도

유저 공간에서 fsync() 함수를 호출하면 커널 공간에서 시스템 콜 핸들러인 sys_fsync() 함수가 호출되는 실행 흐름입니다. 이후 vfs_fsync_range() 함수가 호출되어 파일 객체 fsync 함수 오퍼레이션을 수행합니다.

56번째 줄 로그를 보겠습니다.
56 vfs_file_proc-2102 [001] .... 3993.235767: sys_enter: NR 118 (3, 7edfa4a8, 10, 7edfa4a8, 1077c, 0)

118번 fsync 시스템 콜이 발생했다는 정보입니다. 118번 시스템 콜 번호는 다음 코드에서 확인할 수 있습니다.
[https://elixir.bootlin.com/linux/v4.4.180/source/arch/arm/include/uapi/asm/unistd.h]
#define __NR_fsync (__NR_SYSCALL_BASE+118)

57~64번째 줄 로그에서 fsync 시스템 콜이 발생한 다음 ext4_sync_file() 함수 콜스택을 볼 수 있습니다.

이어서 ext4_sync_file() 함수를 호출하는 코드를 같이 볼까요?
[https://elixir.bootlin.com/linux/v4.19.30/source/source/fs/sync.c]
01 int vfs_fsync_range(struct file *file, loff_t start, loff_t end, int datasync)
02 {
03 struct inode *inode = file->f_mapping->host;
04
05 if (!file->f_op->fsync)
06 return -EINVAL;
07 if (!datasync && (inode->i_state & I_DIRTY_TIME))
08 mark_inode_dirty_sync(inode);
09 return file->f_op->fsync(file, start, end, datasync);
10 }

vfs_fsync_range() 함수 09번째 줄 코드에서 ext4_sync_file() 함수를 호출합니다.

close 파일 오퍼레이션 동작 함수 흐름 확인하기 

마지막으로 유저 공간에서 파일을 닫을 때 close() 함수를 호출하면 커널 공간에서 어떤 함수가 실행되는지 살펴보겠습니다.
#close
66 vfs_file_proc-2102 [001] .... 3993.247156: sys_enter: NR 6 (3, 7edfa4a8, 10, 0, 1077c, 0)
67 vfs_file_proc-2102 [001] .... 3993.247162: __close_fd+0x10/0xa0 <-sys_close+0x30/0x58
68 vfs_file_proc-2102 [001] .... 3993.247197: <stack trace>
69 => __close_fd+0x14/0xa0
70 => sys_close+0x30/0x58
71 => __sys_trace_return+0x0/0x10
72 => 0x7edfa4a4
73 vfs_file_proc-2102  [001] ....  3993.247203: sys_exit: NR 6 = 0

ftrace 로그에서 함수 실행 흐름은 다음 그림과 같습니다.
 
[그림 13.24] ftrace: 파일을 닫을 때 close 함수 오퍼레이션 실행 흐름도

유저 공간에서 close() 함수를 호출하면 커널 공간에서 시스템 콜 핸들러인 sys_close() 함수가 호출되는 실행 흐름입니다. sys_close() 함수가 호출되면 커널 내부에서 파일시스템별 함수 오퍼레이션을 실행하지 않습니다. 단지 프로세스 태스크 디스크립터 내 파일 디스크립터 테이블에 저장된 파일 디스크립터를 지웁니다.

66번째 줄 로그를 보겠습니다.
66 vfs_file_proc-2102 [001] .... 3993.247156: sys_enter: NR 6 (3, 7edfa4a8, 10, 0, 1077c, 0)

6번 close 시스템 콜이 발생했다는 정보입니다. 6번 시스템 콜 번호는 다음 코드에서 확인할 수 있습니다.
[https://elixir.bootlin.com/linux/v4.4.180/source/arch/arm/include/uapi/asm/unistd.h]
#define __NR_close (__NR_SYSCALL_BASE+  6)

67~72번째 줄 로그에서 close 시스템 콜이 발생한 다음 __close_fd() 함수 콜스택을 볼 수 있습니다.

이어서 __close_fd() 함수를 같이 볼까요?
[https://elixir.bootlin.com/linux/v4.19.30/source/source/fs/file.c]
01 int __close_fd(struct files_struct *files, unsigned fd)
02 {
03 struct file *file;
04 struct fdtable *fdt;
05
06 spin_lock(&files->file_lock);
07 fdt = files_fdtable(files);
08 if (fd >= fdt->max_fds)
09 goto out_unlock;
10 file = fdt->fd[fd];
11 if (!file)
12 goto out_unlock;
13 rcu_assign_pointer(fdt->fd[fd], NULL);

__close_fd() 함수 13번째 줄 코드와 같이 파일 디스크립터 테이블에서 해당 파일 디스크립터를 초기화합니다.

여기까지 실습을 통해 커널 내부 함수 흐름을 ftrace로 살펴봤습니다.
실습으로 다음 내용을 알게 됐습니다.
각 시스템콜 별과 연계해 가상 파일시스템에서 관리하는 파일 객체 함수 오퍼레이션을 수행함 
함수 오퍼레이션은 함수 포인터를 써서 수행함 

다른 관점으로 보면 리눅스 디바이스 드라이버에서 지정한 함수 오퍼레이션(연산)도 이번 장에서 배운 파일 객체 함수 오퍼레이션 구조에서 실행됩니다. 이번 소절에서 실습한 내용을 응용해서 여러분이 작성한 디바이스 드라이버 함수 오퍼레이션 동작도 ftrace로 확인해 보시길 바랍니다.


"혹시 궁금한 점이 있으면 댓글로 질문 남겨주세요. 아는 한 성실히 답변 올려드리겠습니다!" 

Thanks,
Austin Kim(austindh.kim@gmail.com)


Reference(가상 파일시스템)

가상 파일시스템 소개
파일 객체
파일 객체 함수 오퍼레이션 동작
프로세스는 파일객체 자료구조를 어떻게 관리할까?
슈퍼블록 객체
아이노드 객체
덴트리 객체
가상 파일시스템 디버깅




핑백

덧글

댓글 입력 영역