コマンド実行時のメッセージ出力先が端末とファイルの場合で出力結果が異なる!

下の例では、 fork0 というコマンドを実行したときに、メッセージの出力先が端末かファイルかで差があることを示している。単純に実行した場合は3行出力されているが、リダイレクトでファイルに出力した場合では4行出力されている。

 1$ ./fork0
 2before fork: pid=6126
 3after fork: pid=6126, ppid=5868
 4after fork: pid=6127, ppid=6126
 5$
 6$ ./fork0 > fork0.txt
 7$
 8$ cat fork0.txt
 9before fork: pid=6132
10after fork: pid=6132, ppid=5868
11before fork: pid=6132
12after fork: pid=6133, ppid=6132
13$

コマンド実行時のメッセージの出力先が端末だろうとファイルだろうとパイプだろうと変わるわけない・・・と考えるのが自然だろうが、実際はそうならないケースもある。 意図的に出力先によって出力内容を変えることもできるし、単にプログラムの考慮漏れということもある。

ここではプログラムの考慮漏れを考えてみる。

子プロセスを生成するプログラムを組むときは注意が必要。 これを説明するため、まずはサンプルプログラム (fork0.c) を示す。

 1#include<stdio.h>
 2#include<stdlib.h>
 3#include<sys/types.h>
 4#include<unistd.h>
 5
 6int main(void){
 7//    char buf[BUFSIZ];
 8//    setvbuf(stdout, buf, _IOFBF, BUFSIZ);
 9    printf("before fork: pid=%d\n", getpid());
10//    fflush(stdout);
11    fork();
12    printf("after fork: pid=%d, ppid=%d\n", getpid(), getppid());
13    sleep(1);
14    exit(0);
15}

プログラムの内容は非常にシンプルで、以下の処理を行なっている。

  • 子プロセス生成前にプロセスIDを端末に出力 ("before fork" から始まる文字列を出力)
  • 子プロセスを生成
  • プロセス生成後にプロセスIDと親プロセスIDを端末に出力 ("after fork" から始まる文字列を出力)

sleep() は表示調整のためのもので、ここでは特に気にしなくて良い。(親プロセスが子プロセスより先に終わると、子プロセスの出力前にプロンプトが表示されるので、それを避けるもの)

この状態でコンパイルしてプログラム実行すると、例えば以下のように表示される。

1$ gcc fork0.c -o fork0
2$
3$ ./fork0
4before fork: pid=9344
5after fork: pid=9344, ppid=2919
6after fork: pid=9345, ppid=9344
7$

3行出力されている。 最下行の ppid が上2行の pid になっているので、上2行は親プロセスの出力、最下行は子プロセスの出力であることがわかる。

至極普通の結果だが、実行方法を少し変えて、リダイレクトで出力先を通常ファイルに変えてみる。

1$ ./fork0 > fork0.txt
2$
3$ cat fork0.txt
4before fork: pid=9364
5after fork: pid=9364, ppid=2919
6before fork: pid=9364
7after fork: pid=9365, ppid=9364
8$

出力が1行増えた。4,5行目は親プロセスによる出力、6,7行目は子プロセスによる出力である。 ここで、6行目の pid が4,5行目と同じなのだから、6行目も親プロセスの出力のはずだ・・・と思ったかもしれないが、間違いなく子プロセスによる出力なのだ。 6行目が子プロセスによる出力ならば、何故 "before fork" から始まる文字列を出力しているのか、ということも気になるだろう。

この一見不思議に思われる現象は、出力先が通常ファイルの場合には、バッファリングのモードがフルバッファリングになるためだ。

フルバッファリングではバッファがいっぱいになった時に実際の出力をする。 最初の printf() で出力指定した "before fork" から始まる文字列は、printf() 呼び出し時にはファイル出力されず単にバッファに溜め込まれるだけとなる。

その後、子プロセスの生成時にバッファが複製されて、子プロセスに引き継がれる。 そして、子プロセスの終了時にバッファ内容がフラッシュされて、 "before fork" から始まる文字列が実際に出力されたのだ。

なお、出力先が端末の場合は、バッファリングのモードが行バッファリングになる。 行バッファリングでは、プロセスが改行コードを書いた時に実際の出力をする。 "before fork" から始まる文字列には末尾に改行コードがあるので、 printf() 呼び出し時に実際に端末に出力され、バッファは空になる。 空のバッファが子プロセスに引き継がれるので、子プロセスが "before fork" から始まる文字列を出力することはない。

通常は子プロセス生成前にバッファの内容を吐き出しておくべきだろう。よって、子プロセス生成前に fflush() をコードすべきだ。 以下のように fflush() のコメントを外して有効化したプログラムを実行してみる。

 1#include<stdio.h>
 2#include<stdlib.h>
 3#include<sys/types.h>
 4#include<unistd.h>
 5
 6int main(void){
 7//    char buf[BUFSIZ];
 8//    setvbuf(stdout, buf, _IOFBF, BUFSIZ);
 9    printf("before fork: pid=%d\n", getpid());
10    fflush(stdout);
11    fork();
12    printf("after fork: pid=%d, ppid=%d\n", getpid(), getppid());
13    sleep(1);
14    exit(0);
15}
 1$ gcc fork0.c -o fork0
 2$
 3$ ./fork0
 4before fork: pid=9497
 5after fork: pid=9497, ppid=2919
 6after fork: pid=9498, ppid=9497
 7$
 8$ ./fork0 > fork0.txt
 9$
10$ cat fork0.txt
11before fork: pid=9507
12after fork: pid=9508, ppid=9507
13after fork: pid=9507, ppid=2919
14$

子プロセス生成時には直前の fflush() によりバッファは空になっているので、空のバッファが引き継がれる。すなわち、子プロセスが "before fork" から始まる文字列を出力することはない。

それでは次に、端末へ出力時のバッファ設定をフルバッファリングに変えた時の挙動を確認しておく。 以下のように setvbuf() のコメントを外して有効化したプログラムを実行してみる。 fflush()は再びコメント化しておく。

 1#include<stdio.h>
 2#include<stdlib.h>
 3#include<sys/types.h>
 4#include<unistd.h>
 5
 6int main(void){
 7    char buf[BUFSIZ];
 8    setvbuf(stdout, buf, _IOFBF, BUFSIZ);
 9    printf("before fork: pid=%d\n", getpid());
10//    fflush(stdout);
11    fork();
12    printf("after fork: pid=%d, ppid=%d\n", getpid(), getppid());
13    sleep(1);
14    exit(0);
15}

setvbuf() はバッファのサイズやモードを変更する関数。 ここでは第3引数でフルバッファリング (_IOFBF) を指定している。

実行結果は以下。 端末に出力する場合でも、子プロセスが "before fork" から始まる文字列を出力していることがわかる。 端末に対してフルバッファリング設定したので、"before fork" から始まる文字列が設定されたバッファが子プロセスに引き継がれたためだ。

 1$ gcc fork0.c -o fork0
 2$
 3$ ./fork0
 4before fork: pid=9616
 5after fork: pid=9616, ppid=2919
 6before fork: pid=9616
 7after fork: pid=9617, ppid=9616
 8$
 9$ ./fork0 > fork0.txt
10$
11$ cat fork0.txt
12before fork: pid=9622
13after fork: pid=9623, ppid=9622
14before fork: pid=9622
15after fork: pid=9622, ppid=2919
16$

なお、今回は解説のために自作のプログタムで試したが、標準コマンドでも確認できる。 例えば ls コマンドの実行結果について、出力先が端末の場合とリダイレクトで通常ファイルに出力した場合で結果が異なる。

1$ ls
2sample1.txt	sample2.txt	sample3.txt
3$ ls -a > ../out.txt
4$ cat ../out.txt
5sample1.txt
6sample2.txt
7sample3.txt
8$

端末へ出力する場合は、デフォルトで ls -C を実行した結果となるのだ。

関連ページ