[erlang-questions] Measuring message queue delay

[Jesper Louis Andersen]

On Wed, Apr 29, 2015 at 11:12 AM, Roger Lipscombe <roger@REDACTED>
wrote:

> I thought of posting a message to self(), with a timestamp and then
> measuring the delta. I could then post another one as soon as that
> message is processed. Obviously, this leaves the process continually
> looping, which is not good.
>

I don't think this should be thrown out. It is salvagable, I think, and
here is how:

We update our gen_server with a new element in the state record:

-record(state, { ..., marker_active = false }).

Whenever we get a normal message, we check this state:

handle_call(Msg, From, #state { marker_active = false } = State) ->
    self() ! {marker, erlang:monotonic_time()},
    handle_call(Msg, From, State#state { marker_active = true });
....

Of course handle_cast/2 and handle_info/2 needs the same treatment. This
means whenever there is flow in the mailbox, we enable a marker with a
timestamp.

Now, we handle the marker:

handle_info({marker, Old}, State) ->
    Diff = erlang:monotonic_time() - Old,
    report_to_hdrhistogram(erlang:convert_time_unit(Diff, native,
milli_seconds)),
    {noreply, State#state { marker_active = false }}
...

This means once we get a marker, we process its queue sojourn latency, but
we avoid reinjecting a new marker. The next processed message will do that.

In turn, if you have 1 message going in, there will be exactly one marker.
But if other processes manages to enter 100 messages between a marker and
the next one, then we have one marker per 100 messages. The process will
never spin if there is nothing to process. An alternative is to add some
sampling interval delay:

handle_info({marker, Old}, State) ->
    Diff = erlang:monotonic_time() - Old,
    report_to_hdrhistogram(erlang:convert_time_unit(Diff, native,
milli_seconds)),
    timer:send_after(50, self(), rearm_marker),
    {noreply, State};
handle_info(rearm_marker, State) ->
    {noreply, State#state { marker_active = false }};
...

which closes off the problem where you have markers all over the place all
the time.

The essential idea is to use the arrival of a "normal" message as a trigger
for invoking a time sojourn marker. And never have the marker itself
reinject a marker so it can't cycle. In turn, there has to be a flux
through your mailbox queue for the markers to get added, and if there is no
flux, no marker will ever get added. The really astute reader will prove my
ramblings :)

-- 
J.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20150429/a616e5c3/attachment.htm>