perfect forwarding avoid copy when arguments passed as rvalue?

Question

I'm reading Scott's book effective modern c++. In item 26, there's an example that I wrote on Wandbox: https://wandbox.org/permlink/6DKoDqg4jAjA9ZTB

I want to verify how much the good code is better than the bad one. However, the performance comparison is not what I expected, even the good one is slower that the bad one. I don't know what's going wrong.

To prevent wandbox's code from disappearing, here's the code:

#include <iostream>
#include <chrono>
#include <cstdlib>
#include <set>
#include <string>

using namespace std;

std::multiset<std::string> names;

void bad_logAndAdd(const std::string& name) {
    auto now = std::chrono::system_clock::now();
    names.emplace(name);
}
template <typename T>
void good_logAndAdd(T&& name) {
    auto now = std::chrono::system_clock::now();
    names.emplace(std::forward<T>(name));
}

void bad() {
    for (int i=0; i<1000000; i++) {
        string petname("cs");
        bad_logAndAdd(petname);
        bad_logAndAdd(std::string("abc")); 
        bad_logAndAdd("dog"); 
    }

}

void good() {
    for (int i=0; i<1000000; i++) {
        string petname("cs");
        good_logAndAdd(petname); 
        good_logAndAdd(std::string("abc")); 
        good_logAndAdd("dog");
    }

}

int main()
{
    auto begin = std::chrono::high_resolution_clock::now();
    bad();
    auto end = std::chrono::high_resolution_clock::now();
    std::cout << std::chrono::duration_cast<std::chrono::milliseconds>(end-begin).count() << std::endl;

    auto begin2 = std::chrono::high_resolution_clock::now();
    good();
    auto end2 = std::chrono::high_resolution_clock::now();
    std::cout << std::chrono::duration_cast<std::chrono::milliseconds>(end2-begin2).count() << std::endl;
}

Answer 1

There are several things that make the difference of behaviour hardly perceptible.

1. a lot of the time is spent in auto now = std::chrono::system_clock::now();,
2. a lot of time is spent in memory allocation (names are all stored),
3. amongst the three calls to logAndAdd(), only two of them can benefit from move (petname is not implicitly moveable),
4. small strings won't benefit from move.

I have tried to rewrite (below) the OP's code in order to minimise the influence of these things.

1. remove the call to now() at each insertion,
2. prefer many medium size allocations to a huge one and consider a warmup in order to avoid the penalty of the first allocations,
3. only use the calls that could benefit from the copy/move difference,
4. make the strings longer in order to make their copy expensive.

In these conditions, I obtain a visible difference between the two solutions (gcc 9.1, linux).

bad: 1.23
good: 1.01

I hope the resulting code is not too far from what was intended in the question.

#include <iostream>
#include <chrono>
#include <cstdlib>
#include <set>
#include <string>

std::multiset<std::string> bad_names;
std::multiset<std::string> good_names;

void bad_logAndAdd(const std::string& name) {
    // auto now = std::chrono::system_clock::now();
    bad_names.emplace(name);
}
template <typename T>
void good_logAndAdd(T&& name) {
    // auto now = std::chrono::system_clock::now();
    good_names.emplace(std::forward<T>(name));
}

void bad() {
    for (int i=0; i<2000; i++) {
        // std::string petname("cs_that_have_been_made_much_longer_in_order_to_prevent_small_string_optimisation_that_makes_copy_and_move_very_similar");
        // bad_logAndAdd(petname);
        bad_logAndAdd(std::string("abc_that_have_been_made_much_longer_in_order_to_prevent_small_string_optimisation_that_makes_copy_and_move_very_similar")); 
        bad_logAndAdd("dog_that_have_been_made_much_longer_in_order_to_prevent_small_string_optimisation_that_makes_copy_and_move_very_similar"); 
    }

}

void good() {
    for (int i=0; i<2000; i++) {
        // std::string petname("cs_that_have_been_made_much_longer_in_order_to_prevent_small_string_optimisation_that_makes_copy_and_move_very_similar");
        // good_logAndAdd(petname); 
        good_logAndAdd(std::string("abc_that_have_been_made_much_longer_in_order_to_prevent_small_string_optimisation_that_makes_copy_and_move_very_similar")); 
        good_logAndAdd("dog_that_have_been_made_much_longer_in_order_to_prevent_small_string_optimisation_that_makes_copy_and_move_very_similar");
    }

}

int main()
{
    auto bad_time=std::chrono::high_resolution_clock::duration{};
    auto good_time=std::chrono::high_resolution_clock::duration{};
    for(auto iter=0; iter<1000; ++iter)
    {
      bad_names={};
      auto begin = std::chrono::high_resolution_clock::now();
      bad();
      auto end = std::chrono::high_resolution_clock::now();
      good_names={};
      auto begin2 = std::chrono::high_resolution_clock::now();
      good();
      auto end2 = std::chrono::high_resolution_clock::now();
      if(iter!=0) // ignore warmup
      {
        bad_time+=end-begin;
        good_time+=end2-begin2;
      }
    }
    std::cout << "bad: " << 1e-3*double(std::chrono::duration_cast<std::chrono::milliseconds>(bad_time).count()) << '\n';
    std::cout << "good: " << 1e-3*double(std::chrono::duration_cast<std::chrono::milliseconds>(good_time).count()) << '\n';
    return 0;
}