使用strace探索tail -f的工作机制

Julia Evans 写了一篇文章，使用 strace 探索 killall 的工作机制. 我也依葫芦画瓢，尝试一下用 strace 探索一下 tail -f 的工作机制。

下面是执行 strace -yy -tt -o strace.log tail -f data.log 的输出结果。期间追加了两次内容。

18:52:38.300588 execve("/usr/bin/tail", ["tail", "-f", "data.log"], 0x7fffd96ca0f0 /* 24 vars */) = 0
18:52:38.308541 brk(NULL)               = 0x7fffdda86000
18:52:38.310225 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
18:52:38.311734 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
18:52:38.313166 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3</etc/ld.so.cache>
18:52:38.314902 fstat(3</etc/ld.so.cache>, {st_mode=S_IFREG|0644, st_size=62985, ...}) = 0
18:52:38.316373 mmap(NULL, 62985, PROT_READ, MAP_PRIVATE, 3</etc/ld.so.cache>, 0) = 0x7fda1db90000
18:52:38.317783 close(3</etc/ld.so.cache>) = 0
18:52:38.319315 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
18:52:38.320763 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3</lib/x86_64-linux-gnu/libc-2.27.so>
18:52:38.322554 read(3</lib/x86_64-linux-gnu/libc-2.27.so>, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\34\2\0\0\0\0\0"..., 832) = 832
18:52:38.323971 fstat(3</lib/x86_64-linux-gnu/libc-2.27.so>, {st_mode=S_IFREG|0755, st_size=2030544, ...}) = 0
18:52:38.325310 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fda1db80000
18:52:38.326690 mmap(NULL, 4131552, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3</lib/x86_64-linux-gnu/libc-2.27.so>, 0) = 0x7fda1d400000
18:52:38.328228 mprotect(0x7fda1d5e7000, 2097152, PROT_NONE) = 0
18:52:38.329655 mmap(0x7fda1d7e7000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3</lib/x86_64-linux-gnu/libc-2.27.so>, 0x1e7000) = 0x7fda1d7e7000
18:52:38.331180 mmap(0x7fda1d7ed000, 15072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fda1d7ed000
18:52:38.332608 close(3</lib/x86_64-linux-gnu/libc-2.27.so>) = 0
18:52:38.334070 arch_prctl(ARCH_SET_FS, 0x7fda1db81540) = 0
18:52:38.335616 mprotect(0x7fda1d7e7000, 16384, PROT_READ) = 0
18:52:38.337093 mprotect(0x7fda1de0f000, 4096, PROT_READ) = 0
18:52:38.338396 mprotect(0x7fda1da27000, 4096, PROT_READ) = 0
18:52:38.339662 munmap(0x7fda1db90000, 62985) = 0
18:52:38.341119 brk(NULL)               = 0x7fffdda86000
18:52:38.342395 brk(0x7fffddaa7000)     = 0x7fffddaa7000
18:52:38.343720 openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3</usr/lib/locale/locale-archive>
18:52:38.345392 fstat(3</usr/lib/locale/locale-archive>, {st_mode=S_IFREG|0644, st_size=3481584, ...}) = 0
18:52:38.346708 mmap(NULL, 3481584, PROT_READ, MAP_PRIVATE, 3</usr/lib/locale/locale-archive>, 0) = 0x7fda1d0ae000
18:52:38.348051 close(3</usr/lib/locale/locale-archive>) = 0
18:52:38.349445 openat(AT_FDCWD, "data.log", O_RDONLY) = 3</tmp/data.log>
18:52:38.352538 fstat(3</tmp/data.log>, {st_mode=S_IFREG|0666, st_size=4, ...}) = 0
18:52:38.353896 lseek(3</tmp/data.log>, 0, SEEK_CUR) = 0
18:52:38.355148 lseek(3</tmp/data.log>, 0, SEEK_END) = 4
18:52:38.356474 lseek(3</tmp/data.log>, 0, SEEK_SET) = 0
18:52:38.357764 read(3</tmp/data.log>, "1\n2\n", 4) = 4
18:52:38.359157 lseek(3</tmp/data.log>, 0, SEEK_SET) = 0
18:52:38.360401 read(3</tmp/data.log>, "1\n2\n", 4) = 4
18:52:38.361862 fstat(1</dev/pts/3>, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 3), ...}) = 0
18:52:38.363334 write(1</dev/pts/3>, "1\n", 2) = 2
18:52:38.364674 write(1</dev/pts/3>, "2\n", 2) = 2
18:52:38.366987 fstat(3</tmp/data.log>, {st_mode=S_IFREG|0666, st_size=4, ...}) = 0
18:52:38.368533 fstatfs(3</tmp/data.log>, {f_type=0x53464846, f_bsize=4096, f_blocks=26214399, f_bfree=14077756, f_bavail=14077756, f_files=999, f_ffree=1000000, f_fsid={val=[1, 0]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_NOATIME}) = 0
18:52:38.369942 fstat(1</dev/pts/3>, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 3), ...}) = 0
18:52:38.371294 lstat("data.log", {st_mode=S_IFREG|0666, st_size=4, ...}) = 0
18:52:38.372616 inotify_init()          = 4
18:52:38.374016 inotify_add_watch(4</unknown>, "data.log", IN_MODIFY) = 1
18:52:38.375391 stat("data.log", {st_mode=S_IFREG|0666, st_size=4, ...}) = 0
18:52:38.376807 fstat(3</tmp/data.log>, {st_mode=S_IFREG|0666, st_size=4, ...}) = 0
18:52:38.378130 select(5, [4</unknown>], NULL, NULL, NULL) = 1 (in [4])
--------------------------- 这里执行 seq 3 4 >/tmp/data.log-----------------------------------------------------------------------------------
18:52:58.852296 read(4</unknown>, "\1\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 25) = 16
18:52:58.855040 fstat(3</tmp/data.log>, {st_mode=S_IFREG|0666, st_size=8, ...}) = 0
18:52:58.857313 read(3</tmp/data.log>, "3\n4\n", 8192) = 4
18:52:58.859427 write(1</dev/pts/3>, "3\n4\n", 4) = 4
18:52:58.861290 read(3</tmp/data.log>, "", 8192) = 0
18:52:58.863148 select(5, [4</unknown>], NULL, NULL, NULL) = 1 (in [4])
--------------------------- 这里执行 seq 5 6 >/tmp/data.log-----------------------------------------------------------------------------------
18:53:04.599560 read(4</unknown>, "\1\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 25) = 16
18:53:04.601325 fstat(3</tmp/data.log>, {st_mode=S_IFREG|0666, st_size=12, ...}) = 0
18:53:04.602809 read(3</tmp/data.log>, "5\n6\n", 8192) = 4
18:53:04.604310 write(1</dev/pts/3>, "5\n6\n", 4) = 4
18:53:04.605677 read(3</tmp/data.log>, "", 8192) = 0
18:53:04.607089 select(5, [4</unknown>], NULL, NULL, NULL) = ? ERESTARTNOHAND (To be restarted if no handler)
--------------------------- 这里按下Ctrl-C-----------------------------------------------------------------------------------------------------
18:53:16.593133 --- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
18:53:16.599328 +++ killed by SIGINT +++

开头

18:52:38.300588 execve("/usr/bin/tail", ["tail", "-f", "data.log"], 0x7fffd96ca0f0 /* 24 vars */) = 0
........
18:52:38.348051 close(3</usr/lib/locale/locale-archive>) = 0

这么一大段，不过是在读取各种动态库而已。可以忽略不看。

然后是

18:52:38.352538 fstat(3</tmp/data.log>, {st_mode=S_IFREG|0666, st_size=4, ...}) = 0
18:52:38.353896 lseek(3</tmp/data.log>, 0, SEEK_CUR) = 0
18:52:38.355148 lseek(3</tmp/data.log>, 0, SEEK_END) = 4
18:52:38.356474 lseek(3</tmp/data.log>, 0, SEEK_SET) = 0

通过 lseek 读出文件结尾的字节数

18:52:38.357764 read(3</tmp/data.log>, "1\n2\n", 4) = 4
18:52:38.359157 lseek(3</tmp/data.log>, 0, SEEK_SET) = 0
18:52:38.360401 read(3</tmp/data.log>, "1\n2\n", 4) = 4
18:52:38.361862 fstat(1</dev/pts/3>, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 3), ...}) = 0
18:52:38.363334 write(1</dev/pts/3>, "1\n", 2) = 2
18:52:38.364674 write(1</dev/pts/3>, "2\n", 2) = 2

读出文件内容并且一行一行的输出，从中可以看到，文件中原始包含的内容有两行，分别是 1 和 2.

后面有多次使用 fstat 和 lstat 获取文件状态，老实说不确定什么目的，估计是检测文件是否被删除，或者改名吧。

18:52:38.372616 inotify_init()          = 4
18:52:38.374016 inotify_add_watch(4</unknown>, "data.log", IN_MODIFY) = 1
18:52:38.375391 stat("data.log", {st_mode=S_IFREG|0666, st_size=4, ...}) = 0
18:52:38.376807 fstat(3</tmp/data.log>, {st_mode=S_IFREG|0666, st_size=4, ...}) = 0

这里用 inotify 机制创建一个watch,

18:52:38.378130 select(5, [4</unknown>], NULL, NULL, NULL) = 1 (in [4])

通过 select 进行阻塞，只有当文件发生修改的情况下才会继续往下执行

后面是多个 read,fstat,write,select 语句的循环

18:52:58.852296 read(4</unknown>, "\1\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 25) = 16
18:52:58.855040 fstat(3</tmp/data.log>, {st_mode=S_IFREG|0666, st_size=8, ...}) = 0
18:52:58.857313 read(3</tmp/data.log>, "3\n4\n", 8192) = 4
18:52:58.859427 write(1</dev/pts/3>, "3\n4\n", 4) = 4
18:52:58.861290 read(3</tmp/data.log>, "", 8192) = 0
18:52:58.863148 select(5, [4</unknown>], NULL, NULL, NULL) = 1 (in [4])

也就是先读出 watch 到的事件，然后在当前文件的位置将新增的内容读出来，再一行一行输出。

这里我没有试验重写文件内容会怎样，不过估计会先重置文件读写位置再读写文件内容吧。

最后

18:53:16.593133 --- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
18:53:16.599328 +++ killed by SIGINT +++

很明显是捕获到了 SIGINT 信号然后退出了。