なぜ？

オレオレな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をごにょごにょする)