ablog

不器用で落着きのない技術者のメモ

ls のソースを読んでプログラマになりました

Linux Perl

タイトルは釣りですw*1

とあるテキストファイルを加工してCSVファイルを出力する Perl スクリプトがあり、ディレクトリ内のファイルをリストアップしてCSVファイルに出力しているのだが、なぜファイル名でソートされていないのか聞かれたので調べてみた。

その Perl スクリプトは File::DosGlob::glob でファイルリストを取得していたので、

yazekats% mkdir tmp
yazekats% cd tmp
yazekats% ls
yazekats% touch 3
yazekats% touch 2
yazekats% touch 1
yazekats% ls
1  2  3
yazekats% perl -MFile::DosGlob -e 'map{print qq/$_\n/} File::DosGlob::glob(q/*/)';
1
3
2

試してみると確かにソートされない。File::DosGlob のソースを見てみると、

	opendir(D, $head) or next OUTER;
	my @leaves = readdir D; <--
	closedir D;

readdir を呼んでいる。

yazekats% perl -e 'opendir(DIR, q/./);map{print qq/$_\n/}readdir(DIR);'
1
.
3
2
..

readdir でファイルリストを取得するとやはりソートされない。strace でシステムコールを見てみると、

yazekats% strace perl -e 'opendir(DIR, q/./);map{print qq/$_\n/}readdir(DIR);'                        
execve("/usr/bin/perl", ["perl", "-e", "opendir(DIR, q/./);map{print qq/"...], [/* 50 vars */]) = 0

...

open(".", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
fcntl(3, F_GETFD)                       = 0x1 (flags FD_CLOEXEC)
getdents(3, /* 5 entries */, 32768)     = 120 <--
getdents(3, /* 0 entries */, 32768)     = 0

getdents システムコールでファイルリストを取得しているようだ。strace で ls が呼んでいるシステムコールを見ると、

yazekats% strace ls
execve("/bin/ls", ["ls"], [/* 50 vars */]) = 0

...

getdents(3, /* 5 entries */, 32768)     = 120 <--
getdents(3, /* 0 entries */, 32768)     = 0

こちらも getdents を呼んでいる。Perl の readdir も ls も getdents システムコールを呼んでるけど、ls はソートしていると思われる。ls の man を見ると、

yazekats% man ls
NAME
       ls - list directory contents

SYNOPSIS
       ls [OPTION]... [FILE]...

DESCRIPTION
       List information about the FILEs (the current directory by default).  Sort entries alphabetically if none of -cftuvSUX nor --sort. <--

...

       -f     do not sort, enable -aU, disable -ls --color <--

デフォルトでアルファベットでソートされ、-f オプションをつけるとソートされないと書かれている。

yazekats% ls -f
1  .  3  2  ..

ls に -f オプションをつけると Perl の readdir と同じ順になった。
そう言えば、

lsを読まずにプログラマを名乗るな!

lsを読まずにプログラマを名乗るな!

とかいう本も見かけるので ls のソースコードを読んでみることにした。ls が含まれるパッケージを調べると、

[root@yazekats-linux ~]# rpm -qf /bin/ls
coreutils-8.4-19.0.1.el6.x86_64

coreutils のようだ。

[root@yazekats-linux ~]# mkdir -p /usr/src/gnu
[root@yazekats-linux ~]# cd /usr/src/gnu
[root@yazekats-linux gnu]# wget http://ftp.gnu.org/gnu/coreutils/coreutils-8.4.tar.gz
[root@yazekats-linux gnu]# tar xvfz coreutils-8.4.tar.gz
[root@yazekats-linux src]# cd coreutils-8.4/src
[root@yazekats-linux src]# wc -l ls.c
4712 ls.c
  • ls.c
436 /* The file characteristic to sort by.  Controlled by -t, -S, -U, -X, -v.
437    The values of each item of this enum are important since they are
438    used as indices in the sort functions array (see sort_files()).  */
439 
440 enum sort_type
441   {
442     sort_none = -1,             /* -U */
443     sort_name,                  /* default */ <--
444     sort_extension,             /* -X */
445     sort_size,                  /* -S */
446     sort_version,               /* -v */
447     sort_time,                  /* -t */
448     sort_numtypes               /* the number of elements of this enum */
449   };

...

3370 sort_files (void) <--
3371 {
3372   bool use_strcmp;
3373 
3374   if (sorted_file_alloc < cwd_n_used + cwd_n_used / 2)
3375     {
3376       free (sorted_file);
3377       sorted_file = xnmalloc (cwd_n_used, 3 * sizeof *sorted_file);
3378       sorted_file_alloc = 3 * cwd_n_used;
3379     }
3380 
3381   initialize_ordering_vector ();
3382 
3383   if (sort_type == sort_none)
3384     return;
3385 
3386   /* Try strcoll.  If it fails, fall back on strcmp.  We can't safely
3387      ignore strcoll failures, as a failing strcoll might be a
3388      comparison function that is not a total order, and if we ignored
3389      the failure this might cause qsort to dump core.  */
3390 
3391   if (! setjmp (failed_strcoll))
3392     use_strcmp = false;      /* strcoll() succeeded */
3393   else
3394     {
3395       use_strcmp = true;
3396       assert (sort_type != sort_version);
3397       initialize_ordering_vector ();
3398     }
3399 
3400   /* When sort_type == sort_time, use time_type as subindex.  */
3401   mpsort ((void const **) sorted_file, cwd_n_used,
3402           sort_functions[sort_type + (sort_type == sort_time ? time_type : 0)]
3403                         [use_strcmp][sort_reverse]
3404                         [directories_first]);
3405 }

ソースコードからもデフォルトでソートしていることがわかる。コンパイルして、

[root@yazekats-linux coreutils-8.4]# pwd
/usr/src/gnu/coreutils-8.4
[root@yazekats-linux coreutils-8.4]# ./configure
[root@yazekats-linux coreutils-8.4]# make "CFLAGS= -g"

gdb でステップ実行してみると、

yazekats% cd /usr/src/gnu/coreutils-8.4/src
yazekats% gdb ls                                                                                      
GNU gdb (GDB) Red Hat Enterprise Linux (7.2-60.el6)
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/src/gnu/coreutils-8.4/src/ls...done.
(gdb) b sort_files
Breakpoint 1 at 0x40798d: file ls.c, line 3374.
(gdb) run
Starting program: /usr/src/gnu/coreutils-8.4/src/ls 
[Thread debugging using libthread_db enabled]

Breakpoint 1, sort_files () at ls.c:3374
3374	  if (sorted_file_alloc < cwd_n_used + cwd_n_used / 2)
Missing separate debuginfos, use: debuginfo-install glibc-2.12-1.132.el6.x86_64
(gdb) n
3376	      free (sorted_file);
(gdb) n
3377	      sorted_file = xnmalloc (cwd_n_used, 3 * sizeof *sorted_file);
(gdb) n
3378	      sorted_file_alloc = 3 * cwd_n_used;
(gdb) n
3381	  initialize_ordering_vector ();
(gdb) n
3383	  if (sort_type == sort_none) <-- ここで return していない
(gdb) n
3391	  if (! setjmp (failed_strcoll)) 
(gdb) n
3392	    use_strcmp = false;      /* strcoll() succeeded */
(gdb) n
3402	          sort_functions[sort_type + (sort_type == sort_time ? time_type : 0)]
(gdb) n
3401	  mpsort ((void const **) sorted_file, cwd_n_used,
(gdb) n
3402	          sort_functions[sort_type + (sort_type == sort_time ? time_type : 0)]
(gdb) n
3401	  mpsort ((void const **) sorted_file, cwd_n_used,
(gdb) n
3405	}
(gdb) n
print_dir (name=0x623c40 ".", realname=0x0, command_line_arg=true) at ls.c:2572
2572	  if (recursive)
(gdb) n
2575	  if (format == long_format || print_block_size)
(gdb) n
2590	  if (cwd_n_used)
(gdb) n
2591	    print_current_files ();
(gdb) n
Makefile	 copy.o		env.o ...

ソート処理が実行されていることがわかる。


追記(2014.03.09):
ディレクトリ内にファイルを10万個作って

[yazekats@yazekats-linux tmp]$ pwd
/home/yazekats/work/tmp
[yazekats@yazekats-linux tmp]$ for i in {1..100000} 
do 
touch $i 
done

time コマンドで ls、ls -f の実行時間を計測してみると、

  • ls
[yazekats@yazekats-linux work]$ time ls ./tmp
real	0m1.603s
user	0m0.409s
sys	0m0.209s
  • ls -f
[yazekats@yazekats-linux work]$ time ls -f ./tmp
real	0m1.399s
user	0m0.121s
sys	0m0.076s

予想通り、ls > ls -f となった。ls -f はユーザー空間でソートしないので、user が短いのは想定通りだが、sys が 1/2 以下なのは意外だった。perf コマンドで関数別のランキングを調べてみた。

  • ls
[yazekats@yazekats-linux work]$ perf record -o perf_ls.data ls ./tmp
[yazekats@yazekats-linux work]$ perf report --show-total-period -i perf_ls.data
Samples: 1K of event 'cycles:HG', Event count (approx.): 794632199
 56.53%    449176209  ls  ls                 [.] 0x00000000000038bd
  6.39%     50800009  ls  libc-2.12.so       [.] __strcmp_sse2
  2.07%     16462434  ls  [ext4]             [k] ext4_htree_store_dirent
  1.87%     14853616  ls  [kernel.kallsyms]  [k] half_md4_transform
  1.55%     12318812  ls  libc-2.12.so       [.] __strcoll_l
  1.25%      9894187  ls  [kernel.kallsyms]  [k] __ticket_spin_lock
  1.24%      9865841  ls  [kernel.kallsyms]  [k] __kmalloc
  1.12%      8939468  ls  [kernel.kallsyms]  [k] native_write_msr_safe
  0.81%      6470704  ls  [kernel.kallsyms]  [k] page_fault
  0.78%      6161492  ls  [kernel.kallsyms]  [k] kfree
  0.76%      6064032  ls  [kernel.kallsyms]  [k] process_output_block
  0.76%      6037474  ls  [kernel.kallsyms]  [k] _raw_spin_unlock_irqrestore
  0.67%      5301578  ls  libc-2.12.so       [.] __ctype_get_mb_cur_max
  0.65%      5165023  ls  libc-2.12.so       [.] _int_malloc
  0.64%      5124283  ls  [kernel.kallsyms]  [k] rb_insert_color
  0.58%      4599655  ls  [kernel.kallsyms]  [k] __schedule
  0.52%      4171788  ls  [ext4]             [k] call_filldir
  0.51%      4040668  ls  [kernel.kallsyms]  [k] insert_work
  0.49%      3857242  ls  [kernel.kallsyms]  [k] _raw_spin_lock_irqsave
  0.47%      3740517  ls  [kernel.kallsyms]  [k] rb_next
  0.46%      3675456  ls  [kernel.kallsyms]  [k] pty_write
  0.44%      3510682  ls  libc-2.12.so       [.] _IO_file_xsputn@@GLIBC_2.2.5
  0.43%      3408243  ls  [kernel.kallsyms]  [k] memset
  0.42%      3327099  ls  libc-2.12.so       [.] fwrite_unlocked
  0.40%      3158698  ls  [kernel.kallsyms]  [k] memcpy
  0.39%      3081929  ls  [kernel.kallsyms]  [k] clear_page_c_e
  0.39%      3081843  ls  libc-2.12.so       [.] memmove
  0.39%      3081185  ls  libc-2.12.so       [.] memcpy
  0.39%      3078938  ls  libc-2.12.so       [.] strcoll
  0.39%      3061134  ls  libc-2.12.so       [.] malloc
  0.34%      2683534  ls  [kernel.kallsyms]  [k] __ticket_spin_unlock
  0.34%      2673397  ls  [ext4]             [k] htree_dirblock_to_tree
  0.33%      2644688  ls  [kernel.kallsyms]  [k] select_task_rq_fair
  0.32%      2531129  ls  [kernel.kallsyms]  [k] update_cfs_shares
  0.32%      2520196  ls  libc-2.12.so       [.] __errno_location
  0.31%      2492874  ls  [kernel.kallsyms]  [k] find_get_page
  0.31%      2480748  ls  [kernel.kallsyms]  [k] mutex_lock
  • ls -f
[yazekats@yazekats-linux work]$ perf record -o perf_ls-f.data ls -f ./tmp
[yazekats@yazekats-linux work]$ perf report --show-total-period -i perf_ls-f.data
Samples: 1K of event 'cycles:HG', Event count (approx.): 555704525
 55.70%    309532919  ls  ls                 [.] 0x00000000000038b0
  2.73%     15160053  ls  [ext4]             [k] ext4_htree_store_dirent
  2.63%     14589331  ls  [kernel.kallsyms]  [k] half_md4_transform
  1.70%      9442331  ls  [kernel.kallsyms]  [k] native_write_msr_safe
  1.49%      8278222  ls  [kernel.kallsyms]  [k] process_output_block
  1.36%      7533656  ls  [kernel.kallsyms]  [k] rb_insert_color
  1.29%      7173532  ls  [kernel.kallsyms]  [k] __ticket_spin_lock
  1.22%      6801953  ls  libc-2.12.so       [.] __ctype_get_mb_cur_max
  0.98%      5420912  ls  libc-2.12.so       [.] _IO_file_xsputn@@GLIBC_2.2.5
  0.97%      5388310  ls  libc-2.12.so       [.] _int_malloc
  0.97%      5384888  ls  [ext4]             [k] free_rb_tree_fname
  0.96%      5329375  ls  [ext4]             [k] call_filldir
  0.95%      5292615  ls  [kernel.kallsyms]  [k] __kmalloc
  0.82%      4535307  ls  [kernel.kallsyms]  [k] clear_page_c_e
  0.80%      4463226  ls  [kernel.kallsyms]  [k] _raw_spin_unlock_irqrestore
  0.73%      4029004  ls  [kernel.kallsyms]  [k] rb_next
  0.69%      3843898  ls  [kernel.kallsyms]  [k] memcpy
  0.69%      3841932  ls  libc-2.12.so       [.] memmove
  0.69%      3831134  ls  [ext4]             [k] str2hashbuf_signed
  0.69%      3823534  ls  libc-2.12.so       [.] __readdir64
  0.68%      3783826  ls  [kernel.kallsyms]  [k] copy_user_enhanced_fast_string
  0.59%      3273124  ls  [kernel.kallsyms]  [k] select_task_rq_fair
  0.56%      3090737  ls  [kernel.kallsyms]  [k] memset
  0.55%      3064682  ls  [ext4]             [k] htree_dirblock_to_tree
  0.50%      2803340  ls  [kernel.kallsyms]  [k] _cond_resched
  0.49%      2739222  ls  [kernel.kallsyms]  [k] try_to_wake_up
  0.49%      2726130  ls  [kernel.kallsyms]  [k] __schedule
  0.43%      2409262  ls  [kernel.kallsyms]  [k] mutex_unlock
  0.42%      2311450  ls  libc-2.12.so       [.] __strlen_sse42
  0.41%      2305214  ls  libc-2.12.so       [.] __strlen_sse2
  0.36%      1976805  ls  [kernel.kallsyms]  [k] kfree
  0.35%      1963559  ls  [kernel.kallsyms]  [k] insert_work
  0.35%      1948315  ls  [kernel.kallsyms]  [k] __queue_work
  0.35%      1920452  ls  [kernel.kallsyms]  [k] tty_flip_buffer_push
  0.30%      1680321  ls  [kernel.kallsyms]  [k] __list_add
  0.30%      1659690  ls  libc-2.12.so       [.] _IO_file_overflow@@GLIBC_2.2.5
  0.28%      1578366  ls  [kernel.kallsyms]  [k] pty_write

ソートするのにメモリを使うので、メモリ領域の獲得と開放とかでシステムコールを呼んで ls は ls -f に比べて sys で使う時間も長くなっているのかな？


さらに追記(2014.03.09):
sys の差ならシンプルに strace -c でいいじゃんということで調べてみた。

  • ls
[yazekats@yazekats-linux work]$ strace -c ls ./tmp
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 89.43    0.025712         265        97           getdents
  9.03    0.002596           1      4348           write
  1.54    0.000443          63         7           mremap
  0.00    0.000000           0        10           read
  0.00    0.000000           0        54        43 open
  0.00    0.000000           0        13           close
  0.00    0.000000           0         5         3 stat
  0.00    0.000000           0        11           fstat
  0.00    0.000000           0        30           mmap
  0.00    0.000000           0        16           mprotect
  0.00    0.000000           0         3           munmap
  0.00    0.000000           0        26           brk
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0         2           ioctl
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           fcntl
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           statfs
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         2         1 futex
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.028751                  4635        48 total
  • ls -f
[yazekats@yazekats-linux work]$ strace -c ls -f ./tmp
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 77.74    0.017489         180        97           getdents
 19.91    0.004480           1      4348           write
  2.16    0.000487          70         7           mremap
  0.10    0.000023           2        10           read
  0.08    0.000017           1        13           close
  0.00    0.000000           0        54        43 open
  0.00    0.000000           0         5         3 stat
  0.00    0.000000           0        11           fstat
  0.00    0.000000           0        30           mmap
  0.00    0.000000           0        16           mprotect
  0.00    0.000000           0         3           munmap
  0.00    0.000000           0        26           brk
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0         2           ioctl
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           fcntl
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           statfs
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         2         1 futex
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.022496                  4635        48 total

ls -f より ls は getdents の呼出し回数(calls)は同じだが、1回当たりの時間(usecs/call)が長くなり、結果として所要時間(seconds)が長くなっている。そろそろ DTrace の出番かも(Oracle Linux + UEK を使っている)。


追記(2014.03.10):
strace に -c オプションをつけずに一つ一つの getdents システムコールを見てみた。

  • ls
[yazekats@yazekats-linux work]$ strace -T -o strace_ls.log ls ./tmp
[yazekats@yazekats-linux work]$ grep getdents strace_ls.log 
getdents(3, /* 1050 entries */, 32768)  = 32760 <0.001016>
getdents(3, /* 1048 entries */, 32768)  = 32752 <0.000636>
getdents(3, /* 1046 entries */, 32768)  = 32768 <0.001006>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.001128>
getdents(3, /* 1052 entries */, 32768)  = 32760 <0.001012>
getdents(3, /* 1052 entries */, 32768)  = 32752 <0.000797>
getdents(3, /* 1052 entries */, 32768)  = 32752 <0.000640>
getdents(3, /* 1055 entries */, 32768)  = 32760 <0.000723>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000730>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.000689>
getdents(3, /* 1051 entries */, 32768)  = 32744 <0.000800>
getdents(3, /* 1050 entries */, 32768)  = 32768 <0.000651>
getdents(3, /* 1047 entries */, 32768)  = 32768 <0.000685>
getdents(3, /* 1049 entries */, 32768)  = 32768 <0.000735>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000731>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.000745>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.000666>
getdents(3, /* 1055 entries */, 32768)  = 32752 <0.000739>
getdents(3, /* 1048 entries */, 32768)  = 32768 <0.000652>
getdents(3, /* 1048 entries */, 32768)  = 32744 <0.000763>
getdents(3, /* 1051 entries */, 32768)  = 32744 <0.000640>
getdents(3, /* 1048 entries */, 32768)  = 32744 <0.000784>
getdents(3, /* 1052 entries */, 32768)  = 32760 <0.000702>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000635>
getdents(3, /* 1053 entries */, 32768)  = 32744 <0.000742>
getdents(3, /* 1049 entries */, 32768)  = 32760 <0.000770>
getdents(3, /* 1053 entries */, 32768)  = 32768 <0.000630>
getdents(3, /* 1051 entries */, 32768)  = 32768 <0.000691>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.000742>
getdents(3, /* 1050 entries */, 32768)  = 32752 <0.000740>
getdents(3, /* 1051 entries */, 32768)  = 32760 <0.000683>
getdents(3, /* 1050 entries */, 32768)  = 32752 <0.000674>
getdents(3, /* 1045 entries */, 32768)  = 32752 <0.000796>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000635>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000671>
getdents(3, /* 1048 entries */, 32768)  = 32768 <0.000753>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000743>
getdents(3, /* 1045 entries */, 32768)  = 32760 <0.000684>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000695>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000692>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000813>
getdents(3, /* 1052 entries */, 32768)  = 32744 <0.000624>
getdents(3, /* 1048 entries */, 32768)  = 32768 <0.000691>
getdents(3, /* 1054 entries */, 32768)  = 32768 <0.000740>
getdents(3, /* 1050 entries */, 32768)  = 32768 <0.000745>
getdents(3, /* 1052 entries */, 32768)  = 32744 <0.000724>
getdents(3, /* 1052 entries */, 32768)  = 32768 <0.000642>
getdents(3, /* 1047 entries */, 32768)  = 32744 <0.000740>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000783>
getdents(3, /* 1048 entries */, 32768)  = 32768 <0.000690>
getdents(3, /* 1049 entries */, 32768)  = 32768 <0.000775>
getdents(3, /* 1049 entries */, 32768)  = 32760 <0.000718>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000652>
getdents(3, /* 1050 entries */, 32768)  = 32768 <0.000723>
getdents(3, /* 1048 entries */, 32768)  = 32760 <0.000733>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.000673>
getdents(3, /* 1047 entries */, 32768)  = 32768 <0.000775>
getdents(3, /* 1048 entries */, 32768)  = 32744 <0.000745>
getdents(3, /* 1056 entries */, 32768)  = 32760 <0.000663>
getdents(3, /* 1053 entries */, 32768)  = 32752 <0.000791>
getdents(3, /* 1052 entries */, 32768)  = 32768 <0.000705>
getdents(3, /* 1051 entries */, 32768)  = 32768 <0.000680>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000766>
getdents(3, /* 1054 entries */, 32768)  = 32768 <0.000692>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000689>
getdents(3, /* 1054 entries */, 32768)  = 32760 <0.000722>
getdents(3, /* 1056 entries */, 32768)  = 32768 <0.000748>
getdents(3, /* 1053 entries */, 32768)  = 32760 <0.000680>
getdents(3, /* 1051 entries */, 32768)  = 32744 <0.000777>
getdents(3, /* 1053 entries */, 32768)  = 32744 <0.000686>
getdents(3, /* 1046 entries */, 32768)  = 32752 <0.000707>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.000804>
getdents(3, /* 1048 entries */, 32768)  = 32760 <0.000674>
getdents(3, /* 1043 entries */, 32768)  = 32760 <0.000733>
getdents(3, /* 1053 entries */, 32768)  = 32768 <0.000708>
getdents(3, /* 1053 entries */, 32768)  = 32744 <0.000676>
getdents(3, /* 1049 entries */, 32768)  = 32768 <0.000732>
getdents(3, /* 1046 entries */, 32768)  = 32752 <0.000694>
getdents(3, /* 1047 entries */, 32768)  = 32768 <0.000771>
getdents(3, /* 1050 entries */, 32768)  = 32744 <0.000798>
getdents(3, /* 1052 entries */, 32768)  = 32752 <0.000707>
getdents(3, /* 1048 entries */, 32768)  = 32744 <0.000689>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000718>
getdents(3, /* 1048 entries */, 32768)  = 32744 <0.000676>
getdents(3, /* 1050 entries */, 32768)  = 32760 <0.000726>
getdents(3, /* 1050 entries */, 32768)  = 32744 <0.000723>
getdents(3, /* 1052 entries */, 32768)  = 32760 <0.000655>
getdents(3, /* 1050 entries */, 32768)  = 32760 <0.000705>
getdents(3, /* 1050 entries */, 32768)  = 32744 <0.000693>
getdents(3, /* 1054 entries */, 32768)  = 32768 <0.000757>
getdents(3, /* 1054 entries */, 32768)  = 32768 <0.000764>
getdents(3, /* 1051 entries */, 32768)  = 32760 <0.000665>
getdents(3, /* 1053 entries */, 32768)  = 32744 <0.000683>
getdents(3, /* 1049 entries */, 32768)  = 32760 <0.000732>
getdents(3, /* 1050 entries */, 32768)  = 32752 <0.000699>
getdents(3, /* 265 entries */, 32768)   = 8264 <0.000153>
getdents(3, /* 0 entries */, 32768)     = 0 <0.000022>
  • ls -f
[yazekats@yazekats-linux work]$ strace -T -o strace_ls-f.log ls -f ./tmp
[yazekats@yazekats-linux work]$ grep getdents strace_ls-f.log 
getdents(3, /* 1050 entries */, 32768)  = 32760 <0.000856>
getdents(3, /* 1048 entries */, 32768)  = 32752 <0.000630>
getdents(3, /* 1046 entries */, 32768)  = 32768 <0.001119>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.001089>
getdents(3, /* 1052 entries */, 32768)  = 32760 <0.001021>
getdents(3, /* 1052 entries */, 32768)  = 32752 <0.000815>
getdents(3, /* 1052 entries */, 32768)  = 32752 <0.000639>
getdents(3, /* 1055 entries */, 32768)  = 32760 <0.000723>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000731>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.000691>
getdents(3, /* 1051 entries */, 32768)  = 32744 <0.000758>
getdents(3, /* 1050 entries */, 32768)  = 32768 <0.000652>
getdents(3, /* 1047 entries */, 32768)  = 32768 <0.000683>
getdents(3, /* 1049 entries */, 32768)  = 32768 <0.000720>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000724>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.000732>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.000675>
getdents(3, /* 1055 entries */, 32768)  = 32752 <0.000714>
getdents(3, /* 1048 entries */, 32768)  = 32768 <0.000670>
getdents(3, /* 1048 entries */, 32768)  = 32744 <0.000753>
getdents(3, /* 1051 entries */, 32768)  = 32744 <0.000669>
getdents(3, /* 1048 entries */, 32768)  = 32744 <0.000792>
getdents(3, /* 1052 entries */, 32768)  = 32760 <0.000729>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000639>
getdents(3, /* 1053 entries */, 32768)  = 32744 <0.000770>
getdents(3, /* 1049 entries */, 32768)  = 32760 <0.000770>
getdents(3, /* 1053 entries */, 32768)  = 32768 <0.000631>
getdents(3, /* 1051 entries */, 32768)  = 32768 <0.000691>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.000734>
getdents(3, /* 1050 entries */, 32768)  = 32752 <0.000741>
getdents(3, /* 1051 entries */, 32768)  = 32760 <0.000676>
getdents(3, /* 1050 entries */, 32768)  = 32752 <0.000679>
getdents(3, /* 1045 entries */, 32768)  = 32752 <0.000785>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000643>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000670>
getdents(3, /* 1048 entries */, 32768)  = 32768 <0.000743>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000728>
getdents(3, /* 1045 entries */, 32768)  = 32760 <0.000670>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000692>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000685>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000808>
getdents(3, /* 1052 entries */, 32768)  = 32744 <0.000618>
getdents(3, /* 1048 entries */, 32768)  = 32768 <0.000685>
getdents(3, /* 1054 entries */, 32768)  = 32768 <0.000720>
getdents(3, /* 1050 entries */, 32768)  = 32768 <0.000737>
getdents(3, /* 1052 entries */, 32768)  = 32744 <0.000708>
getdents(3, /* 1052 entries */, 32768)  = 32768 <0.000630>
getdents(3, /* 1047 entries */, 32768)  = 32744 <0.000731>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000758>
getdents(3, /* 1048 entries */, 32768)  = 32768 <0.000688>
getdents(3, /* 1049 entries */, 32768)  = 32768 <0.000760>
getdents(3, /* 1049 entries */, 32768)  = 32760 <0.000695>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000663>
getdents(3, /* 1050 entries */, 32768)  = 32768 <0.000695>
getdents(3, /* 1048 entries */, 32768)  = 32760 <0.000731>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.000667>
getdents(3, /* 1047 entries */, 32768)  = 32768 <0.000762>
getdents(3, /* 1048 entries */, 32768)  = 32744 <0.000744>
getdents(3, /* 1056 entries */, 32768)  = 32760 <0.000640>
getdents(3, /* 1053 entries */, 32768)  = 32752 <0.000790>
getdents(3, /* 1052 entries */, 32768)  = 32768 <0.000693>
getdents(3, /* 1051 entries */, 32768)  = 32768 <0.000661>
getdents(3, /* 1047 entries */, 32768)  = 32752 <0.000748>
getdents(3, /* 1054 entries */, 32768)  = 32768 <0.000665>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000687>
getdents(3, /* 1054 entries */, 32768)  = 32760 <0.000712>
getdents(3, /* 1056 entries */, 32768)  = 32768 <0.000803>
getdents(3, /* 1053 entries */, 32768)  = 32760 <0.000685>
getdents(3, /* 1051 entries */, 32768)  = 32744 <0.000761>
getdents(3, /* 1053 entries */, 32768)  = 32744 <0.000681>
getdents(3, /* 1046 entries */, 32768)  = 32752 <0.000706>
getdents(3, /* 1049 entries */, 32768)  = 32744 <0.000784>
getdents(3, /* 1048 entries */, 32768)  = 32760 <0.000692>
getdents(3, /* 1043 entries */, 32768)  = 32760 <0.000707>
getdents(3, /* 1053 entries */, 32768)  = 32768 <0.000713>
getdents(3, /* 1053 entries */, 32768)  = 32744 <0.000662>
getdents(3, /* 1049 entries */, 32768)  = 32768 <0.000706>
getdents(3, /* 1046 entries */, 32768)  = 32752 <0.000695>
getdents(3, /* 1047 entries */, 32768)  = 32768 <0.000747>
getdents(3, /* 1050 entries */, 32768)  = 32744 <0.000814>
getdents(3, /* 1052 entries */, 32768)  = 32752 <0.000704>
getdents(3, /* 1048 entries */, 32768)  = 32744 <0.000669>
getdents(3, /* 1049 entries */, 32768)  = 32752 <0.000712>
getdents(3, /* 1048 entries */, 32768)  = 32744 <0.000659>
getdents(3, /* 1050 entries */, 32768)  = 32760 <0.000713>
getdents(3, /* 1050 entries */, 32768)  = 32744 <0.000716>
getdents(3, /* 1052 entries */, 32768)  = 32760 <0.000631>
getdents(3, /* 1050 entries */, 32768)  = 32760 <0.000717>
getdents(3, /* 1050 entries */, 32768)  = 32744 <0.000710>
getdents(3, /* 1054 entries */, 32768)  = 32768 <0.000730>
getdents(3, /* 1054 entries */, 32768)  = 32768 <0.000736>
getdents(3, /* 1051 entries */, 32768)  = 32760 <0.000652>
getdents(3, /* 1053 entries */, 32768)  = 32744 <0.000685>
getdents(3, /* 1049 entries */, 32768)  = 32760 <0.000718>
getdents(3, /* 1050 entries */, 32768)  = 32752 <0.000718>
getdents(3, /* 265 entries */, 32768)   = 8264 <0.000154>
getdents(3, /* 0 entries */, 32768)     = 0 <0.000022>

getdents システムコールの一回あたりの時間を見てみると、あんまり変わらない？

[yazekats@yazekats-linux work]$ perl -lane '/getdents/ and $F[8]=~s/[<>]//g and $s+=$F[8];END{print $s}' strace_ls.log 
0.069295
[yazekats@yazekats-linux work]$ perl -lane '/getdents/ and $F[8]=~s/[<>]//g and $s+=$F[8];END{print $s}' strace_ls-f.log 
0.06873

合計してみても、やはりあんまり差がない。何度か strace -c を見ていると ls と ls -f で差はないようで、sys の差は getdents システムコールによるものではないかも。


追記(2014/03/15):
id:ya--mada さんに

rh系なら /usr/bin/time -v の結果みて比較したいかな。/掘り下げ方が勉強になる。

はてなブックマーク - ls のソースを読んでプログラマになりました - ablog

とブックマークでコメントいただいたので、試してみた。

[yazekats@yazekats-linux tmp]$ time -v ls
bash: -v: command not found

real	0m0.002s
user	0m0.000s
sys	0m0.001s

ほげっ。time の man を見てみると、

$ man time
       Note: some shells (e.g., bash(1)) have a built-in time command that provides less functionality than the command described here.  To access the
       real command, you may need to specify its pathname (something like /usr/bin/time).

何も考えずに実行していた time は bash のビルトインコマンドだった。そもそも、ブックマークのコメントに「/usr/bin/time -v 」って書いているしw 気を取り直して、

  • ls
[yazekats@yazekats-linux tmp]$ /usr/bin/time -v ls
	Command being timed: "ls"
	User time (seconds): 0.18
	System time (seconds): 0.11
	Percent of CPU this job got: 21%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 0:01.40
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 95744
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 0
	Minor (reclaiming a frame) page faults: 6030
	Voluntary context switches: 83
	Involuntary context switches: 36766
	Swaps: 0
	File system inputs: 0
	File system outputs: 0
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0
  • ls -f
[yazekats@yazekats-linux tmp]$ /usr/bin/time -v ls -f
	Command being timed: "ls -f"
	User time (seconds): 0.13
	System time (seconds): 0.11
	Percent of CPU this job got: 17%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 0:01.36
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 94192
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 0
	Minor (reclaiming a frame) page faults: 5932
	Voluntary context switches: 85
	Involuntary context switches: 28150
	Swaps: 0
	File system inputs: 0
	File system outputs: 0
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0

あわせて読みたい

*1:500万ページビュー突破記念で適当なタイトルにしますた