\time
昔読んだ本に、『カッコウはコンピューターに卵を産む』ってのがあった。確かカリフォーニアに住む天文学者が、クラッカーを追い詰めた記録を、小説にしたものだった。
上から回って来る、コンピュータの使用請求書が、自分で管理してるデータより僅かに多かった。なんで？ コンピュータが間違えるはず無いしな。そこから長い長い追跡劇が始まる。
今のコンピュータだと、そんな機能が入っているのかな？ スパコンなんかだと使い放題って訳にもいかないだろうから、歯止めとして、そういう機構が入っていて、割り当てられた分だけ使うと、以後は使えなくなるとかなってるのかな？
ちょいと調べてみる。えーと、アカウント(会計)かな？
NAME
ac - connect time accounting
/var/log/wtmpから引っ張り出した、接続時間。
ob6$ ac -d sakae Aug 1 total 3.84 Aug 2 total 2.14 Aug 3 total 3.76 Aug 4 total 3.26 :
で、他のコマンドとして、saなんてもの紹介された。acctonで、会計データの収録を始める。 溜まったデータをsaで確認出来るとな。
avio Average number of I/O operations per execution.
cp Sum of user and system time, in minutes.
cpu Same as cp.
k CPU time averaged core usage, in 1k units.
k*sec CPU storage integral, in 1k-core seconds.
re Real time, in minutes.
s System time, in minutes.
tio Total number of I/O operations.
u User time, in minutes.
acより格段に細かいデータが得られる。それに、どんなコマンドを投入したかも丸見えみたいだ。NetBSDの時代にこのコマンドが実装されたってなってた。時代で言うと、1993年か。
カッコウはコンピュータに卵を産むの読後録によると、事件が起きたのは1987年と言う事なんで、PC-UNIXってのはあり得ない。VAXが主役の時代だな、と懐かしんでおります。
WSLって速いの？
以前に入れた、Windows10で使えるリナちゃん、WSL。入れた時に体感的に遅いぞと思ったものだ。どのぐらい遅いか、一応暴いておく。例のファイル似てる度のアプリでね。
sakae@atom:/mnt/c/work$ time jot -b 'li.c li.c' 100 | xargs -L 1 ./aa.sh real 0m9.727s user 0m0.875s sys 0m7.703s sakae@atom:/mnt/c/work$ time jot -b 'li.c li.c' 100 | xargs -L 1 -P 4 ./aa.sh real 0m6.611s user 0m1.313s sys 0m8.047s
Windows10だと、４つの石が素直に使えるはずなんで、４パラ運用したけど、むちゃ遅い。 topで１して、４個の石にプロセスが振り分けられている事は、確認出来るんだけどね。
Windows10のタスクマネージャーを起動して、CPUの利用率を見ると、100%になってる。これはもう暴走状態と言ってもいいぐらいの暴れっぷり。その割には大した仕事をしてないんだけどね。
それは、そうと、bashに備え付けのtimeじゃ、詳細分からんぞ。
sakae@atom:/mnt/c/work$ \time jot -b 'li.c li.c' 100 | xargs -L 1 -P 4 ./aa.sh -bash: time: command not found Runtime error (func=(main), adr=14): Divide by zero Runtime error (func=(main), adr=14): Divide by zero (standard_in) 1: syntax error sakae@atom:/mnt/c/work$ /usr/bin/time jot -b 'li.c li.c' 100 | xargs -L 1 -P 4 ./aa.sh -bash: /usr/bin/time: No such file or directory Runtime error (func=(main), adr=14): Divide by zero Runtime error (func=(main), adr=14): Divide by zero (standard_in) 1: syntax error
内蔵コマンド（やalias)を無効にするには、コマンドの冒頭にバックスラッシュを置くのがしきたり。そうやったら、わけわかめな事を言われたので、フルパスで指定したら、そんなコマンド入ってないぞと言われた。Debianの最小構成だと、シス管ぽいコマンドは入っていない訳ね。
入れるのはやぶさかでないけど、timeってどう動いているか、最初に確認しとくかな。 そうじゃないと、ボーっと生きてんじゃないよと、NHKのチコちゃんに叱られる！しまいますからね。
まずはBSD系で
ob6$ \time -l emacs --version
GNU Emacs 25.3.1
:
0.29 real 0.00 user 0.20 sys
3260 maximum resident set size
0 average shared memory size
0 average unshared data size
0 average unshared stack size
277 minor page faults
444 major page faults
0 swaps
206 block input operations
0 block output operations
0 messages sent
0 messages received
0 signals received
133 voluntary context switches
2 involuntary context switches
へぇー、Net系のやり取りも把握してるんだ。ならば、
ob6$ \time -l curl -O http://space.geocities.jp/hamesspam
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 3176 100 3176 0 0 28106 0 --:--:-- --:--:-- --:--:-- 28872
0.18 real 0.00 user 0.05 sys
3996 maximum resident set size
0 average shared memory size
0 average unshared data size
0 average unshared stack size
781 minor page faults
148 major page faults
0 swaps
36 block input operations
6 block output operations
3 messages sent
3 messages received
0 signals received
39 voluntary context switches
5 involuntary context switches
3 messages って、パケット数の事かな？
Ubuntでは、どうよ？
sakae@usvr:/tmp$ cat x
jot -b 'li.c li.c' 100 | xargs -L 1 -P 4 ./aa.shsakae@usvr:/tmp
sakae@usvr:/tmp$ \time -v sh x
Command being timed: "sh x"
User time (seconds): 1.16 (1.29)
System time (seconds): 0.32 (8.95)
Percent of CPU this job got: 196% (148%)
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.75 (0:06.88)
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): 2284 (868)
Average resident set size (kbytes): 0
Major (requiring I/O) page faults: 0
Minor (reclaiming a frame) page faults: 166126 (405124)
Voluntary context switches: 5918 (0)
Involuntary context switches: 3269 (0)
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 (4096)
Exit status: 0
注） 右側にカッコ付で表示したデータは、WSLの結果。
実時間は、0.75秒しかかかっていない。WSLでは、6.88秒って事だから、どんだけ遅いんや！ 実用にしようったって、無理な相談だな。
メモリーが2284K使われた。I/Oに伴うページフォルトは発生してない。それ以外のページフォルトが166126回発生した。
自発的なコンテキストスイッチが5918回発生。これは、処理するデータが流れてこなかったんで、制御を他（のプロセス）に回すように申告されたって事だな。
3269回制御が取り上げられている。プロセスが調子よく実行されていたけど、その回の時間割り当て(通常は10ms)を超過したんで、他のプロセスに強制的に切り替えられたとな。
さあさあ、WSLの駄目さ加減を考察する時間です。
遅いのは、システム時間です。これが諸悪の根源です。WSLの限界を示しています。システム時間って事は、カーネル内で費やされた時間。Debian側から見れば、システムコールの処理がめちゃくちゃかかっている事になる。
Windows側がDebianのシステムコールを肩代わりして実行してるから。肩代わりって事は、システムコールをWindowsのシステムコール（そう言うのかは知らないけど）に変換して、Windowsで実行。その結果をDebian側に返す。これに手間がかかっているんだ。
そして有志の実験によれば、WSLが扱うファイル群が、WSLの領域にあるか、/mnt/c/xxx側に 有るかによって、スピードが数倍違うとの事。勿論遅い方は、/mntを介してのアクセス。ntfsのファイルシステムを一度ext4に翻訳するという無茶ぶりを強いられるからね。
でも、これってWSL側のキャッシュに載ってしまえば、関係無いんと違うかな。オイラーの例だと、十分にキャッシュに載ってると思うんだけどな。それでも遅いって事は、そんなの有難がって使うなって事だな。緊急避難的に使うのはしょうがないけど。
コンテキストスイッチが一切発生していない（ように見える）けど、これってどうなのよ。それじゃ、debian側が動作出来ないはずだけどな。そこまでの実装（真似）は、諦めているのかな？
どんな風にして、これらのデータを採取してるか、ソース嫁だな。
apt source time
大事な事だから、表題にしときましたからね。(/etc/apt/sources.listで、sourceを有効にしておく事）
色々なファイルが有るけど、見る（読む）のは、time.cだけで十分。
pid = fork (); /* Run CMD as child process. */
if (pid < 0)
error (1, errno, "cannot fork");
else if (pid == 0)
{ /* If child. */
/* Don't cast execvp arguments; that causes errors on some systems,
versus merely warnings if the cast is left off. */
execvp (cmd[0], cmd);
error (0, errno, "cannot run %s", cmd[0]);
_exit (errno == ENOENT ? 127 : 126);
}
forkしてexecveするのは、Unixの定番処理。ってか、これしかない。親の方は、wait3で子が終了するのを待つ。wait3が無ければwaitで待つ。(configure時に決定） そして、wait3から復帰すると、子のリソース使用状況（上記結果の元データ）が得られるので、それを整形して表示。 このwaitの部分の詳細は、resuse.cに置いてある。
if (resuse_end (pid, resp) == 0)
error (1, errno, "error waiting for child process");
親の方の子終了待ち。子が終了すれば、結果がrespに入ってる。 resp構造体のメンバーが、コメント付きで列挙されてた。（一部を掲載）
* E == elapsed real (wall clock) time in [hour:]min:sec * F == major page faults (required physical I/O) (ru_majflt) * K == average total mem usage (ru_idrss+ru_isrss+ru_ixrss) * M == maximum resident set size in K (ru_maxrss) * P == percent of CPU this job got (total cpu time / elapsed time) * R == minor page faults (reclaims; no physical I/O involved) (ru_minflt) * S == system (kernel) time (seconds) (ru_stime) * U == user time (seconds) (ru_utime) * c == involuntary context switches (ru_nivcsw) e == elapsed real time in seconds * r == socket messages received (ru_msgrcv) * s == socket messages sent (ru_msgsnd) t == average resident set size in K (ru_idrss) * w == voluntary context switches (ru_nvcsw) (* means the tcsh time builtin also recognizes it)
コンテキスト情報の取得がWSLでなされていない疑惑。どんなに大変な作業が検証してみるかな。それには、カーネル側のソースに当たる必要が有る。
オイラーもOpenBSDにコンテキストスイッチしましょ。
その前に、折角ソースが有るんで、料理して味わってみましょ。
(gdb) b resuse_end
Breakpoint 1 at 0x21fb: file resuse.c, line 75.
(gdb) r sh x
Starting program: /tmp/a.out sh x
Breakpoint 1, resuse_end (pid=28781, resp=0x7fffffffe330) at resuse.c:75
75 {
(gdb) p *resp
$1 = {waitstatus = 0, ru = {ru_utime = {tv_sec = 140737354131216,
tv_usec = 140737349515143}, ru_stime = {tv_sec = 0,
tv_usec = 140737488348032}, {ru_maxrss = 140737488348048,
__ru_maxrss_word = 140737488348048}, {ru_ixrss = 140737354132120,
__ru_ixrss_word = 140737354132120}, {ru_idrss = 0, __ru_idrss_word = 0},
{ru_isrss = 0, __ru_isrss_word = 0}, {ru_minflt = 140737488348064,
__ru_minflt_word = 140737488348064}, {ru_majflt = 4294967295,
__ru_majflt_word = 4294967295}, {ru_nswap = 0, __ru_nswap_word = 0}, {
ru_inblock = 140737354113640, __ru_inblock_word = 140737354113640}, {
ru_oublock = 140737354131216, __ru_oublock_word = 140737354131216}, {
ru_msgsnd = 0, __ru_msgsnd_word = 0}, {ru_msgrcv = 0,
__ru_msgrcv_word = 0}, {ru_nsignals = 0, __ru_nsignals_word = 0}, {
ru_nvcsw = 1970169159, __ru_nvcsw_word = 1970169159}, {ru_nivcsw = 9,
__ru_nivcsw_word = 9}}, start = {tv_sec = 1534580364, tv_usec = 487949},
elapsed = {tv_sec = 15775231, tv_usec = 1}}
wait3を呼び出している関数にBPを置いて走らせてみた。そして結果を持ち帰る構造体の中身を確認。まだその中は埋められていないので、めちゃくちゃな値が入っている。
respの元を辿れば、mainの中で宣言された変数だから、その時にスタック上はどんな値になってたかは不明と言うか不定だ。
(gdb) finish
Run till exit from #0 resuse_end (pid=16034, resp=0x7fffffffe330)
at resuse.c:75
0x0000555555555453 in run_command (resp=0x7fffffffe330, cmd=<optimized out>)
at time.c:623
623 if (resuse_end (pid, resp) == 0)
Value returned is $2 = 1
(gdb) p *resp
$3 = {waitstatus = 0, ru = {ru_utime = {tv_sec = 1, tv_usec = 475242},
ru_stime = {tv_sec = 0, tv_usec = 427560}, {ru_maxrss = 2164,
__ru_maxrss_word = 2164}, {ru_ixrss = 0, __ru_ixrss_word = 0}, {
ru_idrss = 0, __ru_idrss_word = 0}, {ru_isrss = 0, __ru_isrss_word = 0},
{ru_minflt = 167166, __ru_minflt_word = 167166}, {ru_majflt = 0,
__ru_majflt_word = 0}, {ru_nswap = 0, __ru_nswap_word = 0}, {
ru_inblock = 0, __ru_inblock_word = 0}, {ru_oublock = 0,
__ru_oublock_word = 0}, {ru_msgsnd = 0, __ru_msgsnd_word = 0}, {
ru_msgrcv = 0, __ru_msgrcv_word = 0}, {ru_nsignals = 0,
__ru_nsignals_word = 0}, {ru_nvcsw = 5908, __ru_nvcsw_word = 5908}, {
ru_nivcsw = 3352, __ru_nivcsw_word = 3352}}, start = {
tv_sec = 1534915576, tv_usec = 792506}, elapsed = {tv_sec = 24,
tv_usec = 421744}}
関数を実行終了させてから、構造体の中身を確認。今度はそれなりの値が入ってるっぽい。
(gdb) c Continuing. 1.47user 0.42system 0:24.42elapsed 7%CPU (0avgtext+0avgdata 8656maxresident)k 0inputs+0outputs (0major+167166minor)pagefaults 0swaps [Inferior 1 (process 16030) exited normally]
timeコマンドに任せて、結果を印刷。
proc
複数のプロセスが動く時（パイプ等）に、それらのプロセスはどう扱われるかと思って調べてみたよ。
/usr/bin/time in OpenBSD
while (wait3(&status, 0, &ru) != pid)
;
親プロセス側(/usr/bin/time)が、子プロセスの終了を待つ。リナのtimeと違って、wait3の決め打ち。なんで３が付いているかと言うと、引数が３個のwaitだから。実に安易な名前付け。 （昔で言うなら、一番最初の子は、一郎、二番目は二郎みたいなもんだな。）
システムコールで扱ってるのは、引数の数が一番多い wait4 だったりする。コードは、kern_exit.c に置かれてた。終活だな。終活内容は、子のリソース使用状況構造体を解放する事。その為のwaitだったりする。ある意味、子が死ぬのを待ち続ける怖い親でもある。
親が先にいなくなると、この終活が出来ず、俗に言うゾンビになって、システムが停止するまで 居座る事になる。
子プロセスの活動状況は、ruって所に格納されて返る。statusには、子プロセスの終了ステータスが入っている。
問題と言うか注目は、ruの中身と言うか構造体名 rusage。
sys/resorce.sh
struct rusage {
struct timeval ru_utime; /* user time used */
struct timeval ru_stime; /* system time used */
long ru_maxrss; /* max resident set size */
#define ru_first ru_ixrss
long ru_ixrss; /* integral shared text memory size */
long ru_idrss; /* integral unshared data " */
long ru_isrss; /* integral unshared stack " */
long ru_minflt; /* page reclaims */
long ru_majflt; /* page faults */
long ru_nswap; /* swaps */
long ru_inblock; /* block input operations */
long ru_oublock; /* block output operations */
long ru_msgsnd; /* messages sent */
long ru_msgrcv; /* messages received */
long ru_nsignals; /* signals received */
long ru_nvcsw; /* voluntary context switches */
long ru_nivcsw; /* involuntary " */
#define ru_last ru_nivcsw
};
accton, sa
冒頭に出て来た会計をNetBSDでやってみた。会計システムをonにする為の儀式がまず必要との事。manによると、
acctonコマンドをrootで実行しろ。引数は、会計データを保存するファイル。指定しなければ、/var/account/acctってファイルが使われる。次に、/etc/rc.confに、accounting=YESと書いておいて、rebootしろ。これで、会計データの収録が始まる。
lastcommで、どんなコマンドを実行したか、もれなく確認出来る。
nb8$ lastcomm cron -F root __ 0.00 secs Thu Aug 30 06:10 (0:00:00.00) sh - root __ 0.00 secs Thu Aug 30 06:10 (0:00:00.00) atrun - root __ 0.00 secs Thu Aug 30 06:10 (0:00:00.00) cron -F root __ 0.00 secs Thu Aug 30 06:00 (0:00:10.06) sh - root __ 0.00 secs Thu Aug 30 06:00 (0:00:10.06) newsyslog - root __ 0.02 secs Thu Aug 30 06:00 (0:00:10.05) : rm - root pts/1 0.00 secs Thu Aug 30 05:51 (0:00:00.00) calendar - root pts/1 0.00 secs Thu Aug 30 05:51 (0:00:00.00) sa - root pts/1 0.00 secs Thu Aug 30 05:51 (0:00:00.00)
起動時の早い段階からログされてるよ。
nb8$ sa
277 17.95re 0.02cp 0avio 0k
24 0.02re 0.02cp 0avio 0k ***other
106 2.32re 0.00cp 0avio 0k sh*
2 0.20re 0.00cp 0avio 0k sshd*
5 4.10re 0.00cp 0avio 0k lv
22 3.99re 0.00cp 0avio 0k sh
:
nb8$ sa -m root 212 0.02cpu 0tio 0k*sec postfix 1 0.00cpu 0tio 0k*sec sshd 1 0.00cpu 0tio 0k*sec sakae 81 0.00cpu 0tio 0k*sec
これが請求書になるんだな。sshdとかpostfixなんていう公共財は誰に請求が行くのかな？
man 5 acctによると
struct acct {
char ac_comm[10]; /* name of command */
comp_t ac_utime; /* user time */
comp_t ac_stime; /* system time */
comp_t ac_etime; /* elapsed time */
time_t ac_btime; /* starting time */
uid_t ac_uid; /* user id */
gid_t ac_gid; /* group id */
short ac_mem; /* memory usage average */
comp_t ac_io; /* count of IO blocks */
dev_t ac_tty; /* controlling tty */
char ac_flag; /* accounting flags */
};
こんな形式で、ログデータが埋められているみたいですなあ。クラッカーだと、これを改竄して、自分への請求を減らしたりするんだな。そういうのは、クラッカーじゃなくてても、悪徳官僚がよくやる手口です。ログが膨大になるんで、多少間引いても、ばれないだろうって心理が働くに違いない。