なぜ？
オレオレなlsを書いたのだがなぜか遅い。
lsなんて興味ないんだけど、stat()しているだけなのに遅いのは生理的になんかいやだ。
前回はgetpwuid()が犯人とすぐわかり改善できたのだが、機能拡張をしたらまた遅くなった。なぜ？
コード
とりあえずファイル名とタイムスタンプを表示させただけなのだが...
変更箇所は1つしかないので、犯人はlocaltime()に違いない。
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sys/stat.h>
#include <dirent.h>
#include <time.h>
int main(int argc, char** argv)
{
char fpath[PATH_MAX];
DIR* dir;
struct dirent* dp;
struct stat st;
char *dpath;
char timestr[25];
dpath = (argc != 2) ? "." : argv[1];
dir = opendir(dpath);
while ((dp = readdir(dir)) != NULL) {
memset(fpath, '\0', sizeof(fpath));
sprintf(fpath, "%s/%s", dpath, dp->d_name);
if (stat(fpath, &st) != -1) {
struct tm* t = localtime( &st.st_mtime );
strftime(timestr, sizeof(timestr), "%Y-%m-%dT%H:%M:%S", t);
fprintf(stdout, "{ filename = %s, timestamp = %s }\n", fpath, timestr);
}
}
closedir(dir);
exit(EXIT_SUCCESS);
}
調査
例によってltraceで関数の呼び出し性能を確認してみる。
localtime()が遅い。strftime()も遅いがここでは一旦無視しよう。
$ ltrace -c ./minls too_many_files.d/ > /dev/null
% time seconds usecs/call calls function
------ ----------- ----------- --------- --------------------
53.74 5.512542 5512542 1 __libc_start_main
7.78 0.797738 79 10002 localtime
7.25 0.743969 74 10002 __xstat
6.36 0.652299 65 10002 strftime
6.28 0.644409 64 10002 fprintf
6.25 0.641071 64 10002 sprintf
6.17 0.632683 63 10003 readdir
6.17 0.632531 63 10002 memset
0.00 0.000173 173 1 opendir
0.00 0.000144 144 1 exit
0.00 0.000072 72 1 closedir
0.00 0.000071 71 1 exit_group
------ ----------- ----------- --------- --------------------
100.00 10.257702 70020 total
なんとなくデジャブ感が出てきた。
余計なstat()をしている気がするのでstraceで確認してみる。
ああー、/etc/localtime を毎回みているのかよ。
$ strace -f -e stat ./minls . 1> /dev/null
stat("./.", {st_mode=S_IFDIR|0775, st_size=118, ...}) = 0
stat("./..", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=292, ...}) = 0
stat("./test.c", {st_mode=S_IFREG|0664, st_size=816, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=292, ...}) = 0
stat("./too_many_files.d", {st_mode=S_IFDIR|0775, st_size=315392, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=292, ...}) = 0
stat("./test-1.c", {st_mode=S_IFREG|0664, st_size=712, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=292, ...}) = 0
stat("./minls1", {st_mode=S_IFREG|0775, st_size=12520, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=292, ...}) = 0
+++ exited with 0 +++
/etc/localtimeって毎回参照するようなものだっけ？
今度は、perfでレポートを出してみる。
$ perf record -- ./minls ./too_many_files.d/ > /dev/null
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.003 MB perf.data (61 samples) ]
$ perf report --stdio -q
18.03% minls libc-2.17.so [.] vfprintf
13.11% minls libc-2.17.so [.] __strftime_internal
8.20% minls libc-2.17.so [.] _IO_vfscanf
6.56% minls libc-2.17.so [.] __offtime
6.56% minls libc-2.17.so [.] _int_malloc
4.92% minls libc-2.17.so [.] __tz_compute
3.28% minls libc-2.17.so [.] _IO_file_xsputn@@GLIBC_2.2.5
3.28% minls libc-2.17.so [.] __memcpy_sse2
3.28% minls libc-2.17.so [.] __memset_sse2
3.28% minls libc-2.17.so [.] __readdir64
3.28% minls libc-2.17.so [.] __tzfile_compute
3.28% minls libc-2.17.so [.] _int_free
1.64% minls libc-2.17.so [.] _IO_old_init
1.64% minls libc-2.17.so [.] _IO_vsscanf
1.64% minls libc-2.17.so [.] __GI_____strtoull_l_internal
1.64% minls libc-2.17.so [.] __memcmp_sse2
1.64% minls libc-2.17.so [.] __strchrnul
1.64% minls libc-2.17.so [.] __strdup
1.64% minls libc-2.17.so [.] __tz_convert
1.64% minls libc-2.17.so [.] __tzfile_read
1.64% minls libc-2.17.so [.] fprintf
1.64% minls libc-2.17.so [.] free
1.64% minls libc-2.17.so [.] getenv
1.64% minls libc-2.17.so [.] parse_tzname
1.64% minls libc-2.17.so [.] tzset_internal
1.64% minls minls [.] main
printf系が遅いのはいつものことなので一旦無視するが、コードには使用していないgetenv()がいやがる。
ああ、そうだ。localtime()が参照するのは TZ環境変数だったはず。
試しに TZ環境変数の有無でstat()の回数が減るのか確認をしてみると、TZを設定すると/etc/localtimeファイルへのアクセスが表面上はなくなっている。
$ strace -f -e stat,open ./minls test.d
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
stat("test.d/.", {st_mode=S_IFDIR|0775, st_size=42, ...}) = 0
open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 4
stat("test.d/..", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=292, ...}) = 0
stat("test.d/test1", {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=292, ...}) = 0
stat("test.d/test2", {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=292, ...}) = 0
stat("test.d/test3", {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=292, ...}) = 0
+++ exited with 0 +++
$ export TZ=JST-9
$ strace -f -e stat,open ./minls test.d
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
stat("test.d/.", {st_mode=S_IFDIR|0775, st_size=42, ...}) = 0
open("/usr/share/zoneinfo/JST-9", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("test.d/..", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
stat("test.d/test1", {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
stat("test.d/test2", {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
stat("test.d/test3", {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
+++ exited with 0 +++
もっとも、localtime()を使わず、localtime_r()を使ったほうが良いようだ。
if (stat(fpath, &st) != -1) {
struct tm t;
localtime_r( &st.st_mtime, &t );
strftime(timestr, sizeof(timestr), "%Y-%m-%dT%H:%M:%S", &t);
fprintf(stdout, "{ filename = %s, timestamp = %s }\n", fpath, timestr);
}
localtime_r()に変更してstraceをすると、初回は/etc/localtimeへアクセスするが、2回目以降は/etc/localtimeへのアクセスはなくなっているようにみえる。
$ unset TZ
$ strace -f -e stat,open ./minls test.d
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
stat("test.d/.", {st_mode=S_IFDIR|0775, st_size=42, ...}) = 0
open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 4
stat("test.d/..", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
stat("test.d/test1", {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
stat("test.d/test2", {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
stat("test.d/test3", {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
+++ exited with 0 +++
結果
## localtime
$ time ./minls2 ./too_many_files.d > /dev/null
real 0m0.037s
user 0m0.016s
sys 0m0.021s
## localtime + TZ環境変数
$ export TZ=JST-9
$ time ./minls2 ./too_many_files.d > /dev/null
real 0m0.020s
user 0m0.011s
sys 0m0.010s
## localtime_r
$ unset TZ
$ time ./minls1 ./too_many_files.d > /dev/null
real 0m0.019s
user 0m0.015s
sys 0m0.004s
このあたりのどれかで落ち着きました。
- localtime()ではなくlocaltime_r()を使う
- localtime()の場合はTZ環境変数を設定してもらう
- localtime()の場合はTZ環境変数へsetenv()する (tm構造体のtm_zoneとtm_gmtoffをごにょごにょする)