From 6653fca60fdb6bf4ea4781bfee8304832d6a7e83 Mon Sep 17 00:00:00 2001 From: Mathieu Desnoyers Date: Mon, 22 Nov 2021 14:38:35 -0500 Subject: [PATCH] Fix: consumer-stream: live viewers observe timestamps going backwards MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit 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 Signed-off-by: Jérémie Galarneau Change-Id: Ied43cc8229413b25e69b40ac218adad420f18797 --- src/common/consumer/consumer-stream.cpp | 27 ++++++++++++++++++++----- 1 file changed, 22 insertions(+), 5 deletions(-) diff --git a/src/common/consumer/consumer-stream.cpp b/src/common/consumer/consumer-stream.cpp index e466c0155..f9807cb01 100644 --- a/src/common/consumer/consumer-stream.cpp +++ b/src/common/consumer/consumer-stream.cpp @@ -419,6 +419,7 @@ static int consumer_stream_sync_metadata_index( const struct stream_subbuffer *subbuffer, struct lttng_consumer_local_data *ctx) { + bool missed_metadata_flush; int ret; /* Block until all the metadata is sent. */ @@ -431,18 +432,34 @@ static int consumer_stream_sync_metadata_index( pthread_mutex_lock(&stream->metadata_timer_lock); stream->waiting_on_metadata = false; - if (stream->missed_metadata_flush) { + missed_metadata_flush = stream->missed_metadata_flush; + if (missed_metadata_flush) { stream->missed_metadata_flush = false; - pthread_mutex_unlock(&stream->metadata_timer_lock); - (void) stream->read_subbuffer_ops.send_live_beacon(stream); - } else { - pthread_mutex_unlock(&stream->metadata_timer_lock); } + pthread_mutex_unlock(&stream->metadata_timer_lock); if (ret < 0) { goto end; } ret = consumer_stream_send_index(stream, subbuffer, ctx); + /* + * Send the live inactivity beacon to handle the situation where + * the live timer is prevented from sampling this stream + * because the stream lock was being held while this stream is + * waiting on metadata. This ensures live viewer progress in the + * unlikely scenario where a live timer would be prevented from + * locking a stream lock repeatedly due to a steady flow of + * incoming metadata, for a stream which is mostly inactive. + * + * It is important to send the inactivity beacon packet to + * relayd _after_ sending the index associated with the data + * that was just sent, otherwise this can cause live viewers to + * observe timestamps going backwards between an inactivity + * beacon and a following trace packet. + */ + if (missed_metadata_flush) { + (void) stream->read_subbuffer_ops.send_live_beacon(stream); + } end: return ret; } -- 2.34.1