Statistical probes

[pflanze]

Currently, evobench probes are measuring/logging every time the code path where they are placed is executed. For higher-up levels in the code, that is fine.

But sometimes one wishes to benchmark hot code regions. There are two problems using the current approach for those:

1. precision: the measurement and logging has overheads, and while the code region inside this probe's scope may still be OK, timings of probes higher up in the stack include the overhead of the inner scopes (it's possible this could be compensated to some extent, though, if done carefully).

2. log file size: the log files quickly grow very large and become costly to handle.

Statistical probes instead would only do measurement and logging every $n calls, where $n is some specified number, but randomized to avoid aliasing effects. E.g.

EVOBENCH_SCOPE_EVERY(1000, "foo", "bar")

would calculate a random number between 0 and 1000 (say 418) and store it in a counter local to this probe, then decrement until it reaches 0, in which case a measurement and logging is done and then the process repeats.

Open questions:

• Can thread and static be combined to get function-static variables that are also thread-local? How is their initialization behaviour?

Required work:

• A good enough fast PRNG that's easy to access; what shall it be?

• Changes in the probes library:

  • The new log message kind
  • The EVOBENCH_SCOPE_EVERY macro implementation

• Changes in the evaluator:

  • The new log message kind.
  • Calculation for statistics accordingly.
  • Representation ("tagging") in output somehow, so that readers can be aware of the "n chosen too large" pitfall. Idea: just prefix the count to the probe name, e.g. 1000|foo|bar.

Some additional details:

• If n is so large that the calculated random number is larger than the total number the probe is called, then no logging will be done at all if it works as described above. Maybe the EVOBENCH_SCOPE_EVERY probe should measure+log the first time it is encountered, and calculate the random number first, and print it with the message; that way, some judgement could be done about how long the last period was before the probe is never called again (e.g. thread torn down).

[pflanze]

An idea could also be to make the normal probes keep the counter, and automatically go into statistical mode after a cutoff (say 100'000 calls; possibly also use say 1/1000 of the number of done calls as the max value for random number generation). Then one doesn't have to think about anything. This really implies that there will be a mix of approaches to getting the results though and we need to be sure there's no drawback to it (don't really see one currently, other than some extreme values like the ends of the percentiles being sensitive to outliers that might not show up when doing randomized collection).

But Alex said to just remove the hot probe we have now, so for now we can just be manually careful. (And ad-hoc hot spot examination can always be done via perf. It's probably usually the higher up areas that we want to watch automatically, not hot spots.) So this can probably be closed without a fix until the need shows up in the future.

[pflanze]

and automatically go into statistical mode

In the evaluator, need to be careful to not give the period at the beginning, where there are more data points, more weight--the later data point need to be weighed accordingly (multiplied with the random number) to accommodate for the blind times.

[pflanze]

4c5c677 (changes: 762e7c8...4c5c677) now contains a simplified version of such statistical (or shall we say sparse?) probes:

It adds this macro to the probes library: EVOBENCH_SCOPE_EVERY(n, module, action)

n is the number of times this probe is encountered per timing taken. It takes a timing the first time it is encountered, then skips n - 1 encounters, then repeats. It does not currently use randomization.

Example in SILO: GenSpectrum/LAPIS-SILO@4bebe4b...b06a6f1

Also it:

• adds the n value to the timing records; it is added as an optional field, so that the evaluator can read the old log files transparently (it just takes a default of 1 if the field is missing).

• updates the evaluator to handle the n values to weight the sparse measurements accordingly (it does that correctly (as far as I can see) even for the percentiles).

Example in SILO of the difference before and after the change:

Before: https://silo-benchmarks.genspectrum.org/api/CONCURRENCY%3D50/DATASET%3DSC2open/RANDOMIZED%3D1/REPEAT%3D1/SORTED%3D0/9988e227e808db769961a5c84f733ce33fc250f8/summary-%22night%22-sys%20time.svg

After: https://silo-benchmarks.genspectrum.org/api/CONCURRENCY%3D50/DATASET%3DSC2open/RANDOMIZED%3D1/REPEAT%3D1/SORTED%3D0/b06a6f14f27c95ca8d12d285c9e330b4e4b8887b/summary-%22night%22-sys%20time.svg

In the first flamegraph one can see that QueryPlan|writeBatchAsNdjson has a high additional cost, this will just be because the cost of actually logging QueryPlan|sendDataToOutputStream is so high that half of it is attributed to the parent frame. In the second flamegraph, since the cost is now negligible over all, the parent only accounts for the cost inside. (But todo: verify the cases where child frame probes sum up to larger values than their parent frame.)

The compressed benchmark log files have gone from ~871 MB before, to ~37 MB now, so the previously costly (and badly working) probe in SILO can be left in the code with the change.

(Note: those new sparse probes should only be used in leaf locations (no further probes nested inside them), or the output will probably be confusing to read, since the probe's stack frame is missing when the probe doesn't log--all possible combinations of this probe and other nested probes will each generate a separate line of output in the call path based representation.)

[pflanze]

I think this can be closed as "completed":

• Even though the current implementation is not randomized (but uses a fixed skip count), it seems to work well so far and may do all we want? It may be rare that randomization is really necessary.

• Automatic scaling is complex, especially as nested scopes need the context so there is that "leaf only" issue that remains, thus nested random probes need to work together somehow.

Not worth spending time thinking about at this time, so better close and re-open or make a new ticket when the need arises in the future.