[ltt-dev] LTTng 2.0, error in packet timestamp boundaries

[Mathieu Desnoyers]

* Simon Marchi (simon.marchi at polymtl.ca) wrote:
> Hello there,
> 
> I gathered this trace (CTF format) using the git head of lttng tools
> and modules as of today:
> 
> http://nova.polymtl.ca/~simark/aaa-20110802-100934.tgz
> 
> When I inspect the first two event packets of the file channel0_0 by
> hand, I find :
> 
> Packet 1 begin timestamp, found at offset 0x18:   0x0001750964CA677E
> Packet 1 end timestamp,   found at offset 0x20:   0x0001750A2E080C19
> 
> Packet 2 begin timestamp, found at offset 0x1018: 0x0001750A2E0808D1
> Packet 2 end timestamp,   found at offset 0x1020: 0x0001750A2E7508F5
> 
> It appears that the packet 2 begin timestamp is before the packet 1
> end timestamp. I have been told that this should not occur, that the
> timestamp ranges of consecutive packets should not overlap.
> 
> Is this an error in the tracer or is this a normal behaviour ?

OK, I finally got my head around this. Everything is OK, "Don't panic"
(in big friendly letters) ;)

First, as a summary, I should say that the packet "timestamp end" can be
higher than the next packet's "timestamp begin" in CTF traces produced
by LTTng.

The reason why is because the "timestamp begin" field is filled by the
record space reservation, but "timestamp end" is filled by the last
commit that fills a packet. Given that commits are executed out of
order, and also given that I read a timestamp from the clock source in
the commit code when filling a packet, that means the next packet
"timestamp begin" will always be slightly lower than the "timestamp end"
of the previous packet.

Here is the order of operations:

loop until space reservation succeeds:
  read timestamp for new event
  try space reservation

if there is not enough space in the current packet for event:
  write next packet header info, including "timestamp begin"
  using the same timestamp as used for the event.

let the tracer write the event header and payload

update of commit counter
  it notices that the previous sub-buffer has been filled,
  so lib_ring_buffer_check_deliver() calls cb.ring_buffer_clock_read()
  and passes this timestamp to cb.buffer_end(), which writes the
  "timestamp end" value.

So we notice that the previous buffer's "timestamp end" is actually
sampled a little later than the next "timestamp begin".

The real guarantee we have with timestamps is that all the events in a
packet are included (inclusive) within the begin/end timestamps of the
packet. Another guarantee we have is that the "timestamp begin", as well
as the event timestamps, are monotonically increasing (never decrease)
when moving forward in a stream (physically). But this guarantee does
not apply to "timestamp end", because it is sampled at commit time,
which is not ordered with respect to space reservation.

I added a comment in the lttng-modules code explaning this.

Thanks!

Mathieu

> 
> Thanks,
> 
> Simon
> 
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> 

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com