13

After doing the following test:

for( i = 0; i < 3000000; i++ ) {
    printf( "Test string\n" );
}

for( i = 0; i < 3000000; i++ ) {
    write( STDOUT_FILENO, "Test string\n", strlen( "Test string\n" ) );
}

it turns out that the calls to printf take a grand total of 3 seconds, while the calls to write take a whopping 46 seconds. How, with all the fancy formatting magic that printf does, and the fact that printf itself calls write, is this possible? Is there something that I'm missing?

Any and all thoughts and input are appreciated.

Jens Gustedt
  • 76,821
  • 6
  • 102
  • 177
rurouniwallace
  • 2,027
  • 6
  • 25
  • 47
  • 11
    Really? You are calculating the string length each and every time and then measuring that as part of the timings? – K-ballo Jun 26 '12 at 17:46
  • 3
    @K-ballo With optimisations, that should be computed only once, during compilation. – Daniel Fischer Jun 26 '12 at 17:50
  • Does your output go to the console or to a file? If console, the cost of that swamps everything else. – Mike Dunlavey Jun 26 '12 at 17:58
  • @MikeDunlavey Even redirecting stdout to a file make `write` take rather long while `printf` is plenty fast. Redirecting to `/dev/null`, however, both are fast. Then `write` takes less user time, but more sys time and altogether longer, but time is of the same order of magnitude (Linux x86_64, gcc-4.5.1). – Daniel Fischer Jun 26 '12 at 18:03
  • @Daniel: Then that seems to imply that the buffering (as Paul noted) done by `printf` is its major advantage when writing to a file. – Mike Dunlavey Jun 26 '12 at 18:07
  • 2
    `puts` should even be faster. – Jens Gustedt Jun 26 '12 at 18:18
  • @K-ballo The whole reason I'm doing this timing test is because when I'm doing system applications, I generally do it that way. This is mainly because I'm not always sure how the particular system will handle the null terminator. Or, worst case scenario, I don't even know how long the string will be. It seems the most apples to apples way to evaluate the performance of my usual system applications. And, as Daniel Fischer said, the optimizer should handle that pretty well when the string in question is a literal. – rurouniwallace Jun 26 '12 at 22:23
  • @MikeDunlavey The output is being redirected to a file via the redirection operator. – rurouniwallace Jun 26 '12 at 22:30
  • @JensGustedt puts was slightly faster at 2 seconds, without the newline. With the newline it was slightly slower at 4 seconds. Not sure which is a more equitable comparison though (first one gives the same output, second one is providing the same string). – rurouniwallace Jun 26 '12 at 23:14

2 Answers2

31

How, with ... the fact that printf itself calls write, is this possible? Is there something that I'm missing?

Yes, there is something that you are missing. printf doesn't necessarily call write every time. Rather, printf buffers its output. That is, it often stores its result in a memory buffer, only calling write when the buffer is full, or on some other conditions.

write is a fairly expensive call, much more expensive than copying data into printf's buffer, so reducing the number of write calls provides a net performance win.

If your stdout is directed to a terminal device, then printf calls write every time it sees a \n -- in your case, every time it is called. If your stdout is directed to a file (or to /dev/null), then printf calls write only when its internal buffer is full.

Supposing that you are redirecting your output, and that printf's internal buffer is 4Kbytes, then the first loop invokes write 3000000 / (4096 / 12) == 8780 times. Your second loop, however, invokes write 3000000 times.

Beyond the effect of fewer calls to write, is the size of the calls to write. The quantum of storage in a hard drive is a sector -- often 512 bytes. To write a smaller amount of data than a sector may involve reading the original data in the sector, modifying it, and writing the result back out. Invoking write with a complete sector, however, may go faster since you don't have to read in the original data. printf's buffer size is chosen to be a multiple of the typical sector size. That way the system can most efficiently write the data to disk.

I'd expect your first loop to go much faster than the second.

Robᵩ
  • 163,533
  • 20
  • 239
  • 308
  • 1
    This explains everything quite well. Thank you! Regarding your comment about the data size...why wouldn't the original data need to be read just because it fits perfectly in the sector? Doesn't the write call still need to know the data that needs to be written? – rurouniwallace Jun 26 '12 at 23:27
5

You are not comparing apples to apples, because the loop with write runs strlen 3000000 times, while printf does not do any of that; it does not do any formatting either, so "fancy formatting magic" hardly applies.

size_t len = strlen( "Test string\n" );
for( i = 0; i < 3000000; i++ ) {
    write( STDOUT_FILENO, "Test string\n", len );
}

Another important difference is that printf flushes every time when you pass \n, while write does not. You should remove \n from both strings to make your benchmarks more equitable.

Sergey Kalinichenko
  • 714,442
  • 84
  • 1,110
  • 1,523
  • 3
    On my system, gcc-4.5.1 evaluates the `strlen` at compile-time even without optimisations. The flushing/buffering seem to be what makes the difference. – Daniel Fischer Jun 26 '12 at 18:06
  • @DanielFischer Thanks! It's nice to know that `gcc` is smart enough to fold `strlen` expression into a constant. – Sergey Kalinichenko Jun 26 '12 at 18:08
  • 2
    `printf` does **not** flush on every `\n` if the output is redirected to a file. Also, it is more accurate to say that `write` flushes every time, reglardless of content -- after all, "flush" in this context means merely "calls `write`." – Robᵩ Jun 26 '12 at 18:27
  • What makes you think printf does not have to accomplish the effect of strlen? – Chris Stratton Jun 26 '12 at 18:38
  • @Robᵩ There's nothing in the OP that would indicate writing to a file. – Sergey Kalinichenko Jun 26 '12 at 18:38
  • @ChrisStratton What makes you think otherwise? – Sergey Kalinichenko Jun 26 '12 at 18:39
  • 1
    @dasblinkenlight the fact that in order to copy a null-terminated string to a destination it must either have it's length calculated, or be copied character-by-character. – Chris Stratton Jun 26 '12 at 18:45
  • @ChrisStratton Strings can be processed character-by-character without calculating their length ahead of time. Optimizations aside, we're talking two loops going through the string vs. one loop going through the string. – Sergey Kalinichenko Jun 26 '12 at 18:48
  • Sure, but processing a string character by character is comparable to counting the characters. – Chris Stratton Jun 26 '12 at 18:49
  • 1
    @ChrisStratton But when you output a string character by character, you still read each character from the memory only once, not twice. Both `write` and `printf` need to move all characters from the string to some place in the memory that I/O system owns and manages, from which these characters eventually go to a disk or a tty (I am intentionally avoiding the word "buffer"). `printf` would stop when the `\0` character is reached; `write` would stop when the count passed in is exhausted. – Sergey Kalinichenko Jun 26 '12 at 18:55
  • It's up to a given implementation of printf if it copies character by character or measures and then does a more efficient block copy. Note that printf results in the data being copied a minimum of twice, as it is copied both into and then ultimate out of the stream buffer. – Chris Stratton Jun 26 '12 at 19:01
  • @dasblinkenlight Thanks for your answer. It actually is redirecting to a file using the redirection character on the terminal. I didn't mention it in the OP because I didn't know it was relevant. Regarding your suggestion to remove '\n' from both calls, how would that equate the tests? It would prevent `printf` from flushing when writing to the terminal, since the call to `write` itself can be considered a "flush", it wouldn't cause `write` to be buffered, would it? – rurouniwallace Jun 26 '12 at 23:21