Bug #1260
openBabeltrace 2 refuses a trace when a previous packet has an end time > begin of the next packet
0%
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 muxer_msg_iter_do_next_one@muxer.c: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 clock_snapshots_are_monotonic_one@iterator.c:580 Got a message with timestamp 1575594328184404010 of type 4
04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER clock_snapshots_are_monotonic_one@iterator.c:580 Got a message with timestamp 1575594471692837471 of type 4
04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER clock_snapshots_are_monotonic_one@iterator.c: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 clock_snapshots_are_monotonic_one@iterator.c:580 Got a message with timestamp 1575594527642470600 of type 8 <--
04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER call_iterator_next_method@iterator.c:802 Babeltrace 2 library postcondition not satisfied; error is:
04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER call_iterator_next_method@iterator.c: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