printf more than 5 times faster than std::cout?

Question

#include <iostream>
#include <cstdlib>
#include <cstdio>
#include <ctime>

int main(int argc, char* argv[])
{
    std::clock_t start;
    double duration;    

    std::cout << "Starting std::cout test." << std::endl;
    start = std::clock();

    for (int i = 0; i < 1000; i++)
    {
        std::cout << "Hello, World! (" << i << ")" << std::endl;
    }

    duration = (std::clock() - start) / (double) CLOCKS_PER_SEC;

    std::cout << "Ending std::cout test." << std::endl;
    std::cout << "Time taken: " << duration << std::endl;

    std::system("pause");

    std::cout << "Starting std::printf test." << std::endl;
    start = std::clock();

    for (int i = 0; i < 1000; i++)
    {
        std::printf("Hello, World! (%i)\n", i);
        std::fflush(stdout);
    }

    duration = (std::clock() - start) / (double) CLOCKS_PER_SEC;

    std::cout << "Ending std::printf test." << std::endl;
    std::cout << "Time taken: " << duration << std::endl;

    system("pause");

    return 0;
}

Now, here are the times for the first five runs:

• std::cout test: 1.125 s ; printf test: 0.195 s
• std::cout test: 1.154 s ; printf test: 0.230 s
• std::cout test: 1.142 s ; printf test: 0.216 s
• std::cout test: 1.322 s ; printf test: 0.221 s
• std::cout test: 1.108 s ; printf test: 0.232 s

As you can see, using printf and then fflushing takes about 5 times less time than using std::cout.

Although I did expect using std::cout's << operator to be perhaps a little slower (almost minimal) , I wasn't prepared for this huge difference. Am I making a fair test? If so, then what makes the first test so much slower than the second one, if they essentially do the exact same thing?

Answer 1

Try this:

#include <cstdlib>
#include <cstdio>
#include <ctime>
#include <iostream>

int main(int argc, char* argv[])
{
#if defined(NOSYNC)
    std::cout.sync_with_stdio(false);
#endif

    std::cout << "Starting std::cout test." << std::endl;

    std::clock_t start = std::clock();

    for (int i = 0; i < 1000; i++)
    {   
        std::cout << "Hello, World! (" << i << ")" << std::endl;
    }   

    clock_t mid = std::clock();

    for (int i = 0; i < 1000; i++)
    {   
        std::printf("Hello, World! (%i)\n", i); 
        std::fflush(stdout);
    }   

    std::clock_t end = std::clock();

    std::cout << "Time taken: P1 " << ((mid-start)*1.0/CLOCKS_PER_SEC) << std::endl;

    std::cout << "Time taken: P2 " << ((end-mid)*1.0/CLOCKS_PER_SEC) << std::endl;


    return 0;
}

Then I get:

> g++ -O3 t13.cpp
> ./a.out
# lots of lines deleted
Time taken: P1 0.002517
Time taken: P2 0.001872

> g++ -O3 t13.cpp -DNOSYNC   
> ./a.out
# lots of lines deleted
Time taken: P1 0.002398
Time taken: P2 0.001878

So the P2 times do not change.
But you get an improvement of the P1 times (ie std::cout) using std::cout.sync_with_stdio(false);. Becuase the code no longer tries to keep the two stream (std::cout stdout) synchronized. Which if you are writing pure C++ and only using std::cout not a problem.