title: Strange benchmark results for concurrent queue
body: <p><a href="http://coliru.stacked-crooked.com/view?id=2bd42a80bd391f80692fc8e79f5e889a-30b7ec1164b7158ae2aa19f5f8e69331" rel="nofollow">In this program</a> I try to measure the average time between the pushing of an item to a concurrent queue and the popping of the item by another thread:</p>
  
  <pre><code>#include &lt;chrono&gt;
  #include &lt;iomanip&gt;
  #include &lt;iostream&gt;
  #include &lt;thread&gt;
  #include "tbb/concurrent_queue.h"
  
  
  namespace {
  
  
  void test_unbounded_queue(uint32_t iteration_count)
  {
      typedef std::chrono::high_resolution_clock Clock;
      using std::chrono::duration_cast;
      using std::chrono::nanoseconds;
  
      tbb::concurrent_queue&lt;uint32_t&gt; unbounded_queue;
  
      uint32_t verify = 0;
  
      Clock::time_point start_time, end_time;
  
      std::thread consumer_thread([&amp;]
      {
          start_time = Clock::now();
  
          // Active polling (100% CPU usage)
          while (true)
          {
              uint32_t n;
              if (unbounded_queue.try_pop(n))
              {
                  if (n == uint32_t(-1))
                  {
                      end_time = Clock::now();
                      return;
                  }
                  verify += n;
              }
          }
      });
  
      for (unsigned i = 0; i != iteration_count; ++i)
      {
          unbounded_queue.push(1);
      }
  
      // stop the thread
      unbounded_queue.push(uint32_t(-1));
      consumer_thread.join();
  
      // verify the iteration count
      if (verify != iteration_count)
      {
          std::cout &lt;&lt; "verify: " &lt;&lt; verify &lt;&lt; " != " &lt;&lt; iteration_count &lt;&lt; std::endl;
          return;
      }
  
      // print the results
      auto total_time_ns = duration_cast&lt;nanoseconds&gt;(end_time - start_time).count();
      auto cost_per_pop = total_time_ns / iteration_count;
      std::cout
          &lt;&lt; "iterations: "
          &lt;&lt; std::setw(6) &lt;&lt; iteration_count
          &lt;&lt; ", total time: "
          &lt;&lt; std::setw(9) &lt;&lt; total_time_ns &lt;&lt; " ns"
          &lt;&lt; ", average time: "
          &lt;&lt; std::setw(5) &lt;&lt; cost_per_pop &lt;&lt; " ns"
          &lt;&lt; std::endl;
  }
  
  
  void test_bounded_queue(uint32_t iteration_count)
  {
      typedef std::chrono::high_resolution_clock Clock;
      using std::chrono::duration_cast;
      using std::chrono::nanoseconds;
  
      tbb::concurrent_bounded_queue&lt;uint32_t&gt; bounded_queue;
  
      uint32_t verify = 0;
  
      Clock::time_point start_time, end_time;
  
      std::thread consumer_thread([&amp;]
      {
          start_time = Clock::now();
  
          while (true)
          {
              uint32_t n;
              bounded_queue.pop(n); // waits, no CPU usage
              if (n == uint32_t(-1))
              {
                  end_time = Clock::now();
                  return;
              }
              verify += n;
          }
      });
  
      for (unsigned i = 0; i != iteration_count; ++i)
      {
          bounded_queue.push(1);
      }
  
      // stop the thread
      bounded_queue.push(uint32_t(-1));
      consumer_thread.join();
  
      // verify the iteration count
      if (verify != iteration_count)
      {
          std::cout &lt;&lt; "verify: " &lt;&lt; verify &lt;&lt; " != " &lt;&lt; iteration_count &lt;&lt; std::endl;
          return;
      }
  
      // print the results
      auto total_time_ns = duration_cast&lt;nanoseconds&gt;(end_time - start_time).count();
      auto cost_per_pop = total_time_ns / iteration_count;
      std::cout
          &lt;&lt; "iterations: "
          &lt;&lt; std::setw(6) &lt;&lt; iteration_count
          &lt;&lt; ", total time: "
          &lt;&lt; std::setw(9) &lt;&lt; total_time_ns &lt;&lt; " ns"
          &lt;&lt; ", average time: "
          &lt;&lt; std::setw(5) &lt;&lt; cost_per_pop &lt;&lt; " ns"
          &lt;&lt; std::endl;
  }
  
  
  const uint32_t min_iterations = 1u;
  const uint32_t max_iterations = 128u * 1024u;
  
  
  void test_bounded()
  {
      std::cout &lt;&lt; "Test bounded queue" &lt;&lt; std::endl;
      for (uint32_t i = min_iterations; i &lt;= max_iterations; i *= 2)
      {
          test_bounded_queue(i);
      }
      std::cout &lt;&lt; std::endl;
  }
  
  
  void test_unbounded()
  {
      std::cout &lt;&lt; "Test unbounded queue" &lt;&lt; std::endl;
      for (uint32_t i = min_iterations; i &lt;= max_iterations; i *= 2)
      {
          test_unbounded_queue(i);
      }
      std::cout &lt;&lt; std::endl;
  }
  
  
  } // namespace
  
  
  int main()
  {
      test_bounded();
      test_unbounded();
  }
  </code></pre>
  
  <p>The output looks like this:</p>
  
  <pre><code>+ g++ -std=c++11 -O2 -Wall -pedantic -pthread main.cpp -ltbb
  + ./a.out
  Test bounded queue
  iterations:      1, total time:      4861 ns, average time:  4861 ns
  iterations:      2, total time:      2901 ns, average time:  1450 ns
  iterations:      4, total time:      3111 ns, average time:   777 ns
  iterations:      8, total time:      3002 ns, average time:   375 ns
  iterations:     16, total time:      3475 ns, average time:   217 ns
  iterations:     32, total time:      4514 ns, average time:   141 ns
  iterations:     64, total time:      6329 ns, average time:    98 ns
  iterations:    128, total time:     12952 ns, average time:   101 ns
  iterations:    256, total time:     53654 ns, average time:   209 ns
  iterations:    512, total time:    178558 ns, average time:   348 ns
  iterations:   1024, total time:    395186 ns, average time:   385 ns
  iterations:   2048, total time:    886728 ns, average time:   432 ns
  iterations:   4096, total time:   1865523 ns, average time:   455 ns
  iterations:   8192, total time:   3535521 ns, average time:   431 ns
  iterations:  16384, total time:   7044609 ns, average time:   429 ns
  iterations:  32768, total time:  15743366 ns, average time:   480 ns
  iterations:  65536, total time:  32278651 ns, average time:   492 ns
  iterations: 131072, total time:  62466063 ns, average time:   476 ns
  
  Test unbounded queue
  iterations:      1, total time:      2952 ns, average time:  2952 ns
  iterations:      2, total time:      2378 ns, average time:  1189 ns
  iterations:      4, total time:      2463 ns, average time:   615 ns
  iterations:      8, total time:      2874 ns, average time:   359 ns
  iterations:     16, total time:      3094 ns, average time:   193 ns
  iterations:     32, total time:      3542 ns, average time:   110 ns
  iterations:     64, total time:      4138 ns, average time:    64 ns
  iterations:    128, total time:      6380 ns, average time:    49 ns
  iterations:    256, total time:     14647 ns, average time:    57 ns
  iterations:    512, total time:    103661 ns, average time:   202 ns
  iterations:   1024, total time:    275176 ns, average time:   268 ns
  iterations:   2048, total time:    564442 ns, average time:   275 ns
  iterations:   4096, total time:   1182691 ns, average time:   288 ns
  iterations:   8192, total time:   2278423 ns, average time:   278 ns
  iterations:  16384, total time:   4767694 ns, average time:   290 ns
  iterations:  32768, total time:   9382879 ns, average time:   286 ns
  iterations:  65536, total time:  18611420 ns, average time:   283 ns
  iterations: 131072, total time:  34437811 ns, average time:   262 ns
  </code></pre>
  
  <p>With a high number of iterations the average time averages to 400-500 ns for the bounded queue and 200-300 ns for the unbounded queue.</p>
  
  <p>For low iteration counts I would expect that "warm-up" overhead would increase the average time. However, sometimes it is only ~50 ns.</p>
  
  <p>How can this be?</p>