ostream_iterator vs for each loop efficiency

Question

I saw this users post yesterday. And I thought that was a cool way to output a vector. So I typed up an example and asked myself how does this compare to a for each loop?

template <typename T>
void printVectorO(std::vector<T> &v)
{
    std::cout << "Ostream_iterator contents: " << std::endl;
    auto start = std::chrono::high_resolution_clock::now();
    std::ostream_iterator<T> ost(std::cout, " ");
    std::copy(begin(v), end(v), ost);
    std::cout << std::endl;

    auto end = std::chrono::high_resolution_clock::now();
    auto time = end - start;
    auto nano = std::chrono::duration_cast<std::chrono::nanoseconds>(time);
    std::cout << "Ostream_iterator computation took: " << nano.count() << " nano seconds"<< std::endl;
    std::cout << std::endl;
}

template <typename T>
void printVectorC(std::vector<T> &v)
{
    std::cout << "For Each Loop contents: " << std::endl;
    auto start = std::chrono::high_resolution_clock::now();
    for (auto && e : v) std::cout << e << " ";
    std::cout << std::endl;

    auto end = std::chrono::high_resolution_clock::now();
    auto time = end - start;
    auto nano = std::chrono::duration_cast<std::chrono::nanoseconds>(time);
    std::cout << "For Each Loop took: " << nano.count() << " nano seconds" << std::endl;
    std::cout << std::endl;
}

I used 3 vectors to test this:

std::vector<double> doubles = { 3.15, 2.17, 2.555, 2.014 };
std::vector<std::string> strings = { "Hi", "how", "are", "you" };
std::vector<int> ints = { 3, 2 , 2 , 2 };

And I get various results. The for each loop always beats the ostream_iterator when I output the doubles (ex 41856 vs 11207 and 55198 vs 10308 nanoseconds). Sometimes the string ostream_iterator beats out the for each loop, and the for each loop and ostream_iterator almost stay neck and neck with integers.

Why is this? What is going on behind the scenes of ostream_iterator? When would I use ostream_iterator over a for each loop when it comes to efficiency and speed?

Answer 1

Beware of micro-benchmarks.

I have several general comments regarding this code:

1. Pass read-only variables as a const reference not as a regular reference. This does not effect performance, though
2. Don't use std::endl since it calls flush() which ends up taking most of your run-time in such a micro benchmark. For example, printing doubles took 37010 ns with std::endl and only 4456 ns with '\n'
3. A single measurement is inaccurate. In order to smooth out any measurement noise you must run it many times in a loop. This is still imperfect, since the best thing is to run tests interchangeably (to make random events, that can slow-down the code, affect both implementations the same way)
4. Better to redirect it to a file, otherwise terminal speed will dominate the results.

Here is the corrected benchmark:

constexpr unsigned ITERATIONS = 1000000;
template <typename T>
void printVectorO(const std::vector<T> &v)
{
    std::cout << "Ostream_iterator contents\n";
    auto start = std::chrono::high_resolution_clock::now();
    for (unsigned i=0 ; i < ITERATIONS; ++i) {
        std::ostream_iterator<T> ost(std::cout, " ");
        std::copy(begin(v), end(v), ost);
        std::cout << '\n';
    }

    auto end = std::chrono::high_resolution_clock::now();
    auto time = end - start;
    auto nano = std::chrono::duration_cast<std::chrono::nanoseconds>(time);
    std::cout << "Ostream_iterator computation took: "
              << nano.count() / ITERATIONS << " nano seconds\n\n";
}

template <typename T>
void printVectorC(const std::vector<T> &v)
{
    std::cout << "For Each Loop contents\n";
    auto start = std::chrono::high_resolution_clock::now();
    for (unsigned i=0 ; i < ITERATIONS ; ++i) {
        for (auto && e : v) std::cout << e << " ";
        std::cout << '\n';
    }

    auto end = std::chrono::high_resolution_clock::now();
    auto time = end - start;
    auto nano = std::chrono::duration_cast<std::chrono::nanoseconds>(time);
    std::cout << "For Each Loop took: "
              << nano.count() / ITERATIONS << " nano seconds\n\n";
}

And invoking it with:

template <class Container>
void test(const Container & ctr)
{
    printVectorC2(ctr);
    printVectorO2(ctr);
}


int main()
{
    std::vector<double> doubles = { 3.15, 2.17, 2.555, 2.014 };
    test(doubles);
    std::vector<std::string> strings = { "Hi", "how", "are", "you" };
    test(strings);
    std::vector<int> ints = { 3, 2 , 2 , 2 };
    test(ints);
}

And now, after grepping for nano we have:

For Each Loop took: 2045 nano seconds
Ostream_iterator computation took: 2033 nano seconds
For Each Loop took: 487 nano seconds
Ostream_iterator computation took: 485 nano seconds
For Each Loop took: 503 nano seconds
Ostream_iterator computation took: 499 nano seconds

There is barely any difference. Actually, with this specific run it seems that the ostream version is faster. But running it again gives slightly different results.