[lttng-dev] background information about LTTng timestamps

[Sébastien Barthélémy]

Hello Mathieu,

> Already fixed this morning by commit:
>
> commit 9080554ff25b08f48762d2ee7cfa3981317e9c1d
> Author: Mathieu Desnoyers <mathieu.desnoyers at efficios.com>
> Date:   Mon Jan 9 11:42:57 2012 -0500
>
>    Fix timestamps for slow-paced event rates
>
>    Given that we currently do not implement any timer that provides
>    guarantees of 27-bit timestamps overflow detection, force the timestamp
>    to 64-bit.
>
>    Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com>
>
> Please try with LTTng-UST git head.

I just tried, but I still see glitches here. They might well be real
sync problems in
our app. I'll further investigate the matter.

I also had another look at lttng timestamps.
Here is what I understood, could you please correct me if I'm wrong?

Each time an active tracepoint is met, an event (a.k.a. a record) is created by
the probe, which runs within the context (priority etc.) of the probed thread.

The event_header holds a timestamp, created at probe time (so I expect no
latency) from a call to clock_gettime(CLOCK_MONOTONIC,...).

if RING_BUFFER_RFLAG_FULL_TSC is set, the full 64bit timestamp is stored.
Otherwise, only the cfg.tsc_bits least significant bits are stored.

lib_ring_buffer_reserve_slow and lib_ring_buffer_save_slow set
RING_BUFFER_RFLAG_FULL_TSC when they detect that the trimmed
timestamp has overflown. Thus we should get in the buffer a sequence of
events with

- a full timestamp
- partial timestamps for the events occurring within the next
2**cfg.tsc_bits-1 nanoseconds
- a full timestamp
- ... and so on

The overflow detection is done by storing the min(64 - cfg.tsc_bits,
32) most significant bits of the last
timestamp, and comparing it to the new one (at least on 32bits archs).

I think it actually works this way if large event headers are used.

However, I do not understand some details in the case of compact event headers :

In such a case only the 27 least significant bits of the timestamp are
stored in the event header.
However I could not find the place where cfg.tsc_bits is set to 27. Is
there any?

If  cfg.tsc_bits is kept to 32, the overflow detection misses
2**(32-27) overflows, am I right?

In such a case I would get events reported a multiple (between 1 and
2**5-1) of 2**27ns (134ms)
earlier than the time they really occurred.
I don't think this is happening here: I have phony tracepoints that
get a timespec as argument, an
which would have detected that.

In such a case how could it possibly work? Your commit message
mentions timers. A timer would
force a full 64bits timer in the buffer every 2**(27) ns?

Maybe in the case of compact header, another code path is used and
overflow detection is never done?

You also mentions slow-paced event rates. The cycle time of my
application is typically 10ms,
but I may have cycle time errors leading to blackouts as long as 200ms .


Thank you again for your help,
(and, by the way, for LTTng too ;)

Best regards
-- Sébastien