* Simon Marchi ([email protected]) 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 > [email protected] > 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 _______________________________________________ ltt-dev mailing list [email protected] http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
