Fix: consumer-stream: live viewers observe timestamps going backwards
Observed issue
==============
When stress-testing over an entire weekend, we caught the following
occurrences of timestamps going backwards with babeltrace in live viewer
mode:
One occurrence:
# Test ust streaming live clear with viewer with new metadata after clear
# Parameters: tracing_active=0, clear_twice=0, buffer_type=pid
6-7 occurrences:
# Test ust basic streaming live with viewer
# Parameters: tracing_active=1, clear_twice=0, buffer_type=uid
Relevant log of the relayd focused on the context of the stream
triggering the issue (stream 994):
506:DBG1 - 17:26:54.
966288486 [
3866648/
3866655]: Relay viewer stream 994 not found (in viewer_stream_get_by_id() at viewer-stream.cpp:268)
603:DBG1 - 17:26:54.
970265349 [
3866648/
3866655]: Sending stream 994 to viewer (in send_viewer_streams() at live.cpp:241)
843:DBG1 - 17:26:55.
959835404 [
3866648/
3866652]: stream_add_index for stream 994 (in stream_add_index() at stream.cpp:1233)
844:DBG3 - 17:26:55.
959866303 [
3866648/
3866652]: Finding index for stream id 994 and seq_num 0 (in relay_index_get_by_id_or_create() at index.cpp:112)
845:DBG2 - 17:26:55.
959896611 [
3866648/
3866652]: Creating relay index for stream id 994 and seqnum 0 (in relay_index_create() at index.cpp:34)
846:DBG2 - 17:26:55.
959928097 [
3866648/
3866652]: Adding relay index with stream id 994 and seqnum 0 (in relay_index_add_unique() at index.cpp:70)
847:DBG2 - 17:26:55.
959968163 [
3866648/
3866652]: Index found or created in HT for stream ID 994 and seqnum 0 (in relay_index_get_by_id_or_create() at index.cpp:144)
884:DBG3 - 17:26:55.
961676906 [
3866648/
3866652]: Receiving data for stream id 994 seqnum 0, 0 bytes received, 84 bytes left to receive (in relay_process_data_receive_payload() at main.cpp:3583)
885:DBG1 - 17:26:55.
961783540 [
3866648/
3866652]: Wrote to stream 994: data_length = 84, padding_length = 0 (in stream_write() at stream.cpp:1113)
886:DBG1 - 17:26:55.
961862441 [
3866648/
3866652]: Wrote to stream 994: data_length = 0, padding_length = 4012 (in stream_write() at stream.cpp:1113)
887:DBG1 - 17:26:55.
961895593 [
3866648/
3866652]: handle_index_data: stream 994 net_seq_num 0 data offset 0 (in stream_update_index() at stream.cpp:1140)
888:DBG3 - 17:26:55.
961945901 [
3866648/
3866652]: Finding index for stream id 994 and seq_num 0 (in relay_index_get_by_id_or_create() at index.cpp:112)
889:DBG2 - 17:26:55.
961983056 [
3866648/
3866652]: Index found or created in HT for stream ID 994 and seqnum 0 (in relay_index_get_by_id_or_create() at index.cpp:144)
894:DBG2 - 17:26:55.
962334285 [
3866648/
3866652]: Writing index for stream ID 994 and seq num 0 (in relay_index_try_flush() at index.cpp:275)
895:DBG2 - 17:26:55.
962390756 [
3866648/
3866652]: index put for stream id 994 and seqnum 0 refcount 1 (in relay_index_put() at index.cpp:237)
1743:DBG1 - 17:26:56.
083287172 [
3866648/
3866655]: Check index status: index_received_seqcount 1 index_sent_seqcount 0 for stream 994 (in check_index_status() at live.cpp:1454)
1746:DBG1 - 17:26:56.
083446379 [
3866648/
3866655]: Sending viewer index for stream 994 offset 0 (in viewer_get_next_index() at live.cpp:1801)
1748:DBG1 - 17:26:56.
083544877 [
3866648/
3866655]: Index 1 for stream 994 sent (in viewer_get_next_index() at live.cpp:1842)
1751:DBG1 - 17:26:56.
083778149 [
3866648/
3866655]: Sent 4108 bytes for stream 994 (in viewer_get_packet() at live.cpp:1968)
2858:DBG1 - 17:26:56.
907744916 [
3866648/
3866652]: stream_add_index for stream 994 (in stream_add_index() at stream.cpp:1233)
2859:DBG1 - 17:26:56.
907762798 [
3866648/
3866652]: Received live beacon for stream 994 (in stream_add_index() at stream.cpp:1237)
2862:DBG3 - 17:26:56.
907855597 [
3866648/
3866652]: Receiving data for stream id 994 seqnum 1, 0 bytes received, 84 bytes left to receive (in relay_process_data_receive_payload() at main.cpp:3583)
2863:DBG1 - 17:26:56.
907950195 [
3866648/
3866652]: Wrote to stream 994: data_length = 84, padding_length = 0 (in stream_write() at stream.cpp:1113)
2864:DBG1 - 17:26:56.
908002911 [
3866648/
3866652]: Wrote to stream 994: data_length = 0, padding_length = 4012 (in stream_write() at stream.cpp:1113)
2865:DBG1 - 17:26:56.
908024312 [
3866648/
3866652]: handle_index_data: stream 994 net_seq_num 1 data offset 4096 (in stream_update_index() at stream.cpp:1140)
2866:DBG3 - 17:26:56.
908043082 [
3866648/
3866652]: Finding index for stream id 994 and seq_num 1 (in relay_index_get_by_id_or_create() at index.cpp:112)
2867:DBG2 - 17:26:56.
908061879 [
3866648/
3866652]: Creating relay index for stream id 994 and seqnum 1 (in relay_index_create() at index.cpp:34)
2868:DBG2 - 17:26:56.
908082115 [
3866648/
3866652]: Adding relay index with stream id 994 and seqnum 1 (in relay_index_add_unique() at index.cpp:70)
2869:DBG2 - 17:26:56.
908101275 [
3866648/
3866652]: Index found or created in HT for stream ID 994 and seqnum 1 (in relay_index_get_by_id_or_create() at index.cpp:144)
3011:DBG1 - 17:26:56.
913436908 [
3866648/
3866655]: Check index status: index_received_seqcount 1 index_sent_seqcount 1 for stream 994 (in check_index_status() at live.cpp:1454)
3012:DBG1 - 17:26:56.
913457688 [
3866648/
3866655]: Check index status: inactive with beacon, for stream 994 (in check_index_status() at live.cpp:1492)
3014:DBG1 - 17:26:56.
913507164 [
3866648/
3866655]: Index 1 for stream 994 sent (in viewer_get_next_index() at live.cpp:1842)
3043:DBG1 - 17:26:56.
914167206 [
3866648/
3866652]: stream_add_index for stream 994 (in stream_add_index() at stream.cpp:1233)
3044:DBG3 - 17:26:56.
914186324 [
3866648/
3866652]: Finding index for stream id 994 and seq_num 1 (in relay_index_get_by_id_or_create() at index.cpp:112)
3045:DBG2 - 17:26:56.
914205597 [
3866648/
3866652]: Index found or created in HT for stream ID 994 and seqnum 1 (in relay_index_get_by_id_or_create() at index.cpp:144)
3046:DBG2 - 17:26:56.
914227502 [
3866648/
3866652]: Writing index for stream ID 994 and seq num 1 (in relay_index_try_flush() at index.cpp:275)
3047:DBG2 - 17:26:56.
914299536 [
3866648/
3866652]: index put for stream id 994 and seqnum 1 refcount 1 (in relay_index_put() at index.cpp:237)
3587:DBG1 - 17:26:57.
067977800 [
3866648/
3866652]: Set begin data pending flag to stream 994 (in relay_begin_data_pending() at main.cpp:2240)
3644:DBG1 - 17:26:57.
070915787 [
3866648/
3866652]: Data pending for stream id 994: prev_data_seq 1, prev_index_seq 1, and last_seq 1 (in relay_data_pending() at main.cpp:2091)
3913:DBG1 - 17:26:57.
093492259 [
3866648/
3866652]: try_rotate_stream_index: Stream 994 (rotate_at_packet_seq_num = 2, received_packet_seq_num = (value = 1, is_set = 1)) (in try_rotate_stream_index() at stream.cpp:482)
3914:DBG1 - 17:26:57.
093525950 [
3866648/
3866652]: Rotating stream 994 index file (in try_rotate_stream_index() at stream.cpp:511)
3915:DBG1 - 17:26:57.
093561064 [
3866648/
3866652]: try_rotate_stream_data: Stream 994 (rotate_at_index_packet_seq_num = 2, rotate_at_prev_data_net_seq = 1, prev_data_seq = 1) (in try_rotate_stream_data() at stream.cpp:357)
3916:DBG1 - 17:26:57.
093591085 [
3866648/
3866652]: Rotating stream 994 data file with size 8192 (in stream_rotate_data_file() at stream.cpp:138)
3917:DBG1 - 17:26:57.
093626697 [
3866648/
3866652]: stream_rotate_data_file: reset tracefile_size_current for stream 994 was 8192 (in stream_rotate_data_file() at stream.cpp:169)
3918:DBG1 - 17:26:57.
093656578 [
3866648/
3866652]: Rotation completed for stream 994 (in stream_complete_rotation() at stream.cpp:66)
4238:DBG1 - 17:26:57.
635064782 [
3866648/
3866652]: Trying to close stream 994 (in try_stream_close() at stream.cpp:883)
4239:DBG1 - 17:26:57.
635098224 [
3866648/
3866652]: Succeeded in closing stream 994 (in try_stream_close() at stream.cpp:983)
4744:DBG1 - 17:26:57.
741972785 [
3866648/
3866655]: Check index status: index_received_seqcount 2 index_sent_seqcount 1 for stream 994 (in check_index_status() at live.cpp:1454)
4745:DBG1 - 17:26:57.
742030216 [
3866648/
3866655]: Sending viewer index for stream 994 offset 4096 (in viewer_get_next_index() at live.cpp:1801)
4747:DBG1 - 17:26:57.
742088421 [
3866648/
3866655]: Index 2 for stream 994 sent (in viewer_get_next_index() at live.cpp:1842)
4750:DBG1 - 17:26:57.
742197990 [
3866648/
3866655]: Sent 4108 bytes for stream 994 (in viewer_get_packet() at live.cpp:1968)
4755:DBG1 - 17:26:57.
932525633 [
3866648/
3866655]: Releasing stream id 994 (in stream_release() at stream.cpp:778)
4756:DBG1 - 17:26:57.
932555313 [
3866648/
3866655]: Rotation completed for stream 994 (in stream_complete_rotation() at stream.cpp:66)
Cause
=====
This log shows the following sequence:
consumer-data consumer-live-timer relayd-main relayd-live babeltrace
1) lttng_consumer_read_subbuffer
2) get next subbuf
3) write data packet to data socket
(starting here the data packet is
somewhere on the network)
4) put next subbuf
5) post_consume()
6) consumer_stream_sync_metadata_index()
7) wait for metadata
8) consumer_stream_sync_metadata()
9) check_stream()
10) set missed_metadata_flush
11) call send_live_beacon(()
12) sample empty ring buffer
13) read current timestamp
14) send inactivity beacon (empty packet)
15) receives a live beacon (@ 17:26:56.
907762798)
16) call consumer_stream_send_index()
17) send packet index to relayd
18) receives a data packet (@ 17:26:56.
907855597)
(at this point the data
packet is received from the
network)
19) ask for next index
20) informs the live viewer of the live beacon (@ 17:26:56.
913457688)
21) receives an index packet (@ 17:26:56.
914227502)
22) ask for next index
23) sends the packet to the viewer (@ 17:26:57.
742197990)
24) observes time going
backwards between the
previous live beacon
and the data packet.
The issue is caused by consumer_stream_sync_metadata_index which is
called after sending a data packet (therefore after having consumed a
data packet from the ring buffer). It invokes the send_live_beacon
callback before sending the index associated with the data packet that
was just sent.
However, this introduces a discrepancy between the live beacon
inactivity guarantees and the yet-to-be-sent packet index: the data
packet sent at [3] can be anywhere on the network, not even received by
the relay daemon, when the live beacon is sampling a now empty ring
buffer at [12], and thus sends a live inactivity beacon to the relay
daemon. Then, when the index is sent by consumer_stream_send_index
[16], its timestamp is in the past compared to the inactivity beacon
sent by send_live_beacon [11].
The purpose of the field "stream->indexes_in_flight" is to prevent
setting the inactivity timestamp in the relay stream when data is
missing for indexes that were received. This works because the indexes
are sent over the control socket, which is where the inactivity beacons
are also sent. It does not however prevent issues the other way around:
data sent prior to the inactivity beacon may or may not have reached
the relay daemon. It is therefore important to make sure that consuming
ring buffer data and sending that data's index vs sampling for an empty
ring buffer and sending an inactivity beacon are correctly ordered.
Solution
========
Send inactivity beacon after packet index.
Also document the purpose of sending an inactivity beacon in this
scenario.
Note
====
This issue is present since lttng-tools 2.7.0 (backported to 2.6.1),
where lttng_ustconsumer_read_subbuffer() invokes
consumer_flush_ust_index() prior to call consumer_stream_write_index().
It was introduced by commit
288bdb302a1 ("Fix: sessiond vs consumerd
push/get metadata deadlock").
Known drawbacks
===============
None.
Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ied43cc8229413b25e69b40ac218adad420f18797
projects / lttng-tools.git / commit
