Hello Mathieu, > Already fixed this morning by commit: > > commit 9080554ff25b08f48762d2ee7cfa3981317e9c1d > Author: Mathieu Desnoyers <[email protected]> > 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 <[email protected]> > > 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 _______________________________________________ lttng-dev mailing list [email protected] http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
