Project

General

Profile

Bug #1260

Babeltrace 2 refuses a trace when a previous packet has an end time > begin of the next packet

Added by Geneviève Bastien 4 months ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
-
Start date:
04/28/2020
Due date:
% Done:

0%

Estimated time:

Description

With babeltrace 1, the trace is read fine, event timestamps are monotonic. With babeltrace2 it aborts with message

04-22 16:58:59.461 97893 97893 E PLUGIN/FLT.UTILS.MUXER :1079 [muxer] Youngest upstream message iterator wrapper's timestamp is less than muxer's message iterator's last returned timestamp: muxer-msg-iter-addr=0x55b2214faf20, ts=1575594527642470600, last-returned-ts=1575594527642472275

Some investigation shows that the reason for this is that end time of a packet > start time of next packet in a stream (pktB.begin < pktA.end)

However, from the spec, it would seem that this case should be supported:

Time-stamp at the beginning and timestamp at the end of the event packet. Both timestamps are written in the packet header, but sampled respectively while (or before) writing the first event and while (or after) writing the last event in the packet. The inclusive range between these timestamps should include all event timestamps assigned to events contained within the packet. The timestamp at the beginning of an event packet is guaranteed to be below or equal the timestamp at the end of that event packet. The timestamp at the end of an event packet is guaranteed to be below or equal the timestamps at the end of any following packet within the same stream. See Clocks for more detail.

I made bt2 output some debug about the message types it gets when the error occurs and here is the output:

4-22 21:41:02.616 203722 203722 F LIB/MSG-ITER :580 Got a message with timestamp 1575594328184404010 of type 4
04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER :580 Got a message with timestamp 1575594471692837471 of type 4
04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER :580 Got a message with timestamp 1575594527642472275 of type 16 <-- notice the packet ends much later than the last event in it
04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER :580 Got a message with timestamp 1575594527642470600 of type 8 <--
04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER :802 Babeltrace 2 library postcondition not satisfied; error is:
04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER :802 Clock snapshots are not monotonic

type 16 is packet end and type 8 is packet begin. The non-monotonicity does not involve events, only packet times.

No data to display

Also available in: Atom PDF