CODEWITHSUNDEEP
c++linuxoptimizationstdoutbenchmarking
joeButler
joeButler

Reputation: 1711

Why does my program run faster when I redirect stdout?

I'm seeing something really strange. I've written a tiny code timer to capture how long blocks of code are running for. I can't post all the code, it's pretty big, but I've been through the block in question and there is nothing going near std::cout

$ bin/profiler 50 
50 repetitions of Generate Config MLP took: 254 microseconds
50 repetitions of Create Population took: 5318 microseconds
50 repetitions of Create and Score Population took: 218047 microseconds

$ bin/profiler 50 > time_times
$ cat time_times 
50 repetitions of Generate Config MLP took: 258 microseconds
50 repetitions of Create Population took: 5438 microseconds
50 repetitions of Create and Score Population took: 168379 microseconds

$ bin/profiler 50 
50 repetitions of Generate Config MLP took: 269 microseconds
50 repetitions of Create Population took: 5447 microseconds
50 repetitions of Create and Score Population took: 216262 microseconds

$ bin/profiler 50 > time_times
$ cat time_times 
50 repetitions of Generate Config MLP took: 260 microseconds
50 repetitions of Create Population took: 5321 microseconds
50 repetitions of Create and Score Population took: 169431 microseconds

Here is the block i'm using to time, the function ptr is just a link to a void function, which makes a single function call. I'm aware there are probably better ways to time something, I wanted quick and dirty so I start to improve on the code. 

void timeAndDisplay(string name,function_ptr f_ptr) {

    struct timeval start, end;
    long mtime, seconds, useconds;

    gettimeofday(&start, NULL);
    // Run the code 
    for (unsigned x = 0; x < reps; x++) {
        f_ptr();
    }

    gettimeofday(&end, NULL);
    seconds  = end.tv_sec  - start.tv_sec;
    useconds = end.tv_usec - start.tv_usec;
    mtime = ((seconds) * 1000000 + useconds/1.0) + 0.0005;

    std::cout << reps << " repetitions of " << name << " took: " << mtime << " microseconds" << std::endl;
}

I'm compiling and linking with:

g++ -c -Wall  -O3 -fopenmp -mfpmath=sse -march=native src/profiler.cpp -o build/profiler.o
g++ build/*.o -lprotobuf -lgomp -lboost_system -lboost_filesystem  -o bin/profiler

I was about to start making changes so I thought I would save a baseline, but the create and score population is performing differently when I redirect it!

Does anybody know what is going on?

Update 1: First pass with profiling doesnt show anything significant. Almost all the top calls are related to the vector math which the program is running (Eigen library). The prevailing theory is that there is some blocking io for the console but the calls to std::cout are outside of the function loop and only 3 in total so I find this hard to accept it has such an impact.

Update 2: After having this drive me crazy for some time, I gave up a bit and started to make improvements to my program with the data I had available. It got weirder, but I think I've found one the main influencing factors - the available system entropy. My program uses huge amounts of random numbers and it seems it runs at a slower pace after running through an amount of times with either method. I used a for loop to simulate both methods and although it is quicker with the stdout redirected, I suspect this tiny piece of IO bumps urandom a little which is why its faster. I'm still investigating but if anyone can point me in the right direction to prove this I'd be very grateful.

Upvotes: 3

Views: 1445

Answers (3)

Russ Huguley
Russ Huguley

Reputation: 856

Have you tried running it with the window off the screen or behind another window so it does not have to be drawn? I have been on some systems where that would sort of bypass the redrawing of the window.

Upvotes: 0

Chad
Chad

Reputation: 3008

Writing to or from the Standard Console Input/Output system involves buffers and locks. So I would say that you're generally taking a performance hit because of locking buffers.

I would recommend the following Profiler for finding out whats taking the longest amount of time.

Upvotes: 3

Thomas Matthews
Thomas Matthews

Reputation: 57688

Writing to the console involves graphics manipulations and maybe also handling of carriage returns (moving to the beginning of the line) and linefeed (moving all the previous text up one line and erasing the top line).

Redirecting to a file is usually faster because the output is appended and no graphics manipulations take place.

At least that has been my experience.

Upvotes: 1

Related Questions