printf と write の同期

C/C++

フレームワークが write システムコールで標準出力にログ出力、そのフレームワーク上で動作するアプリケーションは printf で標準出力にログ出力し、アプリケーションはマルチスレッドで動作するというケースにおいて、write の出力が printf の出力で潰されるというケースが発生することを確認した。

懸賞のため、以下のようなテストを書いた。

// gcc printf_vs_write.c -o printf_vs_write -lpthread
#include <stdio.h>
#include <stdlib.h>
#include <pthread.h>
#include <unistd.h>

#define HOGE "HOGE\n"
#define FUGA "FUGA\n"

void *start(void *param) {
    int i;

    for (i = 0; i < 10000; i++) {
        write(STDOUT_FILENO, HOGE, sizeof(HOGE) - 1);
    }
}

int main(int argc, char *argv[]) {
    int i;
    pthread_t thread;

    pthread_create(&thread, NULL, start, NULL);
    for (i = 0; i < 10000; i++) {
        printf(FUGA);
    }
    pthread_join(thread, NULL);
    return EXIT_SUCCESS;
}

#!/bin/bash

gcc --version
./printf_vs_write > printf_vs_write.log
grep HOGE printf_vs_write.log | wc
grep FUGA printf_vs_write.log | wc

期待通りなら、HOGE と FUGA が 10000 行ずつ存在するのだが、実際には以下のようになる。

gcc (Ubuntu/Linaro 4.6.3-1ubuntu5) 4.6.3
Copyright (C) 2011 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

   9989    9989   49965
    174     174     878

printf で出力する FUGA が極端に少ない。write で出力する HOGE も一部欠損している。

write 側の壊れ方は、HOGE に FUGA が混ざってしまうという具合の壊れ方だ。

142 行目と 143 行目で UGA が出て FHOGE が出ているのは、printf が "FUGA\n" を出力している際に write が割り込み、F が欠落し、次のループの F だけが HOGE の先頭に出力された形になる。その他も大体同じパターンだ。

printf 側の壊れ方は、以下のような感じだ。

面白いのが 10000 行以降、printf のターンなのだが、要するに 10000 回の write のループ中は、常に write が優先されるということを意味している。ひとつでも printf が成功していたら、10000 行以降にも HOGE が表示されるのだが、そのようには振舞わない。

アプリケーションで確認したパターンとほぼ逆の振る舞いになってしまっているが、ログが混ざるわけではなく握りつぶされてしまうという点で、再現はできていると思う。

これをログが一行に入り交じってしまっても良いから、出力はされるように修正してみる。

    pthread_create(&thread, NULL, start, NULL);
    for (i = 0; i < 10000; i++) {
//      printf(FUGA);
        write(STDOUT_FILENO, FUGA, sizeof(FUGA) - 1);
    }
}

上記のようにした結果が以下だ。

   4597    4597   22985
   5442    5442   27210

write だけを使うと、同一行に HOGE と FUGA が入り交じるということがなくなったが、write 実行中の write が無視されるのか、後の write が優先されるのかわからないが、HOGE と FUGA がほぼ半分ずつの出力となった。

以下のように mutex でロックすることで、期待通りの動作にはなる。

// gcc printf_vs_write3.c -o printf_vs_write3 -lpthread
#include <stdio.h>
#include <stdlib.h>
#include <pthread.h>
#include <unistd.h>

#define HOGE "HOGE\n"
#define FUGA "FUGA\n"

static pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER;

void *start(void *unused) {
    int i;

    for (i = 0; i < 10000; i++) {
        pthread_mutex_lock(&mutex);
        write(STDOUT_FILENO, HOGE, sizeof(HOGE) - 1);
        pthread_mutex_unlock(&mutex);
    }
}

int main(int argc, char *argv[]) {
    int i;
    pthread_t thread;

    pthread_create(&thread, NULL, start, NULL);
    for (i = 0; i < 10000; i++) {
        pthread_mutex_lock(&mutex);
        write(STDOUT_FILENO, FUGA, sizeof(FUGA) - 1);
        pthread_mutex_unlock(&mutex);
    }
    pthread_join(thread, NULL);
    return EXIT_SUCCESS;
}

  10000   10000   50000
  10000   10000   50000

ただこの方法は確実ではあるが、フレームワークにロックなんてしてはダメという制約があるため、見送る。

出力先が STDOUT_FILENO ではなく、自分で open で開いたファイルなら、open にオプション O_SYNC を渡すことで、write がブロックされてこのような問題は発生しなくなる。

標準出力のようなファイルディスクリプタにはどのように行えばよいかというと、syncfs ではないだろうか。

// gcc printf_vs_write4.c -o printf_vs_write4 -lpthread
#define _GNU_SOURCE
#include <stdio.h>
#include <stdlib.h>
#include <pthread.h>
#include <unistd.h>

#define HOGE "HOGE\n"
#define FUGA "FUGA\n"

void *start(void *unused) {
    int i;

    for (i = 0; i < 10000; i++) {
        write(STDOUT_FILENO, HOGE, sizeof(HOGE) - 1);
    }
}

int main(int argc, char *argv[]) {
    int i;
    pthread_t thread;

    syncfs(STDOUT_FILENO);
    pthread_create(&thread, NULL, start, NULL);
    for (i = 0; i < 10000; i++) {
        write(STDOUT_FILENO, FUGA, sizeof(FUGA) - 1);
    }
    pthread_join(thread, NULL);
    return EXIT_SUCCESS;
}

syncfs の呼び出しは成功しているが、処理時間が長くなっただけで結果は変わらなかった。STDOUT_FILENO や STDERR_FILENO には有効に機能しないのかもしれない。


今回の検証でわかったこと：