printf slows down my program

Question

I have a small C program to calculate hashes (for hash tables). The code looks quite clean I hope, but there's something unrelated to it that's bugging me.

I can easily generate about one million hashes in about 0.2-0.3 seconds (benchmarked with /usr/bin/time). However, when I'm printf()inging them in the for loop, the program slows down to about 5 seconds.

1. Why is this?
2. How to make it faster? mmapp()ing stdout maybe?
3. How is stdlibc designed in regards to this, and how may it be improved?
4. How could the kernel support it better? How would it need to be modified to make the throughput on local "files" (sockets,pipes,etc) REALLY fast?

I'm looking forward for interesting and detailed replies. Thanks.

PS: this is for a compiler construction toolset, so don't by shy to get into details. While that has nothing to do with the problem itself, I just wanted to point out that details interest me.

Addendum

I'm looking for more programatic approaches for solutions and explanations. Indeed, piping does the job, but I don't have control over what the "user" does.

Of course, I'm doing a testing right now, which wouldn't be done by "normal users". BUT that doesn't change the fact that a simple printf() slows down a process, which is the problem I'm trying to find an optimal programmatic solution for.

---

Addendum - Astonishing results

The reference time is for plain printf() calls inside a TTY and takes about 4 mins 20 secs.

Testing under a /dev/pts (e.g. Konsole) speeds up the output to about 5 seconds.

It takes about the same amount of time when using setbuffer() in my testing code to a size of 16384, almost the same for 8192: about 6 seconds.

setbuffer() has apparently no effect when using it: it takes the same amount of time (on a TTY about 4 mins, on a PTS about 5 seconds).

The astonishing thing is, if I'm starting the test on TTY1 and then switch to another TTY, it does take just the same as on a PTS: about 5 seconds.

Conclusion: the kernel does something which has to do with accessibility and user friendliness. HUH!

Normally, it should be equally slow no matter if you stare at the TTY while its active, or you switch over to another TTY.

---

Lesson: when running output-intensive programs, switch to another TTY!

Answer 1

If you are printf()ing to the console it's usually extremely slow. I'm not sure why but I believe it doesn't return until the console graphically shows the outputted string. Additionally you can't mmap() to stdout.

Writing to a file should be much faster (but still orders of magnitude slower than computing a hash, all I/O is slow).

Answer 2

You can try to redirect output in shell from console to a file. Using this, logs with gigabytes in size can be created in just seconds.

Answer 3

1. I/O is always slow in comparison to straight computation. The system has to wait for more components to be available in order to use them. It then has to wait for the response before it can carry on. Conversely if its simply computing, then its only really moving data between the RAM and CPU registers.

2. I've not tested this but it may be quicker to append your hashes onto a string, then just print the string at the end. Although if you're using C not c++ this may prove to be a pain!

3 and 4 are beyond me I'm afraid.

Answer 4

You could store your strings in a buffer and output them to a file (or console) at the end or periodically, when your buffer is full.

If outputting to a console, scrolling is usually a killer.

Answer 5

1. Why not create the strings on demand rather that at the point of construction? There is no point in outputting 40 screens of data in one second how can you possibly read it? Why not create the output as required and just display the last screen full and then as required it the user scrolls???

2. Why not use sprintf to print to a string and then build a concatenated string of all the results in memory and print at the end?

3. By switching to sprintf you can clearly see how much time is spent in the format conversion and how much is spent displaying the result to the console and change the code appropriately.

4. Console output is by definition slow, creating a hash is only manipulating a few bytes of memory. Console output needs to go through many layers of the operating system, which will have code to handle thread/process locking etc. once it eventually gets to the display driver which maybe a 9600 baud device! or large bitmap display, simple functions like scrolling the screen may involve manipulating megabytes of memory.

Answer 6

As I/O is always much slower than CPU computation, you might store all values in fastest possible I/O first. So use RAM if you have enough, use Files if not, but it is much slower than RAM.

Printing out the values can now be done afterwards or in parallel by another thread. So the calculation thread(s) may not need to wait until printf has returned.

Answer 7

Unbuffered output is very slow.

By default stdout is fully-buffered, however when attached to terminal, stdout is either unbuffered or line-buffered.

Try to switch on buffering for stdout using setvbuf(), like this:

char buffer[8192];

setvbuf(stdout, buffer, _IOFBF, sizeof(buffer));

Answer 8

I guess the terminal type is using some buffered output operations, so when you do a printf it does not happen to output in split micro-seconds, it is stored in the buffer memory of the terminal subsystem.

This could be impacted by other things that could cause a slow down, perhaps there's a memory intensive operation running on it other than your program. In short there's far too many things that could all be happening at the same time, paging, swapping, heavy i/o by another process, configuration of memory utilized, maybe memory upgrade, and so on.

It might be better to concatenate the strings until a certain limit is reached, then when it is, write it all out at once. Or even using pthreads to carry out the desired process execution.

Edited: As for 2,3 it is beyond me. For 4, I am not familiar with Sun, but do know of and have messed with Solaris, There may be a kernel option to use a virtual tty.. i'll admit its been a while since messing with the kernel configs and recompiling it. As such my memory may not be great on this, have a root around with the options to see.

user@host:/usr/src/linux $ make; make menuconfig **OR kconfig if from X**

This will fire up the kernel menu, have a dig around in to see the video settings section under the devices sub-tree..

Edited: but there's a tweak you put into the kernel by adding a file into the proc filesystem (if a such thing does exist), or possibly a switch passed into the kernel, something like this (this is imaginative and does not imply it actually exists), fastio

Hope this helps, Best regards, Tom.

Answer 9

I discovered long ago using this technique something that should have been obvious. Not only is I/O slow, especially to the console, but formatting decimal numbers is not fast either. If you can put the numbers in binary into big buffers, and write those to a file, you'll find it's a lot faster.

Besides, who's going to read them? There's no point printing them all in a human-readable format if nobody needs to read all of them.