Fix: consumer-stream: live viewers observe timestamps going backwards
authorMathieu Desnoyers <mathieu.desnoyers@efficios.com>
Mon, 22 Nov 2021 19:38:35 +0000 (14:38 -0500)
committerJérémie Galarneau <jeremie.galarneau@efficios.com>
Fri, 21 Jan 2022 22:57:40 +0000 (17:57 -0500)
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

src/common/consumer/consumer-stream.c

index 09543abb78b49aa0469ae641cdeb386f15c758b0..ef29866a00c8d79be136f3788cce0d1b323e0053 100644 (file)
@@ -420,6 +420,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. */
@@ -432,18 +433,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;
 }
This page took 0.032123 seconds and 4 git commands to generate.