C: Why is a fprintf(stdout,....) so slow?

Question

I still often use console output to get ideas what's going on in my code. I know this may be a bit old fashion, but I also use this to "pipe" stdout into log files etc.

However, it turns out that the output to the console is slowed down for some reason. I was wondering if someone can explain why an fprintf() to a console window appears to be sort of blocking.

What I've done/diagnosed so far:

1. I measured the time a simple fprintf(stdout,"quick fprintf\n"); It needs: 0.82ms (in average). This is considered by far too long since a vsprintf_s(...) writes the same output into a string in just a few microseconds. Therefore there must be some blocking specifically to the console.

2. In oder to escape from the blocking I have used vsprintf_s(...) to copy my output into a fifo alike data structure. The data structure is protected by a critical section object. A separate thread is then unqueing the data structure by putting the queued output to the console.

3. One further improvement I could obtain by the introduction of pipe services. The output of my program (supposed to end up in a console window) goes the following way:

   • A vsprintf_s(...) formats the output to simple strings.
   • The strings are queued into a fifo alike data structure, a linked list sructure for example. This data structure is protected by a critical section object.
   • A second thread dequeues the data structure by sending the output strings to a named pipe.
   • A second process reads the named pipe and puts the strings again into a fifo alike data structure. This is needed to keep the reading away from the blocking output to the console. The reading process is fast at reading the named pipe and monitors the fill level of the pipes buffer continuously.
   • A second thread in that second process finally dequeues the data structure by fprintf(stdout,...) to the console.

So I have two processes with at least two threads each, a named pipe between them, and fifo alike data structures on both sides of the pipe to avoid blocking in the event of pipe buffer full.

That is a lot of stuff to just make sure that console output is "non-blocking". But the result is not too bad. My main program can write complex fprintf(stdout,...) within just a few microseconds.

Maybe I should have asked earlier: Is there some other (easier!) way to have nonblocking console output?

Answer 1

I think the timing problem has to do with the fact that console is line buffered by default. This means that every time you write a '\n' character to it, your entire output buffer is sent to the console, which is a rather costly operation. This is the price that you pay for the line to appear in the output immediately.

You can change this default behavior by changing the buffering strategy to full buffering. The consequence is that the output will be sent to console in chunks that are equal to the size of your buffer, but individual operations will complete faster.

Make this call before you first write to console:

char buf[10000];
setvbuf(stdout, buf, _IOFBF, sizeof(buf));

The timing of individual writes should improve, but the output will not appear in the console immediately. This is not too useful for debugging, but the timing will improve. If you set up a thread that calls fflush(stdout) on regular time intervals, say, once every second, you should get a reasonable balance between the performance of individual writes and the delay between your program writing the output and the time when you can actually see it on the console.