CODEWITHSUNDEEP
cperformance
Masood_mj
Masood_mj

Reputation: 1184

Long delay hiccups for logging stdout to file

I have a C program that writes into 3 lines every 10ms into stdout. If I redirect the output to a file (using > ) there will be long delays (60ms) in the running of the program. The delays are periodic (say every 5 seconds).

If I just let it write to console or redirect to /dev/null, there is no problem.

I suspected that this is the stdout buffer problem, but using fflush(stdout) didn't solve the problem.

How can I solve the issue?

Upvotes: 3

Views: 503

Answers (3)

Matthew
Matthew

Reputation: 563

You need to use fsync. The following:

fsync(fileno(stdout))

Should help. Note that the Linux kernel will still buffer limit I/O according to its internal scheduler limits. Running as root and setting a very low nice value might make a difference, if you're not getting the frequency you want.

If it's still too slow, try using fdatasync instead. Every fflush and fsync causes the filesystem to update node metadata (filesize, access time, etc) as well as the actual data itself. If you know in blocks how much data you'll be writing, then you can try the following trick:

#define _XOPEN_SOURCE 500 

#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <string.h>

int main(int argc, char **argv){

        FILE *fp = fopen("test.txt", "w");

        char *line = "Test\n";
        char *fill = "\0";

        fwrite(fill, 1, 100*strlen(line), fp);
        fflush(fp);
        fsync(fileno(fp));

        rewind(fp);

        for (int i = 0; i < 100; i++){

                fwrite(line, strlen(line), 1, fp);
                fflush(fp);
                fdatasync(fileno(fp));

        }

}

The first fwrite call writes 5*100 zeros to the file in one chunk, and fsyncs so that it's written to disk and the node information is updated. Now we can write up to 500 bytes to the file without trashing filesystem metadata. rewind(3) returns the file pointer position to the beginning of the file so we can write over the data without changing the filesize of the node.

Timing that program gives the following:

$ time ./fdatasync
./fdatasync  0.00s user 0.01s system 1% cpu 0.913 total

So it ran fdatasync and sync'ed to disk 100 times in 0.913 seconds, which averages out to ~9ms per write & fdatasync call.

Upvotes: 3

Filipe Gon&#231;alves
Filipe Gon&#231;alves

Reputation: 21223

If I redirect the output to a file (using > ) there will be long delays (60ms) in the running of the program.

That's because when stdout is a terminal device, it is usually (although not required) line-buffered, that is, the output buffer is flushed when a newline character is written, whereas in the case of regular files, output is fully buffered, meaning the buffers are flushed either when they are full or you close the file (or you explicitly call fflush(), of course).

fflush(stdout) may not be enough for you because that only flushes the standard I/O library buffers, but the kernel also buffers and delays writes to disk. You can call fsync() on the file descriptor to flush the modified buffer cache pages to disk after calling fflush(), as in fsync(STDOUT_FILENO).

Be careful and don't call fsync() without calling fflush() before.

UPDATE: You can also try sync(), which, unlike fsync(), does not block waiting for the underlying writes to return. Or, as suggested in another answer, fdatasync() may be a good choice because it avoids the overhead of updating file times.

Upvotes: 3

Pradheep
Pradheep

Reputation: 3819

it could be just that every 5seconds you are filling up your disk buffer and there is a spike in the latency due to flushing to actual disk.check with iostat

Upvotes: 1

Related Questions