最近、社内開催のOS勉強会に参加することもあり、何かOSを理解する上でパッと分かりやすいカーネル処理が無いかなと考えていたところ、time コマンド の動きを追うのが良いんじゃないかとふと思いつきました。理由は以下の通り。
- Linux を触る人なら恐らく誰でも使ったことがある
- 関連する man マニュアルの説明は（どちらかと言うと）詳細で分かりやすい
- ユーザー/システムCPU時間がユーザー/カーネルモードに対応しており、カーネルを理解した気分になれる
というわけで、time コマンドの内部動作を追いかけて、計測される時間が何を意味するのか確認してみましょう。仕組みは至って単純ですが、カーネルのお仕事の一端が垣間見れるはず。カーネルソースの追いかけ方がなんとなく理解してもらえたら、と思います。
以下、ソースコードを追いかけながら書いてるのでかなり長くなっており、すごく細かい所・大雑把な説明入り混じってますがご容赦ください。まとめとあとがきだけでも読んでいただけたら幸いです。
基本的に Ubuntu 16.04 LTS での動作と、ベースカーネルである Linux-4.4 のカーネルソースを元にしています。
#time コマンドの種類
time コマンドには以下の２種類があります。
-
GNU の time コマンド
- ソース http://git.savannah.gnu.org/cgit/time.git/
- usage は
man time(又は man マニュアル) で確認できる
- シェルの組み込み (builtin) コマンド
- 例: GNU bash
- usage は
help timeで確認できる
Ubuntu 16.04 の場合、apt で time パッケージがインストールされていれば which コマンドを使うと以下のように 1. の方が表示されるはずです。
$ which time
/usr/bin/time
しかし、実際に time を実行すると 2. が使用されています。この時、1. の time コマンドを使うなら絶対パスで指定する必要があります。どちらを使っているかは、組み込みコマンドの type で判別できます。
$ time sleep 1
real 0m1.001s
user 0m0.000s
sys 0m0.004s
$ /usr/bin/time sleep 1
0.00user 0.00system 0:01.00elapsed 0%CPU (0avgtext+0avgdata 1628maxresident)k
0inputs+0outputs (0major+67minor)pagefaults 0swaps
$ type time
time はシェルの予約語です
$ type /usr/bin/time
/usr/bin/time は /usr/bin/time です
GNU time コマンドの方が実行時間以外にも色々使用したリソース情報が表示できるので使い勝手は良いと思います。表示内容のフォーマットは -f オプションで指定できるので、詳細は man マニュアルで確認してみてください。
ユーザーランド処理
time コマンドの処理としては、引数に指定したプログラムのプロセス生成前から終了後でそれぞれ real, user, sys 時間を取得しておき、その差を表示しているだけです。使用していたシステムコールは以下の通り。
| 取得したい時間 | 使用していた syscall |
|---|---|
| real |
gettimeofday(2), times(2)
|
| user/sys |
getrusage(2), wait3(2) (注), times(2)
|
(注) wait3(2) の場合、子プロセスの使用したリソース情報そのものが取得されるため差分を取る必要はありません。
具体的に time コマンド 内部でどんな処理が行われているのでしょう？
以下では time-1.7.2 パッケージのソースコードを抜粋してみます。bash の builtin 部分は少し見辛いので割愛しますが、上記２種類の time コマンド内部処理はどちらもほぼ同じです。
main 処理は time.c。作りはシンプルで、関数 run_command() で時間を計測したいプログラムを教科書的に fork(2) -> exec(2) し、その前後で resuse_start(), resuse_end() という関数を呼び出してます。これらの関数が時刻取得処理で、定義は resuse.c にあります。time コマンド のプロセス自体は、生成した子プロセスを wait するだけで、子プロセス生成〜終了間は何もしません。
void
main (argc, argv)
int argc;
char **argv;
{
const char **command_line;
RESUSE res;
command_line = getargs (argc, argv);
run_command (command_line, &res);
summarize (outfp, output_format, command_line, &res);
fflush (outfp);
if (WIFSTOPPED (res.waitstatus))
exit (WSTOPSIG (res.waitstatus));
else if (WIFSIGNALED (res.waitstatus))
exit (WTERMSIG (res.waitstatus));
else if (WIFEXITED (res.waitstatus))
exit (WEXITSTATUS (res.waitstatus));
}
/* Run command CMD and return statistics on it.
Put the statistics in *RESP. */
static void
run_command (cmd, resp)
char *const *cmd;
RESUSE *resp;
{
pid_t pid; /* Pid of child. */
sighandler interrupt_signal, quit_signal;
resuse_start (resp);
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);
}
/* Have signals kill the child but not self (if possible). */
interrupt_signal = signal (SIGINT, SIG_IGN);
quit_signal = signal (SIGQUIT, SIG_IGN);
if (resuse_end (pid, resp) == 0)
error (1, errno, "error waiting for child process");
/* Re-enable signals. */
signal (SIGINT, interrupt_signal);
signal (SIGQUIT, quit_signal);
}
/* Prepare to measure a child process. */
void
resuse_start (resp)
RESUSE *resp;
{
#if HAVE_WAIT3
gettimeofday (&resp->start, (struct timezone *) 0);
#else
long value;
struct tms tms;
value = times (&tms);
resp->start.tv_sec = value / HZ;
resp->start.tv_usec = value % HZ * (1000000 / HZ);
#endif
}
/* Wait for and fill in data on child process PID.
Return 0 on error, 1 if ok. */
#if __STDC__
/* pid_t is short on BSDI, so don't try to promote it. */
int
resuse_end (pid_t pid, RESUSE *resp)
#else
int
resuse_end (pid, resp)
pid_t pid;
RESUSE *resp;
#endif
{
int status;
#if HAVE_WAIT3
pid_t caught;
/* Ignore signals, but don't ignore the children. When wait3
returns the child process, set the time the command finished. */
while ((caught = wait3 (&status, 0, &resp->ru)) != pid)
{
if (caught == -1)
return 0;
}
gettimeofday (&resp->elapsed, (struct timezone *) 0);
#else /* !HAVE_WAIT3 */
long value;
struct tms tms;
pid = wait (&status);
if (pid == -1)
return 0;
value = times (&tms);
memset (&resp->ru, 0, sizeof (struct rusage));
resp->ru.ru_utime.tv_sec = tms.tms_cutime / HZ;
resp->ru.ru_stime.tv_sec = tms.tms_cstime / HZ;
#if HAVE_SYS_RUSAGE_H
resp->ru.ru_utime.tv_nsec = tms.tms_cutime % HZ * (1000000000 / HZ);
resp->ru.ru_stime.tv_nsec = tms.tms_cstime % HZ * (1000000000 / HZ);
#else
resp->ru.ru_utime.tv_usec = tms.tms_cutime % HZ * (1000000 / HZ);
resp->ru.ru_stime.tv_usec = tms.tms_cstime % HZ * (1000000 / HZ);
#endif
resp->elapsed.tv_sec = value / HZ;
resp->elapsed.tv_usec = value % HZ * (1000000 / HZ);
#endif /* !HAVE_WAIT3 */
resp->elapsed.tv_sec -= resp->start.tv_sec;
if (resp->elapsed.tv_usec < resp->start.tv_usec)
{
/* Manually carry a one from the seconds field. */
resp->elapsed.tv_usec += 1000000;
--resp->elapsed.tv_sec;
}
resp->elapsed.tv_usec -= resp->start.tv_usec;
resp->waitstatus = status;
return 1;
}
/* Information on the resources used by a child process. */
typedef struct
{
int waitstatus;
struct rusage ru;
struct timeval start, elapsed; /* Wallclock time of process. */
} RESUSE;
計測時間の出力は main() で呼び出す summarize() で処理されますが、計算は resuse_end() 処理で完了済み。したがって、時間と変数の対応関係は以下の通り。
| 時間 | real | user | sys |
|---|---|---|---|
| 変数 | resp->elapsed | resp->ru.ru_utime | resp->ru.ru_stime |
| 型 | struct timeval |
struct timeval (struct rusage のメンバ変数 ru_utime) |
struct timeval (struct rusage のメンバ変数 ru_stime) |
注）一般的な struct rusage の定義は getrusage(2) の man マニュアルを参照
|
real の時間の意味は分かりやすいと思います。
time コマンドのプロセスが親プロセス、time コマンドから生成されたプロセスが子プロセスとなり gettimeofday(2) は現在時刻を取得するのだから、取得した時刻の差分にはおよそ以下の処理が実行されています。
-
fork(2)による子プロセス生成
-
exec(2)によるプロセスイメージ置き換え - 親プロセスの休眠 (
wait(2)で待っている) - 子プロセスの処理
- 子プロセス終了後にシグナル SIGCHLD を受信して親プロセスが起床 (
wait(2)のところから復帰)
細かいですが、times(2) が使われる場合は返り値がクロック数 (tick) となるので HZ (1/HZ 秒毎に 1 ずつ増える Linux カーネルのグローバル変数が jiffies で tick と呼ばれたりする、詳しくはググッてほしい) で割ってます。結局意味は同じ。
以上から、real は、生成した子プロセスの実際の処理時間だけでなく、親プロセス側の処理 (fork(2), exec(2), シグナル受信など) も含んでおり、かつ、子プロセス処理中のタスクスイッチ・割り込み処理時間も含む可能性があります。つまり、子プロセスの処理時間計測としては不正確であるということに注意が必要というわけです。
それに対し、user/sys は times(2), wait3(2) により取得されていますが、ユーザーランドの処理だけみても何の処理時間をどうやって計測しているか全く分かりません。ここを詳しく見るにはカーネルランド処理を確かめる必要がでてきます。
カーネルランド処理
アプリケーション (この場合は time コマンド) に関わるカーネルランド処理とは、基本的にアプリが呼び出した各システムコールの中の処理のこと指すと思っておけば間違いではないです。一般的な OS 講義では「システムコールはカーネルの入り口」とか「OSへの仕事を依頼する方法」など説明を受けているかもしれません。
そこで、カーネル内で実際に user/sys をどう計算しているかを追いかけてみましょう。「消費したCPU時間」というのはプロセスが実際に CPU を使用した時間のことで、タスクスケジューリングにも密接に関わっていますが、今回はそこまで踏み込まないでおきます。
システムコール time(2) の処理
man マニュアルに書いてあるとおり wait3(2) はレガシーコードとして削除されているので、ひとまず times(2) の処理をみてみます。
今の所、システムコールがどのように呼び出されるかは気にしなくて良いです。引数が一つのシステムコールは SYSCALL_DEFINE1() というマクロが使われるので、times(2) の呼び出しでカーネル内で実行されるのは SYSCALL_DEFINE1(times, struct tms __user *, tbuf) となります。メイン処理は do_sys_times() ですが、これも値の代入だけで時間の計算方法はまだ分かりません。
（注）知らない人のための注釈。current とは、現在CPUを使用中のプロセスの struct task_struct へのポインタなので、システムコールを発行した time コマンドのプロセスの task_struct を指していることになります。
確認したいのは子プロセスのリソース情報なので cutime (恐らく child user time の略), cstime (同じく child system time の略) がどう計算されるかを見ればよい。current->signal->cutime の signal とは何かということも注目すべきことの一つ。
SYSCALL_DEFINE1(times, struct tms __user *, tbuf)
{
if (tbuf) {
struct tms tmp;
do_sys_times(&tmp);
if (copy_to_user(tbuf, &tmp, sizeof(struct tms)))
return -EFAULT;
}
force_successful_syscall_return();
return (long) jiffies_64_to_clock_t(get_jiffies_64());
}
void do_sys_times(struct tms *tms)
{
cputime_t tgutime, tgstime, cutime, cstime;
thread_group_cputime_adjusted(current, &tgutime, &tgstime);
cutime = current->signal->cutime;
cstime = current->signal->cstime;
tms->tms_utime = cputime_to_clock_t(tgutime);
tms->tms_stime = cputime_to_clock_t(tgstime);
tms->tms_cutime = cputime_to_clock_t(cutime);
tms->tms_cstime = cputime_to_clock_t(cstime);
}
ポイントは時間の計測がいつ開始されていつ終了するのか、どんなタイミングで加算されているのかということになります。きっと、プロセスの処理時間を計測しているのだから、プロセス生成・削除処理辺りにカギがありそうであること予想できます。
プロセス生成時 (fork) の処理
というわけで、プロセス生成処理をみてみます。
プロセス生成シーケンスは以下の通りで、ソースは kernel/fork.c に集約されてます。copy_process() が子プロセスを生成するメイン処理。１つのプロセスに対する使用リソース管理情報は struct task_struct であることは、なんとなく知っていれば良いでしょう。
copy_process() は親プロセスの task_struct から子プロセスの task_struct を複製する。そして、この処理途中で、ちゃんと utime, stime を 0 に初期化している。これは、fork(2) の man マニュアルに「プロセスの資源利用量 (getrusage(2)) と CPU タイムカウンター (times(2)) が、子プロセスでは 0 にリセットされる。」と書いてある通りの処理ですね。
・プロセス生成シーケンス
fork/vfork/clone システムコール
+-> _do_fork()
+-> copy_process()
# SPARC アーキテクチャなどいくつかのアーキでは上記シーケンスと異なるので注意
/*
* This creates a new process as a copy of the old one,
* but does not actually start it yet.
*
* It copies the registers, and all the appropriate
* parts of the process environment (as per the clone
* flags). The actual kick-off is left to the caller.
*/
static struct task_struct *copy_process(unsigned long clone_flags,
unsigned long stack_start,
unsigned long stack_size,
int __user *child_tidptr,
struct pid *pid,
int trace,
unsigned long tls)
{
・・・（省略）・・・
p->utime = p->stime = p->gtime = 0;
・・・（省略）・・・
}
ここでちょっと思い出してほしいのですが、time コマンドで取得していたのは current->signal->cutime/cstime であって、current->utime/stime ではありませんでした。これは何故でしょう？
struct signal_struct
struct signal_struct の定義には以下のメンバ変数が存在しています。これらをよく見ると、ユーザーランドで使用していた struct rusage の中身に非常に似ていることに気づきます。
実は getrusage(2) で取得できる struct rusage の中身そのものが Linux カーネルの struct signal_struct のメンバ変数として定義されています。これは getrusage(2) の man マニュアルと照らし合わせながら getrusage(2) のソースコード (kernel/sys.c) を読めばすんなり理解できるはずなので説明は省きますが、頭文字に c が付いている変数は子プロセス (child) のリソース情報となっています。
以上からプロセスが使用したリソースのアカウンティング情報は、対応する struct task_struct のメンバ変数 signal_struct signal に集約されているということがわかりました。
ところで、なぜ signal_struct に蓄積しているのでしょうか。恐らくこの理由は、シグナルをプロセスグループに送信したりするという性質上、シグナルを管理する構造体にプロセスグループのリソース情報を置いておくのが便利だったのではないか、と考えられます。
次は、子プロセスが終了するタイミングを捕まえたいので、プロセスが終了するときにリソース情報をどう扱うかに注意してソースを追いかけてみましょう。
/*
* NOTE! "signal_struct" does not have its own
* locking, because a shared signal_struct always
* implies a shared sighand_struct, so locking
* sighand_struct is always a proper superset of
* the locking of signal_struct.
*/
struct signal_struct {
・・・（省略）・・・
/*
* Cumulative resource counters for dead threads in the group,
* and for reaped dead child processes forked by this group.
* Live threads maintain their own counters and add to these
* in __exit_signal, except for the group leader.
*/
seqlock_t stats_lock;
cputime_t utime, stime, cutime, cstime;
cputime_t gtime;
cputime_t cgtime;
struct prev_cputime prev_cputime;
unsigned long nvcsw, nivcsw, cnvcsw, cnivcsw;
unsigned long min_flt, maj_flt, cmin_flt, cmaj_flt;
unsigned long inblock, oublock, cinblock, coublock;
unsigned long maxrss, cmaxrss;
struct task_io_accounting ioac;
/*
* Cumulative ns of schedule CPU time fo dead threads in the
* group, not including a zombie group leader, (This only differs
* from jiffies_to_ns(utime + stime) if sched_clock uses something
* other than jiffies.)
*/
unsigned long long sum_sched_runtime;
・・・（省略）・・・
}
プロセス終了時 (exit) の処理
プロセス終了シーケンスは以下の通りで、ソースは kernel/exit.c にソースは集約されています。シグナルを受けてプロセスが終了する場合も最終的に do_exit() が呼び出されるので、これがメイン処理。プロセス生成時に struct task_struct を作ったので、プロセス終了処理はこれが管理するリソースを解放していく処理となります。
・プロセス終了シーケンス
exit_group システムコール
+-> do_group_exit()
+-> do_exit()
又は、
exit システムコール
+-> do_exit()
使用したプロセスグループのリソース情報は struct signal_struct で集めることは上記に説明した通りで、自プロセスが終了する時はリソースのアカウンティング処理も終了させて親プロセスに情報を引き渡すはずです。その処理がどこにあるかを確認しましょう。
以下から、カーネル内処理がより一層複雑になるので、手抜きですが time コマンド の理解に必要なポイントだけ処理を確認していきます。
子プロセス終了を親プロセスに通知する処理 (exit_notify)
do_exit() 処理の一環で呼び出されている exit_notify() が親プロセスへの通知処理全般を担っています。実際に通知するメイン処理は do_notify_parent() (関数名が表している通りの処理)。この関数が呼ばれると、親プロセスはシグナル SIGCHLD を受けて起床します。
また、ここで重要な変数として autoreap, tsk->exit_state があります。
autoreap は終了したプロセスを自動刈り取りするか、親プロセスに刈り取らせるかを決める変数であり、その結果が tsk->exit_state に反映されます。一般的に sigaction(2) などの設定をせずに、普通に fork(2) を呼び出して子プロセスを作った場合、かつ、子プロセスより親プロセスの終了が後の場合に、子プロセスは親プロセスが刈り取ることになります。その時、autoreap = false となり tsk->exit_state = EXIT_ZOMBIE に設定されます。これがいわゆる「ゾンビプロセス」になった状態です。この場合、親プロセスが wait(2) で刈り取るまで子プロセスはゾンビ状態でカーネルに残り続けることになります。
/*
* Send signals to all our closest relatives so that they know
* to properly mourn us..
*/
static void exit_notify(struct task_struct *tsk, int group_dead)
{
bool autoreap;
struct task_struct *p, *n;
LIST_HEAD(dead);
write_lock_irq(&tasklist_lock);
forget_original_parent(tsk, &dead);
if (group_dead)
kill_orphaned_pgrp(tsk->group_leader, NULL);
if (unlikely(tsk->ptrace)) {
int sig = thread_group_leader(tsk) &&
thread_group_empty(tsk) &&
!ptrace_reparented(tsk) ?
tsk->exit_signal : SIGCHLD;
autoreap = do_notify_parent(tsk, sig);
} else if (thread_group_leader(tsk)) {
autoreap = thread_group_empty(tsk) &&
do_notify_parent(tsk, tsk->exit_signal);
} else {
autoreap = true;
}
tsk->exit_state = autoreap ? EXIT_DEAD : EXIT_ZOMBIE;
if (tsk->exit_state == EXIT_DEAD)
list_add(&tsk->ptrace_entry, &dead);
/* mt-exec, de_thread() is waiting for group leader */
if (unlikely(tsk->signal->notify_count < 0))
wake_up_process(tsk->signal->group_exit_task);
write_unlock_irq(&tasklist_lock);
list_for_each_entry_safe(p, n, &dead, ptrace_entry) {
list_del_init(&p->ptrace_entry);
release_task(p);
}
}
必然的に、次は wait(2) の処理を追いかけます。
wait(2) の処理
wait(2) は実はライブラリ関数です。Web の man マニュアルには書いていないが、以下のように端末で man コマンドを打てばちゃんと書いてます。さらに、waitpid(2) も glibc においてはただのラッパー関数なので、システムコールとして確認すべきは wait4(2), waitid(2) の処理です。
$ man wait
WAIT(2) Linux Programmer's Manual WAIT(2)
NAME
wait, waitpid, waitid - wait for process to change state
・・・（省略）・・・
C library/kernel differences
wait() is actually a library function that (in glibc) is implemented as
a call to wait4(2).
Within glibc, waitpid() is a wrapper function that invokes wait(2).
・・・（省略）・・・
wait 処理関連のソースも kernel/exit.c に存在しています。cutime, cstime の集約場所だけ確認したいので、関係ない処理シーケンスを省略させてもらうと以下の通り。
・wait 処理シーケンス
wait4, waitid システムコール
+-> do_wait()
+-> do_wait_thread()
+-> wait_consider_task()
+-> wait_task_zombie()
wait_task_zombie() の処理を見ればすぐに分かりますが、ようやく子プロセス側で蓄積した utime, stime を親プロセス側の cutime, cstime に集約している箇所が出てきましたね。今回で言うと wait(2) を発行するのは親プロセスである time コマンド なので、ここの current は time コマンド の task_struct のポインタを示しています。
EXIT_ZOMBIE 状態となっていた子プロセスは EXIT_DEAD となり、最終的に release_task() で刈り取り終了 (task_struct の削除) となります。
コメントを読めば理解できますが、tgutime, tgstime はスレッドグループのユーザーCPU時間、システムCPU時間のことですね。子スレッドまで話を広げるととても書ききれない (すでにだいぶ長い) ので、またの機会に書きたいと思います。
/*
* Handle sys_wait4 work for one task in state EXIT_ZOMBIE. We hold
* read_lock(&tasklist_lock) on entry. If we return zero, we still hold
* the lock and this task is uninteresting. If we return nonzero, we have
* released the lock and the system call should return.
*/
static int wait_task_zombie(struct wait_opts *wo, struct task_struct *p)
{
int state, retval, status;
pid_t pid = task_pid_vnr(p);
uid_t uid = from_kuid_munged(current_user_ns(), task_uid(p));
struct siginfo __user *infop;
・・・（省略）・・・
/*
* Move the task's state to DEAD/TRACE, only one thread can do this.
*/
state = (ptrace_reparented(p) && thread_group_leader(p)) ?
EXIT_TRACE : EXIT_DEAD;
if (cmpxchg(&p->exit_state, EXIT_ZOMBIE, state) != EXIT_ZOMBIE)
return 0;
/*
* We own this thread, nobody else can reap it.
*/
read_unlock(&tasklist_lock);
sched_annotate_sleep();
/*
* Check thread_group_leader() to exclude the traced sub-threads.
*/
if (state == EXIT_DEAD && thread_group_leader(p)) {
struct signal_struct *sig = p->signal;
struct signal_struct *psig = current->signal;
unsigned long maxrss;
cputime_t tgutime, tgstime;
/*
* The resource counters for the group leader are in its
* own task_struct. Those for dead threads in the group
* are in its signal_struct, as are those for the child
* processes it has previously reaped. All these
* accumulate in the parent's signal_struct c* fields.
*
* We don't bother to take a lock here to protect these
* p->signal fields because the whole thread group is dead
* and nobody can change them.
*
* psig->stats_lock also protects us from our sub-theads
* which can reap other children at the same time. Until
* we change k_getrusage()-like users to rely on this lock
* we have to take ->siglock as well.
*
* We use thread_group_cputime_adjusted() to get times for
* the thread group, which consolidates times for all threads
* in the group including the group leader.
*/
thread_group_cputime_adjusted(p, &tgutime, &tgstime);
spin_lock_irq(¤t->sighand->siglock);
write_seqlock(&psig->stats_lock);
psig->cutime += tgutime + sig->cutime;
psig->cstime += tgstime + sig->cstime;
psig->cgtime += task_gtime(p) + sig->gtime + sig->cgtime;
psig->cmin_flt +=
p->min_flt + sig->min_flt + sig->cmin_flt;
psig->cmaj_flt +=
p->maj_flt + sig->maj_flt + sig->cmaj_flt;
psig->cnvcsw +=
p->nvcsw + sig->nvcsw + sig->cnvcsw;
psig->cnivcsw +=
p->nivcsw + sig->nivcsw + sig->cnivcsw;
psig->cinblock +=
task_io_get_inblock(p) +
sig->inblock + sig->cinblock;
psig->coublock +=
task_io_get_oublock(p) +
sig->oublock + sig->coublock;
maxrss = max(sig->maxrss, sig->cmaxrss);
if (psig->cmaxrss < maxrss)
psig->cmaxrss = maxrss;
task_io_accounting_add(&psig->ioac, &p->ioac);
task_io_accounting_add(&psig->ioac, &sig->ioac);
write_sequnlock(&psig->stats_lock);
spin_unlock_irq(¤t->sighand->siglock);
}
・・・（省略）・・・
if (state == EXIT_DEAD)
release_task(p);
return retval;
}
さて、ここまでで子プロセスのCPU時間を計測する最初 (fork(2) によるプロセス生成) と最後の処理 (wait(2) による子プロセスの刈り取り) がわかりました。最後はどこでユーザー/システムCPU時間をカウントしているのかです。
user/sys 時間のカウント
カーネル内で時間の計測は非常に重要な機能の一つです。Linux 解説本として有名な 「Linux カーネル詳解」の目次を見ても丸々１章分が「時間管理」に割り当てられています。
しかし、資源を効率的・公平に分割できてさえいれば user/sys 時間をどちらにどう使ったかなんてカーネルにとって気にすべきものではありません。ユーザからの依頼を実施するため、カーネルモードになった時に依頼をこなすために必要な処理をするだけです。
この時間を気にするのは人間の方であり、time コマンドで計測される時間は、カーネルが制御すべき時間に比べてあまり精度が高くありません。それを確かめていきましょう。
user/sys 時間のカウントは、タイマ割込み処理の延長で実施しています。
ここでは昔から存在している定期的なタイマ割込み (カーネルコンフィグ CONFIG_HZ_PERIODIC=y の時のタイマ割込み) で説明します。Ubuntu 16.04 LTS では既に tickless 版タイマ割込み (CONFIG_NO_HZ=y) となっていますが、user/sys 時間のカウントの仕組みとしてはあんまり変わらないので、説明は理解しやすい方を選んでおきます。
(定期的) タイマ割込み処理ハンドラ tick_handle_priodic() があって、user/sys 時間カウントの処理シーケンスが以下の通り。tick_periodic() が上記で少し書いた jiffies をインクリメントする処理で、update_process_times() がお待ちかねの user/sys 時間をカウントする処理 (この処理は CONFIG_NO_HZ=y でも呼び出される)。現在が user と判定されたら account_user_time(), sys なら account_system_time() が呼び出されます。
・(定期的) タイマ割込みの処理シーケンス
tick_handle_periodic() : <kernel/time/tick-common.c>
+-> tick_periodic()
+-> update_process_times() : <kernel/time/timer.c>
+-> account_process_tick() : <kernel/sched/cputime.c>
+-> account_user_time()
+-> account_system_time()
update_process_times() の引数で user/sys 判定をしているので、呼び出し元を確認してみましょう。引数に user_mode(get_irq_regs()) を入れてますね。これは、簡単に言うと、スタック上にある最後の例外フレーム位置から該当のレジスタを読んでユーザ/カーネルモードの判定をしているということになります。
/*
* Periodic tick
*/
static void tick_periodic(int cpu)
{
if (tick_do_timer_cpu == cpu) {
write_seqlock(&jiffies_lock);
/* Keep track of the next tick event */
tick_next_period = ktime_add(tick_next_period, tick_period);
do_timer(1);
write_sequnlock(&jiffies_lock);
update_wall_time();
}
update_process_times(user_mode(get_irq_regs()));
profile_tick(CPU_PROFILING);
}
以下に、x86 アーキテクチャを例として、もう少しみてみましょう。
struct pt_regs は CPU のレジスタを表す構造体で、CPU アーキテクチャ毎に用意されてます。そして、そのレジスタ値からカーネルモードか否か判定する方法も CPU アーキテクチャ毎に異なるので、user_mode() もそれぞれ用意されてます。
Wikipedia を見ると CS レジスタの下位2ビットが CPL (current privilege level) と書いているので、x86 の user_mode() の処理と整合性が取れているのがわかります。
/*
* Per-cpu current frame pointer - the location of the last exception frame on
* the stack
*/
DECLARE_PER_CPU(struct pt_regs *, __irq_regs);
static inline struct pt_regs *get_irq_regs(void)
{
return __this_cpu_read(__irq_regs);
}
#ifndef __ASSEMBLY__
#ifdef __i386__
struct pt_regs {
unsigned long bx;
unsigned long cx;
unsigned long dx;
unsigned long si;
unsigned long di;
unsigned long bp;
unsigned long ax;
unsigned long ds;
unsigned long es;
unsigned long fs;
unsigned long gs;
unsigned long orig_ax;
unsigned long ip;
unsigned long cs;
unsigned long flags;
unsigned long sp;
unsigned long ss;
};
#else /* __i386__ */
struct pt_regs {
/*
* C ABI says these regs are callee-preserved. They aren't saved on kernel entry
* unless syscall needs a complete, fully filled "struct pt_regs".
*/
unsigned long r15;
unsigned long r14;
unsigned long r13;
unsigned long r12;
unsigned long bp;
unsigned long bx;
/* These regs are callee-clobbered. Always saved on kernel entry. */
unsigned long r11;
unsigned long r10;
unsigned long r9;
unsigned long r8;
unsigned long ax;
unsigned long cx;
unsigned long dx;
unsigned long si;
unsigned long di;
/*
* On syscall entry, this is syscall#. On CPU exception, this is error code.
* On hw interrupt, it's IRQ number:
*/
unsigned long orig_ax;
/* Return frame for iretq */
unsigned long ip;
unsigned long cs;
unsigned long flags;
unsigned long sp;
unsigned long ss;
/* top of stack page */
};
#endif /* !__i386__ */
/*
* user_mode(regs) determines whether a register set came from user
* mode. On x86_32, this is true if V8086 mode was enabled OR if the
* register set was from protected mode with RPL-3 CS value. This
* tricky test checks that with one comparison.
*
* On x86_64, vm86 mode is mercifully nonexistent, and we don't need
* the extra check.
*/
static inline int user_mode(struct pt_regs *regs)
{
#ifdef CONFIG_X86_32
return ((regs->cs & SEGMENT_RPL_MASK) | (regs->flags & X86_VM_MASK)) >= USER_RPL;
#else
return !!(regs->cs & 3);
#endif
}
さて、タイマ割込み契機の user/sys のCPU時間カウントの話に戻ります。
細かい処理はさておき、account_process_tick() の処理をみると、cputime_one_jiffy の値しか utime, stime に加算していないことが分かります。定期的タイマ割込みは HZ の周期で発生するので、タイマ割込みが発生した時のスタック上のフレーム情報 (CPUレジスタの情報) だけをみて今のタイマ割込み1回分のCPU時間は user/sys が消費したとみなしている、ということになります。
/*
* Account a single tick of cpu time.
* @p: the process that the cpu time gets accounted to
* @user_tick: indicates if the tick is a user or a system tick
*/
void account_process_tick(struct task_struct *p, int user_tick)
{
cputime_t one_jiffy_scaled = cputime_to_scaled(cputime_one_jiffy);
struct rq *rq = this_rq();
if (vtime_accounting_enabled())
return;
if (sched_clock_irqtime) {
irqtime_account_process_tick(p, user_tick, rq, 1);
return;
}
if (steal_account_process_tick())
return;
if (user_tick)
account_user_time(p, cputime_one_jiffy, one_jiffy_scaled);
else if ((p != rq->idle) || (irq_count() != HARDIRQ_OFFSET))
account_system_time(p, HARDIRQ_OFFSET, cputime_one_jiffy,
one_jiffy_scaled);
else
account_idle_time(cputime_one_jiffy);
}
自分のマシンで HZ の値を確認すると、以下の通り 250 だったので、1/250秒 (=4ms) が time コマンドで計測可能な user/sys 時間の精度ということになります。さらに、超細かい処理の性能を測りたいと思っても、運が悪ければ片方にしか加算されなかったりするかもしれません。なので、ある程度長い期間実行されるプログラムを平均的に見た時に user, sys がそれらしい精度で求められる、ぐらいに思っておけば良さそうです。HZ に設定できる値も 1000 が最高なので、誤差を 1ms まで小さく出来ますが、それ以上は何かしら工夫をしないと不可となります。
$ grep "CONFIG_HZ=" /boot/config-$(uname -r)
CONFIG_HZ=250
以上で、ようやく一通りの処理を追いかけることが出来ました。お疲れ様でした。
まとめ
time コマンド によって計測される real, user, sys の意味は以下のとおりです。
-
real: 計測したいプロセスが生成されてから終了するまでの実時間 (親プロセスの処理・システムの負荷状況により誤差あり) -
user: タイマ割込み毎に加算されるユーザーモードで消費した (とされる) CPU時間 -
sys: タイマ割込み毎に加算されるカーネルモードで消費した (とされる) CPU時間
今回はスレッド並列になった場合どうするかソースは見てませんが、全スレッド分の utime, stime が最終的にスレッドグループの utime, stime に加算されるので、CPUコアが8個あって各CPUコアに1スレッドを割当てる8スレッド並列のプログラムを time コマンド で計測すれば、簡単に (real の値) < (user の値) になったりします。使用したCPU時間が実時間を超えていても不思議じゃないということですね。
また、豆知識ですが、意外と sys の時間が大きいなと思った時、strace コマンドを使うとプロセスが使用したシステムコールをトレースしてくれるので調査に便利です。例えば、以下のように ls -l コマンドを strace -T で実行するとシステムコールがつらつらと表示されて <> で囲まれた時間が各システムコールを実行するのにかかった時間となります。これが分かれば、プログラムの処理が悪いのか、システムコールの処理が遅いのか切り分け出来そうですね。
$ strace -T -ttt ls -l
1497450437.838044 execve("/bin/ls", ["ls", "-l"], [/* 71 vars */]) = 0 <0.005817>
1497450437.844184 brk(NULL) = 0x9279000 <0.000023>
1497450437.844284 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) <0.000028>
1497450437.844372 mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb771c000 <0.000021>
1497450437.844455 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000019>
1497450437.844520 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000024>
1497450437.844583 fstat64(3, {st_mode=S_IFREG|0644, st_size=151229, ...}) = 0 <0.000016>
1497450437.844641 mmap2(NULL, 151229, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb76f7000 <0.000019>
・・・（省略）・・・
ちなみに、user, sys の場合、割込みにより邪魔されたCPU時間はちゃんと差し引かれた値になっているはずです。tickless版タイマ割込み処理と合わせて、この処理も機会があれば追いかけてみたいなと思いますが、興味がある方はカーネルソースを眺めてみてはいかがでしょうか。
あとがき
カーネル内部処理を追いかけてみてどうでしたか？
改めて man マニュアルをちゃんと読めば結構キチンと書いてて、最近はカーネル内部のコメントも充実しているので、個人的には細かいところで色んな人が頑張ってメンテナンスしてるんだなぁと思いました。
気になるシステムコールを手がかりにカーネルソースを追いかけてみるのはカーネル理解に有用なのでお勧めします。
あと、wait(2) の man マニュアルのバグの章で面白い記載を見つけてしまいました。抜粋すると以下の通り。要するに Linux が POSIX に準拠してないことに man マニュアル作者が激おこ状態。準拠してないことはソースを見れば誰でも分かるほど些細な違い。ちなみに最新の Linux-4.11.3 の exit.c を見ても未修正です。
POSIX.1-2008 によると、waitid() を呼び出すアプリケーションは、
infop が siginfo_t 構造体を指していること (つまり infop が
NULL でないポインターであること) を保証しなければならない。
Linux では、infop が NULL の場合、waitid() は成功し、wait
している子プロセスのプロセス ID を返す。アプリケーションは、この
食い違った、非標準で、不必要な機能に依存しないようにすべきである。
man マニュアルの記載は 2014 年、かつ、同様の指摘は Linux Mailing List で既に 2009 年で出ている のに直す気配すら無いところが Linux らしいところ。誰か修正パッチを送ってみてはどうでしょうか。恐らくは accept されるか、無視されるか、罵倒されるかの三択。濃厚なのは後ろ２つ。