ANN bench fix latency measurement overhead

[tfeher]

The CPU time stamp start is taken before the ANN algo is copied to all threads. This is fixed by initializing start a few lines later.

[achirkin]

The move of .lap() functions breaks the functionality. I'd suggest to only leave change that moves start to initialize after the algo is copied.

[achirkin]

There also seems to be a problem with how we compute both "Latency" and "GPU" counters. In both cases, we divide the the values by the number of iterations state.iterations() to compute the average.
However, we don't know how many times the counter is stored and what's the value of state.iterations() at these moments. You see, gbench can probably call the same benchmark case multiple times within a single thread. It may do so to control the overall benchmark time. If that's the case, the counter values are summed up, which is not what we want to compute.

I've tried to add this change and compare the benchmark outputs:

...
    auto end      = std::chrono::high_resolution_clock::now();
    auto duration = std::chrono::duration_cast<std::chrono::duration<double>>(end - start).count();
    if (state.thread_index() == 0) { state.counters.insert({{"end_to_end", duration}}); }
    state.counters.insert(
      {"Latency",
       {duration, benchmark::Counter::kAvgThreads | benchmark::Counter::kAvgIterations}});
  }

  state.SetItemsProcessed(queries_processed);
  if (cudart.found()) {
    state.counters.insert({"GPU",
                           {gpu_timer.total_time(),
                            benchmark::Counter::kAvgThreads | benchmark::Counter::kAvgIterations}});
...

As a result I've got Latency counter match almost perfectly with the real_time counter (make sure start time is initialized after the index copy though), this confirms that there's a redundancy between Latency and real_time and that we measured Latency and GPU time incorrectly until now.

NB: "items_per_second" metric has always been using "real_time" under the hood, so we can rely on it being correct in our previous benchmark results.

[tfeher]

@achirkin gbench real_time is not the value that we want to define as latency. See details here: #1940 (comment)

[achirkin]

Thanks, @tfeher , for clarification! Indeed, now I see that the total iterations counter sums the iterations from all threads, whereas the real_time counts the time only by the main thread; as a result, the real_time shows the proper average latency divided by the number of threads.

This means the GPU counter is probably correct and the Latency counter is probably only slightly off due to the wrapper copy overheads.

In that case, I modify my suggestion: to be on the safe side, let's replace the explicit state.iterations() division with the kAvgIterations flag; it divides the total time by the total number of iterations (in all threads), hence gives the proper average latency for a single thread:

...
    auto end      = std::chrono::high_resolution_clock::now();
    auto duration = std::chrono::duration_cast<std::chrono::duration<double>>(end - start).count();
    if (state.thread_index() == 0) { state.counters.insert({{"end_to_end", duration}}); }
    state.counters.insert({"Latency", {duration, benchmark::Counter::kAvgIterations}});
  }

  state.SetItemsProcessed(queries_processed);
  if (cudart.found()) {
    state.counters.insert({"GPU", {gpu_timer.total_time(), benchmark::Counter::kAvgIterations}});
  }
...

[tfeher]

The PR is reduced to fixing the starting of the timer. Other overheads are not addressed. For reference, here is the other issue that was discussed in a previous version of the PR.

The current latency measurement includes overhead in the order of 10 microseconds, which is visible when we compare the benchmark output columns "GPU" and "Latency". This could be significant for benchmarks with small batch size.

This overhead is mainly due to the lap() call within the benchmark loop. It would be probably better to make it optional to measure GPU latency.

[tfeher]

I have also applied Artem's suggestion to store latency values with benchmark::Counter::kAvgIterations marker.

Earlier we manually divided by number of iterations and let gbench average over threads using kAvgThreads. Since iterations are counted as total iterations performed by all threads, using kAviIterations leads to the same results (without manual divisions by iterations).

[achirkin]

LGTM!

[cjnolet]

/merge