タイトルは釣りです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 と同じ順になった。
そう言えば、
- 作者: 藤原克則
- 出版社/メーカー: 秀和システム
- 発売日: 2013/09/20
- メディア: 単行本
- この商品を含むブログ (14件) を見る
[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万ページビュー突破記念で適当なタイトルにしますた