Question
GenServer.call latency measurement vs Telemetry instrumentation: selecting an accurate approach
Mira Lane
0 reputation · 14 Sept 2022, 17:15 UTC
84K views1
Loading…
0 reputation · 14 Sept 2022, 17:15 UTC
When a GenServer receives a high‑frequency synchronous request, the round‑trip time of GenServer.call/3 can become a performance bottleneck. Two documented ways to capture this latency are :timer.tc/1 (or :erlang.monotonic_time/0) and Telemetry events emitted by the BEAM runtime. Each technique has subtle interactions with the scheduler, message queue, and measurement overhead.
Using :timer.tc gives a raw time span in microseconds but adds a function call for every measurement, which can itself influence the observed latency. Telemetry, on the other hand, emits events that can be collected by handlers; while the event payload is lightweight, the handler code and any downstream processing may introduce additional delay. Moreover, the BEAM scheduler flags (+P, +Qw, +sbwt) can change preemption behavior, affecting both measurement methods independently of the GenServer logic.
Deciding which method to use before optimising the GenServer is therefore non‑trivial. The goal is to obtain a trustworthy baseline that reflects the true cost of a call under realistic load, without the measurement itself becoming the bottleneck.
:timer.tc skew the latency measurement for a GenServer handling thousands of calls per second?:timer.tc approach?33775 reputation · 15 Sept 2022, 02:11 UTC
For a trustworthy baseline of GenServer.call/3 latency you should emit a Telemetry event on call entry and compute the delta with :erlang.monotonic_time/0. Keep the handler minimal or run it asynchronously; this gives a measurement that reflects the true call time plus a small, consistent wrapper cost. If you need per‑microsecond precision, use :timer.tc on a no‑op call to determine the wrapper overhead and subtract it from the raw measurement.
elixir:timer.tc is a function call that the BEAM treats like any other code, so its overhead is subject to the same scheduling as the call itself. Under thousands of calls per second this can dominate the measured latency if the GenServer does little work.handle_call/3 returns. The emission is lightweight, but any synchronous handler (e.g., logging) runs in the same process and can add noticeable delay. Asynchronous handlers (Task.start/1) keep the measured latency close to the raw call time.+P (preemption threshold) and +sbwt (fair scheduling) influence how quickly a GenServer receives its message. Using a higher +P value reduces latency variance for both measurement methods, while +Qw can introduce jitter.:timer.tc.:myapp.gen_server.call, and emit it at the start of handle_call/3 with the current monotonic timestamp.
def handle_call(msg, _from, state) do
start = :erlang.monotonic_time(:microsecond)
:telemetry.execute([:myapp, :gen_server, :call], %{duration: 0}, %{start: start})
# … real work …
:telemetry.execute([:myapp, :gen_server, :call], %{duration: 0}, %{end: :erlang.monotonic_time(:microsecond)})
end
start and end timestamps and calculates the delta. If you need to keep the handler asynchronous, spawn a Task that writes the delta to a file or a statsd client.
benchee or :telemetry_poller) and collect the latency distribution. This represents the true call cost plus the minimal wrapper.
:timer.tc on a no‑op call:
overhead = :timer.tc(fn -> :ok end) |> elem(0)
overhead from the raw :timer.tc results to isolate the GenServer work.
+P 1000 and +sbwt in the VM startup arguments and re‑measure; compare variance.
To fine‑tune the recommendation, could you share the typical amount of work your GenServer performs per call (e.g., CPU cycles, I/O operations)? This will help decide whether the wrapper overhead is a significant fraction of the total latency.
| Method | Overhead | Handler Impact | Scheduler Sensitivity |
|---|---|---|---|
:timer.tc | ≈5‑10 µs | None | High |
| Telemetry + monotonic | ≈1‑2 µs | Depends on handler | Moderate |
| Telemetry + async handler | ≈1‑2 µs | Low | Low |
Use comments to ask for clarification. Post a solution as an answer.
33,775 reputation · 14 Sept 2022, 23:36 UTC
When you attach a handler to the :gen_server, :call event, the BEAM runtime already supplies a :duration field that spans from the GenServer.call/3 invocation to the moment the reply is sent. The payload itself is tiny, but any handler code runs after the reply, so the measured duration includes that handler’s execution time. A common pattern is to register a no‑op handler that simply records the :duration value, keeping the overhead below 5 µs.
Using :erlang.monotonic_time/0 around the call gives nanosecond precision and avoids the extra function call that :timer.tc/1 introduces. Converting the elapsed ticks to microseconds is trivial, and the overhead is typically an order of magnitude lower.
Running the VM with +Qw (preemption disabled) produces the most stable latency readings because the scheduler never preempts a running process. However, this setting hides real‑world contention. The +sbwt flag is a good compromise: it keeps the scheduler in back‑off mode, reducing jitter while still allowing preemption to surface when the system is under load.