Linuxでvmstatの1行ごとに時刻を付けるときにミリ秒まで入れる。
$ vmstat 3 | ruby -ne 'print Time.now.strftime("%X.%3N #{$_}"); STDOUT.flush' | tee vmstat_log.txt
18:44:25.141 procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
18:44:25.141 r b swpd free buff cache si so bi bo in cs us sy id wa st
18:44:25.141 1 0 0 23715472 133952 2093676 0 0 12 166 34 170 5 1 94 0 0
18:44:27.991 0 0 0 23699344 133952 2093664 0 0 0 0 195 1590 0 0 100 0 0
straceやinotifywaitにも使える。
$ strace sleep 3 |& ruby -ne 'print Time.now.strftime("%X.%3N #{$_}"); STDOUT.flush' | tee trace_sleep3.txt
16:55:38.939 execve("/usr/bin/sleep", ["sleep", "3"], 0x7ffeaad126a8 /* 29 vars */) = 0
16:55:38.939 brk(NULL) = 0x55df60aa7000
16:55:38.939 arch_prctl(0x3001 /* ARCH_??? */, 0x7fff72025b60) = -1 EINVAL (Invalid argument)
16:55:38.939 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff2c632a000
16:55:38.939 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
16:55:38.939 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
16:55:38.939 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=23031, ...}, AT_EMPTY_PATH) = 0
16:55:38.939 mmap(NULL, 23031, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7ff2c6324000
16:55:38.939 close(3) = 0
16:55:38.939 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
16:55:38.939 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\237\2\0\0\0\0\0"..., 832) = 832
16:55:38.939 pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
16:55:38.939 pread64(3, "\4\0\0\0 \0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0"..., 48, 848) = 48
16:55:38.939 pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0i8\235HZ\227\223\333\350s\360\352,\223\340."..., 68, 896) = 68
16:55:38.939 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=2216304, ...}, AT_EMPTY_PATH) = 0
16:55:38.939 pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
16:55:38.939 mmap(NULL, 2260560, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ff2c60fc000
16:55:38.939 mmap(0x7ff2c6124000, 1658880, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x28000) = 0x7ff2c6124000
16:55:38.939 mmap(0x7ff2c62b9000, 360448, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1bd000) = 0x7ff2c62b9000
16:55:38.939 mmap(0x7ff2c6311000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x214000) = 0x7ff2c6311000
16:55:38.939 mmap(0x7ff2c6317000, 52816, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ff2c6317000
16:55:38.939 close(3) = 0
16:55:38.939 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff2c60f9000
16:55:38.939 arch_prctl(ARCH_SET_FS, 0x7ff2c60f9740) = 0
16:55:38.939 set_tid_address(0x7ff2c60f9a10) = 26285
16:55:38.939 set_robust_list(0x7ff2c60f9a20, 24) = 0
16:55:38.939 rseq(0x7ff2c60fa0e0, 0x20, 0, 0x53053053) = 0
16:55:38.939 mprotect(0x7ff2c6311000, 16384, PROT_READ) = 0
16:55:38.939 mprotect(0x55df60214000, 4096, PROT_READ) = 0
16:55:38.939 mprotect(0x7ff2c6364000, 8192, PROT_READ) = 0
16:55:38.939 prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
16:55:38.939 munmap(0x7ff2c6324000, 23031) = 0
16:55:38.939 getrandom("\x7e\xdb\x66\x5e\x19\x12\x13\x89", 8, GRND_NONBLOCK) = 8
16:55:38.939 brk(NULL) = 0x55df60aa7000
16:55:38.939 brk(0x55df60ac8000) = 0x55df60ac8000
16:55:38.939 openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
16:55:38.939 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=5712208, ...}, AT_EMPTY_PATH) = 0
16:55:38.939 mmap(NULL, 5712208, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7ff2c5b86000
16:55:38.939 close(3) = 0
16:55:41.785 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=3, tv_nsec=0}, 0x7fff72025bb0) = 0
16:55:41.786 close(1) = 0
16:55:41.786 close(2) = 0
16:55:41.787 exit_group(0) = ?
16:55:41.788 +++ exited with 0 +++
$
秒単位よりもう少し細かいタイミングが欲しいときに。
