LTTng » Babeltrace

I can confirm some discrepancy between Babeltrace and the Java TMF implementation. It seems the time ranges reported by Babeltrace are "offset" with regards to the lost events:

Using the trace at http://www.dorsal.polymtl.ca/~alexmont/data/hello-lost.tar.bz2 , the first few lost event ranges reported by TMF are (seconds are all "1376592664", I removed them for brevity):

[828,848,222 to 828,848,540], 859 lost events
[829,402,521 to 829,403,076], 488 lost events
[829,823,874 to 829,824,514], 884 lost events

and the first lost events reported by Babeltrace:

[829,402,521 to 829,403,076], 859 lost events
[829,823,874 to 829,824,514], 488 lost events
[830,394,108 to 830,394,755], 884 lost events

As you can see, the time ranges reported by Babeltrace are "offset" by one lost event range. I'm tempted to believe that the results reported by TMF are the correct ones, or it would have completely invented that first time range...

The original bug report indicates that Babeltrace reports the lost events too early and the update says they are too late. Do both cases occur or is one of the reports wrong?

Here is a tentative fix.

To make it easier to diagnose the problem, I have created a trace which contains three packets, each announcing a single discarded event.

Packet 1: 1 event with clock cycle 0
Packet 2: 1000 events at clock cycles (1 to 1000)
Packet 3: 1 event with clock cycle 1001

Here is babeltrace's output with my proposed patch

$ ./converter/babeltrace --clock-cycles /tmp/ctfwriter_9ogyvU/ | grep "Tracer discarded" 
[warning] Tracer discarded 1 events between [00000000000000000000] and [00000000000000000000] in trace UUID 50fe6b07cf54c1e94bb58e8137b37b, at path: "/tmp/ctfwriter_9ogyvU", within stream id 0, at relative path: "test_stream_0". You should consider recording a new trace with larger buffers or with fewer events enabled.
[warning] Tracer discarded 1 events between [00000000000000000001] and [00000000000000001000] in trace UUID 50fe6b07cf54c1e94bb58e8137b37b, at path: "/tmp/ctfwriter_9ogyvU", within stream id 0, at relative path: "test_stream_0". You should consider recording a new trace with larger buffers or with fewer events enabled.
[warning] Tracer discarded 1 events at end of stream between [00000000000000001001] and [00000000000000001001] in trace UUID 50fe6b07cf54c1e94bb58e8137b37b, at path: "/tmp/ctfwriter_9ogyvU", within stream id 0, at relative path: "test_stream_0". You should consider recording a new trace with larger buffers or with fewer events enabled.

Can you add TMF's output so we can compare?

With the patch I prepared (added to this bug), we get, on Jeremie's test case:

[warning] Tracer discarded 1 events between [00000000000000000000] and [00000000000000000000] in trace UUID 50fe6b07cf54c1e94bb58e8137b37b, at path: ".", within stream id 0, at relative path: "test_stream_0". You should consider recording a new trace with larger buffers or with fewer events enabled.
[warning] Tracer discarded 1 events between [00000000000000000000] and [00000000000000001000] in trace UUID 50fe6b07cf54c1e94bb58e8137b37b, at path: ".", within stream id 0, at relative path: "test_stream_0". You should consider recording a new trace with larger buffers or with fewer events enabled.
[warning] Tracer discarded 1 events between [00000000000000001000] and [00000000000000001001] in trace UUID 50fe6b07cf54c1e94bb58e8137b37b, at path: ".", within stream id 0, at relative path: "test_stream_0". You should consider recording a new trace with larger buffers or with fewer events enabled.

Important comment added in the patch:

/* * Discarded events can be either: * - discarded after end of previous buffer due to buffer full: * happened within range: [ prev_timestamp_end, timestamp_begin ] * - discarded within current buffer due to either event too large or * nested wrap-around: * happened within range: [ timestamp_begin, timestamp_end ] * * Given we have discarded counters of those two types merged into the * events_discarded counter, we need to use the union of those ranges: * [ prev_timestamp_end, timestamp_end ]
*/

Please try it out and let me know what you think.

Thanks,

Mathieu

Can you guys have a look at this patch and comment ?

The result with Jeremie's test case is:

[warning] Tracer discarded 1 events between [00000000000000000000] and [00000000000000000000] in trace UUID 50fe6b07cf54c1e94bb58e8137b37b, at path: ".", within stream id 0, at relative path: "test_stream_0". You should consider recording a new trace with larger buffers or with fewer events enabled.
[warning] Tracer discarded 1 events between [00000000000000000000] and [00000000000000001000] in trace UUID 50fe6b07cf54c1e94bb58e8137b37b, at path: ".", within stream id 0, at relative path: "test_stream_0". You should consider recording a new trace with larger buffers or with fewer events enabled.
[warning] Tracer discarded 1 events between [00000000000000001000] and [00000000000000001001] in trace UUID 50fe6b07cf54c1e94bb58e8137b37b, at path: ".", within stream id 0, at relative path: "test_stream_0". You should consider recording a new trace with larger buffers or with fewer events enabled.

The range is from the end of the previous buffer to the end of the current buffer (see comment in code).

Fixed by:

commit 2654fe9bab8f0eaeb17264ef7abadfd14e245b23
Author: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Date:   Tue Feb 25 17:36:11 2014 -0500

    Fix: events discarded timing inaccuracy

    Introduce babeltrace_ctf_console_output too, to ensure we only print
    discarded events when a text output is used.

    Fixes #589

    Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>