Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 1 | #ifndef AOS_EVENTS_LOGGING_LOGFILE_UTILS_H_ |
| 2 | #define AOS_EVENTS_LOGGING_LOGFILE_UTILS_H_ |
| 3 | |
| 4 | #include <sys/uio.h> |
| 5 | |
Austin Schuh | 97789fc | 2020-08-01 14:42:45 -0700 | [diff] [blame] | 6 | #include <chrono> |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 7 | #include <deque> |
Austin Schuh | 97789fc | 2020-08-01 14:42:45 -0700 | [diff] [blame] | 8 | #include <limits> |
| 9 | #include <memory> |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 10 | #include <optional> |
Austin Schuh | fa89589 | 2020-01-07 20:07:41 -0800 | [diff] [blame] | 11 | #include <string> |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 12 | #include <string_view> |
Brian Silverman | 98360e2 | 2020-04-28 16:51:20 -0700 | [diff] [blame] | 13 | #include <tuple> |
Austin Schuh | 97789fc | 2020-08-01 14:42:45 -0700 | [diff] [blame] | 14 | #include <utility> |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 15 | #include <vector> |
| 16 | |
Austin Schuh | 4b5c22a | 2020-11-30 22:58:43 -0800 | [diff] [blame] | 17 | #include "absl/container/btree_set.h" |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 18 | #include "absl/types/span.h" |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 19 | #include "aos/containers/resizeable_buffer.h" |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 20 | #include "aos/events/event_loop.h" |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 21 | #include "aos/events/logging/buffer_encoder.h" |
Austin Schuh | c41603c | 2020-10-11 16:17:37 -0700 | [diff] [blame] | 22 | #include "aos/events/logging/logfile_sorting.h" |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 23 | #include "aos/events/logging/logger_generated.h" |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 24 | #include "aos/flatbuffers.h" |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 25 | #include "flatbuffers/flatbuffers.h" |
| 26 | |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 27 | namespace aos::logger { |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 28 | |
| 29 | enum class LogType : uint8_t { |
| 30 | // The message originated on this node and should be logged here. |
| 31 | kLogMessage, |
| 32 | // The message originated on another node, but only the delivery times are |
| 33 | // logged here. |
| 34 | kLogDeliveryTimeOnly, |
| 35 | // The message originated on another node. Log it and the delivery times |
| 36 | // together. The message_gateway is responsible for logging any messages |
| 37 | // which didn't get delivered. |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 38 | kLogMessageAndDeliveryTime, |
| 39 | // The message originated on the other node and should be logged on this node. |
| 40 | kLogRemoteMessage |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 41 | }; |
| 42 | |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 43 | // This class manages efficiently writing a sequence of detached buffers to a |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 44 | // file. It encodes them, queues them up, and batches the write operation. |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 45 | class DetachedBufferWriter { |
| 46 | public: |
Brian Silverman | a9f2ec9 | 2020-10-06 18:00:53 -0700 | [diff] [blame] | 47 | // Marker struct for one of our constructor overloads. |
| 48 | struct already_out_of_space_t {}; |
| 49 | |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 50 | DetachedBufferWriter(std::string_view filename, |
| 51 | std::unique_ptr<DetachedBufferEncoder> encoder); |
Brian Silverman | a9f2ec9 | 2020-10-06 18:00:53 -0700 | [diff] [blame] | 52 | // Creates a dummy instance which won't even open a file. It will act as if |
| 53 | // opening the file ran out of space immediately. |
| 54 | DetachedBufferWriter(already_out_of_space_t) : ran_out_of_space_(true) {} |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 55 | DetachedBufferWriter(DetachedBufferWriter &&other); |
| 56 | DetachedBufferWriter(const DetachedBufferWriter &) = delete; |
| 57 | |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 58 | ~DetachedBufferWriter(); |
| 59 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 60 | DetachedBufferWriter &operator=(DetachedBufferWriter &&other); |
Brian Silverman | 98360e2 | 2020-04-28 16:51:20 -0700 | [diff] [blame] | 61 | DetachedBufferWriter &operator=(const DetachedBufferWriter &) = delete; |
| 62 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 63 | std::string_view filename() const { return filename_; } |
| 64 | |
Brian Silverman | a9f2ec9 | 2020-10-06 18:00:53 -0700 | [diff] [blame] | 65 | // This will be true until Close() is called, unless the file couldn't be |
| 66 | // created due to running out of space. |
| 67 | bool is_open() const { return fd_ != -1; } |
| 68 | |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 69 | // Queues up a finished FlatBufferBuilder to be encoded and written. |
| 70 | // |
| 71 | // Triggers a flush if there's enough data queued up. |
| 72 | // |
| 73 | // Steals the detached buffer from it. |
| 74 | void QueueSizedFlatbuffer(flatbuffers::FlatBufferBuilder *fbb) { |
| 75 | QueueSizedFlatbuffer(fbb->Release()); |
| 76 | } |
| 77 | // May steal the backing storage of buffer, or may leave it alone. |
| 78 | void QueueSizedFlatbuffer(flatbuffers::DetachedBuffer &&buffer) { |
Brian Silverman | a9f2ec9 | 2020-10-06 18:00:53 -0700 | [diff] [blame] | 79 | if (ran_out_of_space_) { |
| 80 | return; |
| 81 | } |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 82 | encoder_->Encode(std::move(buffer)); |
| 83 | FlushAtThreshold(); |
| 84 | } |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 85 | |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 86 | // Queues up data in span. May copy or may write it to disk immediately. |
| 87 | void QueueSpan(absl::Span<const uint8_t> span); |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 88 | |
Brian Silverman | 0465fcf | 2020-09-24 00:29:18 -0700 | [diff] [blame] | 89 | // Indicates we got ENOSPC when trying to write. After this returns true, no |
| 90 | // further data is written. |
| 91 | bool ran_out_of_space() const { return ran_out_of_space_; } |
| 92 | |
| 93 | // To avoid silently failing to write logfiles, you must call this before |
| 94 | // destruction if ran_out_of_space() is true and the situation has been |
| 95 | // handled. |
| 96 | void acknowledge_out_of_space() { |
| 97 | CHECK(ran_out_of_space_); |
| 98 | acknowledge_ran_out_of_space_ = true; |
| 99 | } |
| 100 | |
| 101 | // Fully flushes and closes the underlying file now. No additional data may be |
| 102 | // enqueued after calling this. |
| 103 | // |
| 104 | // This will be performed in the destructor automatically. |
| 105 | // |
| 106 | // Note that this may set ran_out_of_space(). |
| 107 | void Close(); |
| 108 | |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 109 | // Returns the total number of bytes written and currently queued. |
| 110 | size_t total_bytes() const { return encoder_->total_bytes(); } |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 111 | |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 112 | // The maximum time for a single write call, or 0 if none have been performed. |
| 113 | std::chrono::nanoseconds max_write_time() const { return max_write_time_; } |
| 114 | // The number of bytes in the longest write call, or -1 if none have been |
| 115 | // performed. |
| 116 | int max_write_time_bytes() const { return max_write_time_bytes_; } |
| 117 | // The number of buffers in the longest write call, or -1 if none have been |
| 118 | // performed. |
| 119 | int max_write_time_messages() const { return max_write_time_messages_; } |
| 120 | // The total time spent in write calls. |
| 121 | std::chrono::nanoseconds total_write_time() const { |
| 122 | return total_write_time_; |
| 123 | } |
| 124 | // The total number of writes which have been performed. |
| 125 | int total_write_count() const { return total_write_count_; } |
| 126 | // The total number of messages which have been written. |
| 127 | int total_write_messages() const { return total_write_messages_; } |
| 128 | // The total number of bytes which have been written. |
| 129 | int total_write_bytes() const { return total_write_bytes_; } |
| 130 | void ResetStatistics() { |
| 131 | max_write_time_ = std::chrono::nanoseconds::zero(); |
| 132 | max_write_time_bytes_ = -1; |
| 133 | max_write_time_messages_ = -1; |
| 134 | total_write_time_ = std::chrono::nanoseconds::zero(); |
| 135 | total_write_count_ = 0; |
| 136 | total_write_messages_ = 0; |
| 137 | total_write_bytes_ = 0; |
| 138 | } |
Brian Silverman | 98360e2 | 2020-04-28 16:51:20 -0700 | [diff] [blame] | 139 | |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 140 | private: |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 141 | // Performs a single writev call with as much of the data we have queued up as |
| 142 | // possible. |
| 143 | // |
| 144 | // This will normally take all of the data we have queued up, unless an |
| 145 | // encoder has spit out a big enough chunk all at once that we can't manage |
| 146 | // all of it. |
| 147 | void Flush(); |
| 148 | |
Brian Silverman | 0465fcf | 2020-09-24 00:29:18 -0700 | [diff] [blame] | 149 | // write_return is what write(2) or writev(2) returned. write_size is the |
| 150 | // number of bytes we expected it to write. |
| 151 | void HandleWriteReturn(ssize_t write_return, size_t write_size); |
| 152 | |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 153 | void UpdateStatsForWrite(aos::monotonic_clock::duration duration, |
| 154 | ssize_t written, int iovec_size); |
| 155 | |
| 156 | // Flushes data if we've reached the threshold to do that as part of normal |
| 157 | // operation. |
| 158 | void FlushAtThreshold(); |
| 159 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 160 | std::string filename_; |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 161 | std::unique_ptr<DetachedBufferEncoder> encoder_; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 162 | |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 163 | int fd_ = -1; |
Brian Silverman | 0465fcf | 2020-09-24 00:29:18 -0700 | [diff] [blame] | 164 | bool ran_out_of_space_ = false; |
| 165 | bool acknowledge_ran_out_of_space_ = false; |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 166 | |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 167 | // List of iovecs to use with writev. This is a member variable to avoid |
| 168 | // churn. |
| 169 | std::vector<struct iovec> iovec_; |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 170 | |
| 171 | std::chrono::nanoseconds max_write_time_ = std::chrono::nanoseconds::zero(); |
| 172 | int max_write_time_bytes_ = -1; |
| 173 | int max_write_time_messages_ = -1; |
| 174 | std::chrono::nanoseconds total_write_time_ = std::chrono::nanoseconds::zero(); |
| 175 | int total_write_count_ = 0; |
| 176 | int total_write_messages_ = 0; |
| 177 | int total_write_bytes_ = 0; |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 178 | }; |
| 179 | |
| 180 | // Packes a message pointed to by the context into a MessageHeader. |
| 181 | flatbuffers::Offset<MessageHeader> PackMessage( |
| 182 | flatbuffers::FlatBufferBuilder *fbb, const Context &context, |
| 183 | int channel_index, LogType log_type); |
| 184 | |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 185 | std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> ReadHeader( |
Austin Schuh | 3bd4c40 | 2020-11-06 18:19:06 -0800 | [diff] [blame] | 186 | std::string_view filename); |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 187 | std::optional<SizePrefixedFlatbufferVector<MessageHeader>> ReadNthMessage( |
Austin Schuh | 3bd4c40 | 2020-11-06 18:19:06 -0800 | [diff] [blame] | 188 | std::string_view filename, size_t n); |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 189 | |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 190 | // Class to read chunks out of a log file. |
| 191 | class SpanReader { |
| 192 | public: |
| 193 | SpanReader(std::string_view filename); |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 194 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 195 | std::string_view filename() const { return filename_; } |
| 196 | |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 197 | // Returns a span with the data for a message from the log file, excluding |
| 198 | // the size. |
| 199 | absl::Span<const uint8_t> ReadMessage(); |
| 200 | |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 201 | private: |
| 202 | // TODO(austin): Optimization: |
| 203 | // Allocate the 256k blocks like we do today. But, refcount them with |
| 204 | // shared_ptr pointed to by the messageheader that is returned. This avoids |
| 205 | // the copy. Need to do more benchmarking. |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 206 | // And (Brian): Consider just mmapping the file and handing out refcounted |
| 207 | // pointers into that too. |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 208 | |
| 209 | // Reads a chunk of data into data_. Returns false if no data was read. |
| 210 | bool ReadBlock(); |
| 211 | |
Austin Schuh | c41603c | 2020-10-11 16:17:37 -0700 | [diff] [blame] | 212 | std::string filename_; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 213 | |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 214 | // File reader and data decoder. |
| 215 | std::unique_ptr<DataDecoder> decoder_; |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 216 | |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 217 | // Vector to read into. |
| 218 | ResizeableBuffer data_; |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 219 | |
| 220 | // Amount of data consumed already in data_. |
| 221 | size_t consumed_data_ = 0; |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 222 | }; |
| 223 | |
| 224 | // Class which handles reading the header and messages from the log file. This |
| 225 | // handles any per-file state left before merging below. |
| 226 | class MessageReader { |
| 227 | public: |
| 228 | MessageReader(std::string_view filename); |
| 229 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 230 | std::string_view filename() const { return span_reader_.filename(); } |
| 231 | |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 232 | // Returns the header from the log file. |
| 233 | const LogFileHeader *log_file_header() const { |
Austin Schuh | 97789fc | 2020-08-01 14:42:45 -0700 | [diff] [blame] | 234 | return &raw_log_file_header_.message(); |
| 235 | } |
| 236 | |
| 237 | // Returns the raw data of the header from the log file. |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 238 | const SizePrefixedFlatbufferVector<LogFileHeader> &raw_log_file_header() |
| 239 | const { |
Austin Schuh | 97789fc | 2020-08-01 14:42:45 -0700 | [diff] [blame] | 240 | return raw_log_file_header_; |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 241 | } |
| 242 | |
| 243 | // Returns the minimum maount of data needed to queue up for sorting before |
| 244 | // ware guarenteed to not see data out of order. |
| 245 | std::chrono::nanoseconds max_out_of_order_duration() const { |
| 246 | return max_out_of_order_duration_; |
| 247 | } |
| 248 | |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 249 | // Returns the newest timestamp read out of the log file. |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 250 | monotonic_clock::time_point newest_timestamp() const { |
| 251 | return newest_timestamp_; |
| 252 | } |
| 253 | |
| 254 | // Returns the next message if there is one. |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 255 | std::optional<SizePrefixedFlatbufferVector<MessageHeader>> ReadMessage(); |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 256 | |
| 257 | // The time at which we need to read another chunk from the logfile. |
| 258 | monotonic_clock::time_point queue_data_time() const { |
| 259 | return newest_timestamp() - max_out_of_order_duration(); |
| 260 | } |
| 261 | |
| 262 | private: |
| 263 | // Log chunk reader. |
| 264 | SpanReader span_reader_; |
| 265 | |
Austin Schuh | 97789fc | 2020-08-01 14:42:45 -0700 | [diff] [blame] | 266 | // Vector holding the raw data for the log file header. |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 267 | SizePrefixedFlatbufferVector<LogFileHeader> raw_log_file_header_; |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 268 | |
| 269 | // Minimum amount of data to queue up for sorting before we are guarenteed |
| 270 | // to not see data out of order. |
| 271 | std::chrono::nanoseconds max_out_of_order_duration_; |
| 272 | |
| 273 | // Timestamp of the newest message in a channel queue. |
| 274 | monotonic_clock::time_point newest_timestamp_ = monotonic_clock::min_time; |
| 275 | }; |
| 276 | |
Austin Schuh | c41603c | 2020-10-11 16:17:37 -0700 | [diff] [blame] | 277 | // A class to seamlessly read messages from a list of part files. |
| 278 | class PartsMessageReader { |
| 279 | public: |
| 280 | PartsMessageReader(LogParts log_parts); |
| 281 | |
| 282 | std::string_view filename() const { return message_reader_.filename(); } |
| 283 | |
Austin Schuh | d2f9610 | 2020-12-01 20:27:29 -0800 | [diff] [blame] | 284 | // Returns the LogParts that holds the filenames we are reading. |
| 285 | const LogParts &parts() const { return parts_; } |
| 286 | |
Austin Schuh | 4b5c22a | 2020-11-30 22:58:43 -0800 | [diff] [blame] | 287 | const LogFileHeader *log_file_header() const { |
| 288 | return message_reader_.log_file_header(); |
| 289 | } |
| 290 | |
Austin Schuh | c41603c | 2020-10-11 16:17:37 -0700 | [diff] [blame] | 291 | // Returns the minimum amount of data needed to queue up for sorting before |
| 292 | // we are guarenteed to not see data out of order. |
| 293 | std::chrono::nanoseconds max_out_of_order_duration() const { |
| 294 | return message_reader_.max_out_of_order_duration(); |
| 295 | } |
| 296 | |
| 297 | // Returns the newest timestamp read out of the log file. |
| 298 | monotonic_clock::time_point newest_timestamp() const { |
| 299 | return newest_timestamp_; |
| 300 | } |
| 301 | |
| 302 | // Returns the next message if there is one, or nullopt if we have reached the |
| 303 | // end of all the files. |
| 304 | // Note: reading the next message may change the max_out_of_order_duration(). |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 305 | std::optional<SizePrefixedFlatbufferVector<MessageHeader>> ReadMessage(); |
Austin Schuh | c41603c | 2020-10-11 16:17:37 -0700 | [diff] [blame] | 306 | |
| 307 | private: |
| 308 | // Opens the next log and updates message_reader_. Sets done_ if there is |
| 309 | // nothing more to do. |
| 310 | void NextLog(); |
| 311 | |
| 312 | const LogParts parts_; |
| 313 | size_t next_part_index_ = 1u; |
| 314 | bool done_ = false; |
| 315 | MessageReader message_reader_; |
| 316 | |
| 317 | monotonic_clock::time_point newest_timestamp_ = monotonic_clock::min_time; |
| 318 | }; |
| 319 | |
Austin Schuh | 1be0ce4 | 2020-11-29 22:43:26 -0800 | [diff] [blame] | 320 | // Struct to hold a message as it gets sorted on a single node. |
| 321 | struct Message { |
| 322 | // The channel. |
| 323 | uint32_t channel_index = 0xffffffff; |
| 324 | // The local queue index. |
| 325 | uint32_t queue_index = 0xffffffff; |
| 326 | // The local timestamp on the monotonic clock. |
| 327 | monotonic_clock::time_point timestamp = monotonic_clock::min_time; |
| 328 | // The data (either a timestamp header, or a data header). |
| 329 | SizePrefixedFlatbufferVector<MessageHeader> data; |
| 330 | |
| 331 | bool operator<(const Message &m2) const; |
| 332 | bool operator>=(const Message &m2) const; |
Austin Schuh | 8f52ed5 | 2020-11-30 23:12:39 -0800 | [diff] [blame] | 333 | bool operator==(const Message &m2) const; |
Austin Schuh | 1be0ce4 | 2020-11-29 22:43:26 -0800 | [diff] [blame] | 334 | }; |
| 335 | |
| 336 | std::ostream &operator<<(std::ostream &os, const Message &m); |
| 337 | |
Austin Schuh | d2f9610 | 2020-12-01 20:27:29 -0800 | [diff] [blame] | 338 | // Structure to hold a full message and all the timestamps, which may or may not |
| 339 | // have been sent from a remote node. The remote_queue_index will be invalid if |
| 340 | // this message is from the point of view of the node which sent it. |
| 341 | struct TimestampedMessage { |
| 342 | uint32_t channel_index = 0xffffffff; |
| 343 | |
| 344 | uint32_t queue_index = 0xffffffff; |
| 345 | monotonic_clock::time_point monotonic_event_time = monotonic_clock::min_time; |
| 346 | realtime_clock::time_point realtime_event_time = realtime_clock::min_time; |
| 347 | |
| 348 | uint32_t remote_queue_index = 0xffffffff; |
| 349 | monotonic_clock::time_point monotonic_remote_time = monotonic_clock::min_time; |
| 350 | realtime_clock::time_point realtime_remote_time = realtime_clock::min_time; |
| 351 | |
| 352 | SizePrefixedFlatbufferVector<MessageHeader> data; |
| 353 | }; |
| 354 | |
| 355 | std::ostream &operator<<(std::ostream &os, const TimestampedMessage &m); |
| 356 | |
Austin Schuh | 4b5c22a | 2020-11-30 22:58:43 -0800 | [diff] [blame] | 357 | // Class to sort the resulting messages from a PartsMessageReader. |
| 358 | class LogPartsSorter { |
| 359 | public: |
| 360 | LogPartsSorter(LogParts log_parts); |
| 361 | |
| 362 | // Returns the current log file header. |
| 363 | // TODO(austin): Is this the header we want to report? Do we want a better |
| 364 | // start time? |
| 365 | // TODO(austin): Report a start time from the LogParts. Figure out how that |
| 366 | // all works. |
| 367 | const LogFileHeader *log_file_header() const { |
| 368 | return parts_message_reader_.log_file_header(); |
| 369 | } |
| 370 | |
Austin Schuh | d2f9610 | 2020-12-01 20:27:29 -0800 | [diff] [blame] | 371 | monotonic_clock::time_point monotonic_start_time() const { |
| 372 | return parts_message_reader_.parts().monotonic_start_time; |
| 373 | } |
| 374 | realtime_clock::time_point realtime_start_time() const { |
| 375 | return parts_message_reader_.parts().realtime_start_time; |
| 376 | } |
| 377 | |
Austin Schuh | 4b5c22a | 2020-11-30 22:58:43 -0800 | [diff] [blame] | 378 | // The time this data is sorted until. |
| 379 | monotonic_clock::time_point sorted_until() const { return sorted_until_; } |
| 380 | |
| 381 | // Returns the next sorted message from the log file. It is safe to call |
| 382 | // std::move() on the result to move the data flatbuffer from it. |
| 383 | Message *Front(); |
| 384 | // Pops the front message. This should only be called after a call to |
| 385 | // Front(). |
| 386 | void PopFront(); |
| 387 | |
| 388 | // Returns a debug string representing the contents of this sorter. |
| 389 | std::string DebugString() const; |
| 390 | |
| 391 | private: |
| 392 | // Log parts reader we are wrapping. |
| 393 | PartsMessageReader parts_message_reader_; |
| 394 | // Cache of the time we are sorted until. |
| 395 | aos::monotonic_clock::time_point sorted_until_ = monotonic_clock::min_time; |
| 396 | |
Austin Schuh | b000de6 | 2020-12-03 22:00:40 -0800 | [diff] [blame^] | 397 | // Timestamp of the last message returned. Used to make sure nothing goes |
| 398 | // backwards. |
| 399 | monotonic_clock::time_point last_message_time_ = monotonic_clock::min_time; |
| 400 | |
Austin Schuh | 4b5c22a | 2020-11-30 22:58:43 -0800 | [diff] [blame] | 401 | // Set used for efficient sorting of messages. We can benchmark and evaluate |
| 402 | // other data structures if this proves to be the bottleneck. |
| 403 | absl::btree_set<Message> messages_; |
| 404 | }; |
| 405 | |
Austin Schuh | 8f52ed5 | 2020-11-30 23:12:39 -0800 | [diff] [blame] | 406 | // Class to run merge sort on the messages from multiple LogPartsSorter |
| 407 | // instances. |
| 408 | class NodeMerger { |
| 409 | public: |
Austin Schuh | d2f9610 | 2020-12-01 20:27:29 -0800 | [diff] [blame] | 410 | NodeMerger(std::vector<LogParts> parts); |
| 411 | |
| 412 | // Node index in the configuration of this node. |
| 413 | int node() const { return node_; } |
Austin Schuh | 8f52ed5 | 2020-11-30 23:12:39 -0800 | [diff] [blame] | 414 | |
| 415 | // The log file header for one of the log files. |
| 416 | const LogFileHeader *log_file_header() const { |
| 417 | CHECK(!parts_sorters_.empty()); |
Austin Schuh | d2f9610 | 2020-12-01 20:27:29 -0800 | [diff] [blame] | 418 | return parts_sorters_[0].log_file_header(); |
| 419 | } |
| 420 | |
| 421 | monotonic_clock::time_point monotonic_start_time() const { |
| 422 | return monotonic_start_time_; |
| 423 | } |
| 424 | realtime_clock::time_point realtime_start_time() const { |
| 425 | return realtime_start_time_; |
Austin Schuh | 8f52ed5 | 2020-11-30 23:12:39 -0800 | [diff] [blame] | 426 | } |
| 427 | |
| 428 | // The time this data is sorted until. |
| 429 | monotonic_clock::time_point sorted_until() const { return sorted_until_; } |
| 430 | |
| 431 | // Returns the next sorted message from the set of log files. It is safe to |
| 432 | // call std::move() on the result to move the data flatbuffer from it. |
| 433 | Message *Front(); |
| 434 | // Pops the front message. This should only be called after a call to |
| 435 | // Front(). |
| 436 | void PopFront(); |
| 437 | |
| 438 | private: |
| 439 | // Unsorted list of all parts sorters. |
Austin Schuh | d2f9610 | 2020-12-01 20:27:29 -0800 | [diff] [blame] | 440 | std::vector<LogPartsSorter> parts_sorters_; |
Austin Schuh | 8f52ed5 | 2020-11-30 23:12:39 -0800 | [diff] [blame] | 441 | // Pointer to the parts sorter holding the current Front message if one |
| 442 | // exists, or nullptr if a new one needs to be found. |
| 443 | LogPartsSorter *current_ = nullptr; |
| 444 | // Cached sorted_until value. |
| 445 | aos::monotonic_clock::time_point sorted_until_ = monotonic_clock::min_time; |
Austin Schuh | d2f9610 | 2020-12-01 20:27:29 -0800 | [diff] [blame] | 446 | |
| 447 | // Cached node. |
| 448 | int node_; |
| 449 | |
Austin Schuh | b000de6 | 2020-12-03 22:00:40 -0800 | [diff] [blame^] | 450 | // Timestamp of the last message returned. Used to make sure nothing goes |
| 451 | // backwards. |
| 452 | monotonic_clock::time_point last_message_time_ = monotonic_clock::min_time; |
| 453 | |
Austin Schuh | d2f9610 | 2020-12-01 20:27:29 -0800 | [diff] [blame] | 454 | realtime_clock::time_point realtime_start_time_ = realtime_clock::max_time; |
| 455 | monotonic_clock::time_point monotonic_start_time_ = monotonic_clock::max_time; |
| 456 | }; |
| 457 | |
| 458 | // Class to match timestamps with the corresponding data from other nodes. |
| 459 | class TimestampMapper { |
| 460 | public: |
| 461 | TimestampMapper(std::vector<LogParts> file); |
| 462 | |
| 463 | // Copying and moving will mess up the internal raw pointers. Just don't do |
| 464 | // it. |
| 465 | TimestampMapper(TimestampMapper const &) = delete; |
| 466 | TimestampMapper(TimestampMapper &&) = delete; |
| 467 | void operator=(TimestampMapper const &) = delete; |
| 468 | void operator=(TimestampMapper &&) = delete; |
| 469 | |
| 470 | // TODO(austin): It would be super helpful to provide a way to queue up to |
| 471 | // time X without matching timestamps, and to then be able to pull the |
| 472 | // timestamps out of this queue. This lets us bootstrap time estimation |
| 473 | // without exploding memory usage worst case. |
| 474 | |
| 475 | // Returns a log file header for this node. |
| 476 | const LogFileHeader *log_file_header() const { |
| 477 | return node_merger_.log_file_header(); |
| 478 | } |
| 479 | |
| 480 | // Returns which node this is sorting for. |
| 481 | size_t node() const { return node_; } |
| 482 | |
| 483 | // The start time of this log. |
| 484 | monotonic_clock::time_point monotonic_start_time() const { |
| 485 | return node_merger_.monotonic_start_time(); |
| 486 | } |
| 487 | realtime_clock::time_point realtime_start_time() const { |
| 488 | return node_merger_.realtime_start_time(); |
| 489 | } |
| 490 | |
| 491 | // Uses timestamp_mapper as the peer for its node. Only one mapper may be set |
| 492 | // for each node. Peers are used to look up the data for timestamps on this |
| 493 | // node. |
| 494 | void AddPeer(TimestampMapper *timestamp_mapper); |
| 495 | |
| 496 | // Time that we are sorted until internally. |
| 497 | monotonic_clock::time_point sorted_until() const { |
| 498 | return node_merger_.sorted_until(); |
| 499 | } |
| 500 | |
| 501 | // Returns the next message for this node. |
| 502 | TimestampedMessage *Front(); |
| 503 | // Pops the next message. Front must be called first. |
| 504 | void PopFront(); |
| 505 | |
| 506 | // Returns debug information about this node. |
| 507 | std::string DebugString() const; |
| 508 | |
| 509 | private: |
| 510 | // The state for a remote node. This holds the data that needs to be matched |
| 511 | // with the remote node's timestamps. |
| 512 | struct NodeData { |
| 513 | // True if we should save data here. This should be true if any of the |
| 514 | // bools in delivered below are true. |
| 515 | bool any_delivered = false; |
| 516 | |
| 517 | // Peer pointer. This node is only to be considered if a peer is set. |
| 518 | TimestampMapper *peer = nullptr; |
| 519 | |
| 520 | struct ChannelData { |
| 521 | // Deque per channel. This contains the data from the outside |
| 522 | // TimestampMapper node which is relevant for the node this NodeData |
| 523 | // points to. |
| 524 | std::deque<Message> messages; |
| 525 | // Bool tracking per channel if a message is delivered to the node this |
| 526 | // NodeData represents. |
| 527 | bool delivered = false; |
| 528 | }; |
| 529 | |
| 530 | // Vector with per channel data. |
| 531 | std::vector<ChannelData> channels; |
| 532 | }; |
| 533 | |
| 534 | // Returns (and forgets about) the data for the provided timestamp message |
| 535 | // showing when it was delivered to this node. |
| 536 | Message MatchingMessageFor(const Message &message); |
| 537 | |
| 538 | // Queues up a single message into our message queue, and any nodes that this |
| 539 | // message is delivered to. Returns true if one was available, false |
| 540 | // otherwise. |
| 541 | bool Queue(); |
| 542 | |
| 543 | // Queues up data until we have at least one message >= to time t. |
| 544 | // Useful for triggering a remote node to read enough data to have the |
| 545 | // timestamp you care about available. |
| 546 | void QueueUntil(monotonic_clock::time_point t); |
| 547 | |
| 548 | // Fills message_ with the contents of m. |
| 549 | void FillMessage(Message *m); |
| 550 | |
| 551 | // The node merger to source messages from. |
| 552 | NodeMerger node_merger_; |
| 553 | // Our node. |
| 554 | const size_t node_; |
| 555 | // The buffer of messages for this node. These are not matched with any |
| 556 | // remote data. |
| 557 | std::deque<Message> messages_; |
| 558 | // The node index for the source node for each channel. |
| 559 | std::vector<size_t> source_node_; |
| 560 | |
| 561 | // Vector per node. Not all nodes will have anything. |
| 562 | std::vector<NodeData> nodes_data_; |
| 563 | |
| 564 | // Latest message to return. |
| 565 | TimestampedMessage message_; |
| 566 | |
| 567 | // Tracks if the first message points to message_, nullptr (all done), or is |
| 568 | // invalid. |
| 569 | enum class FirstMessage { |
| 570 | kNeedsUpdate, |
| 571 | kInMessage, |
| 572 | kNullptr, |
| 573 | }; |
| 574 | FirstMessage first_message_ = FirstMessage::kNeedsUpdate; |
| 575 | |
| 576 | // Timestamp of the last message returned. Used to make sure nothing goes |
| 577 | // backwards. |
| 578 | monotonic_clock::time_point last_message_time_ = monotonic_clock::min_time; |
| 579 | // Time this node is queued up until. Used for caching. |
| 580 | monotonic_clock::time_point queued_until_ = monotonic_clock::min_time; |
Austin Schuh | 8f52ed5 | 2020-11-30 23:12:39 -0800 | [diff] [blame] | 581 | }; |
| 582 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 583 | class TimestampMerger; |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 584 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 585 | // A design requirement is that the relevant data for a channel is not more than |
| 586 | // max_out_of_order_duration out of order. We approach sorting in layers. |
| 587 | // |
| 588 | // 1) Split each (maybe chunked) log file into one queue per channel. Read this |
| 589 | // log file looking for data pertaining to a specific node. |
| 590 | // (SplitMessageReader) |
| 591 | // 2) Merge all the data per channel from the different log files into a sorted |
| 592 | // list of timestamps and messages. (TimestampMerger) |
| 593 | // 3) Combine the timestamps and messages. (TimestampMerger) |
| 594 | // 4) Merge all the channels to produce the next message on a node. |
| 595 | // (ChannelMerger) |
| 596 | // 5) Duplicate this entire stack per node. |
| 597 | |
| 598 | // This class splits messages and timestamps up into a queue per channel, and |
| 599 | // handles reading data from multiple chunks. |
| 600 | class SplitMessageReader { |
| 601 | public: |
| 602 | SplitMessageReader(const std::vector<std::string> &filenames); |
| 603 | |
| 604 | // Sets the TimestampMerger that gets notified for each channel. The node |
| 605 | // that the TimestampMerger is merging as needs to be passed in. |
| 606 | void SetTimestampMerger(TimestampMerger *timestamp_merger, int channel, |
| 607 | const Node *target_node); |
| 608 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 609 | // Returns the (timestamp, queue_index, message_header) for the oldest message |
| 610 | // in a channel, or max_time if there is nothing in the channel. |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 611 | std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *> |
| 612 | oldest_message(int channel) { |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 613 | return channels_[channel].data.front_timestamp(); |
| 614 | } |
| 615 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 616 | // Returns the (timestamp, queue_index, message_header) for the oldest |
| 617 | // delivery time in a channel, or max_time if there is nothing in the channel. |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 618 | std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *> |
| 619 | oldest_message(int channel, int destination_node) { |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 620 | return channels_[channel].timestamps[destination_node].front_timestamp(); |
| 621 | } |
| 622 | |
| 623 | // Returns the timestamp, queue_index, and message for the oldest data on a |
| 624 | // channel. Requeues data as needed. |
| 625 | std::tuple<monotonic_clock::time_point, uint32_t, |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 626 | SizePrefixedFlatbufferVector<MessageHeader>> |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 627 | PopOldest(int channel_index); |
| 628 | |
| 629 | // Returns the timestamp, queue_index, and message for the oldest timestamp on |
| 630 | // a channel delivered to a node. Requeues data as needed. |
| 631 | std::tuple<monotonic_clock::time_point, uint32_t, |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 632 | SizePrefixedFlatbufferVector<MessageHeader>> |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 633 | PopOldestTimestamp(int channel, int node_index); |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 634 | |
| 635 | // Returns the header for the log files. |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 636 | const LogFileHeader *log_file_header() const { |
Austin Schuh | fa89589 | 2020-01-07 20:07:41 -0800 | [diff] [blame] | 637 | return &log_file_header_.message(); |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 638 | } |
| 639 | |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 640 | const SizePrefixedFlatbufferVector<LogFileHeader> &raw_log_file_header() |
| 641 | const { |
Austin Schuh | 97789fc | 2020-08-01 14:42:45 -0700 | [diff] [blame] | 642 | return log_file_header_; |
| 643 | } |
| 644 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 645 | // Returns the starting time for this set of log files. |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 646 | monotonic_clock::time_point monotonic_start_time() { |
| 647 | return monotonic_clock::time_point( |
| 648 | std::chrono::nanoseconds(log_file_header()->monotonic_start_time())); |
| 649 | } |
| 650 | realtime_clock::time_point realtime_start_time() { |
| 651 | return realtime_clock::time_point( |
| 652 | std::chrono::nanoseconds(log_file_header()->realtime_start_time())); |
| 653 | } |
| 654 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 655 | // Returns the configuration from the log file header. |
| 656 | const Configuration *configuration() const { |
| 657 | return log_file_header()->configuration(); |
| 658 | } |
| 659 | |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 660 | // Returns the node who's point of view this log file is from. Make sure this |
| 661 | // is a pointer in the configuration() nodes list so it can be consumed |
| 662 | // elsewhere. |
| 663 | const Node *node() const { |
| 664 | if (configuration()->has_nodes()) { |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 665 | return configuration::GetNodeOrDie(configuration(), |
| 666 | log_file_header()->node()); |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 667 | } else { |
| 668 | CHECK(!log_file_header()->has_node()); |
| 669 | return nullptr; |
| 670 | } |
| 671 | } |
| 672 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 673 | // Returns the timestamp of the newest message read from the log file, and the |
| 674 | // timestamp that we need to re-queue data. |
| 675 | monotonic_clock::time_point newest_timestamp() const { |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 676 | return newest_timestamp_; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 677 | } |
| 678 | |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 679 | // Returns the next time to trigger a requeue. |
| 680 | monotonic_clock::time_point time_to_queue() const { return time_to_queue_; } |
| 681 | |
| 682 | // Returns the minimum amount of data needed to queue up for sorting before |
Austin Schuh | c41603c | 2020-10-11 16:17:37 -0700 | [diff] [blame] | 683 | // we are guarenteed to not see data out of order. |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 684 | std::chrono::nanoseconds max_out_of_order_duration() const { |
| 685 | return message_reader_->max_out_of_order_duration(); |
| 686 | } |
| 687 | |
| 688 | std::string_view filename() const { return message_reader_->filename(); } |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 689 | |
| 690 | // Adds more messages to the sorted list. This reads enough data such that |
| 691 | // oldest_message_time can be replayed safely. Returns false if the log file |
| 692 | // has all been read. |
| 693 | bool QueueMessages(monotonic_clock::time_point oldest_message_time); |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 694 | |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 695 | // Returns debug strings for a channel, and timestamps for a node. |
| 696 | std::string DebugString(int channel) const; |
| 697 | std::string DebugString(int channel, int node_index) const; |
| 698 | |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 699 | // Returns true if all the messages have been queued from the last log file in |
| 700 | // the list of log files chunks. |
| 701 | bool at_end() const { return at_end_; } |
| 702 | |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 703 | private: |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 704 | // TODO(austin): Need to copy or refcount the message instead of running |
| 705 | // multiple copies of the reader. Or maybe have a "as_node" index and hide it |
| 706 | // inside. |
| 707 | |
Austin Schuh | fa89589 | 2020-01-07 20:07:41 -0800 | [diff] [blame] | 708 | // Moves to the next log file in the list. |
| 709 | bool NextLogFile(); |
| 710 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 711 | // Filenames of the log files. |
| 712 | std::vector<std::string> filenames_; |
| 713 | // And the index of the next file to open. |
| 714 | size_t next_filename_index_ = 0; |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 715 | |
Austin Schuh | ee71105 | 2020-08-24 16:06:09 -0700 | [diff] [blame] | 716 | // Node we are reading as. |
| 717 | const Node *target_node_ = nullptr; |
| 718 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 719 | // Log file header to report. This is a copy. |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 720 | SizePrefixedFlatbufferVector<LogFileHeader> log_file_header_; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 721 | // Current log file being read. |
| 722 | std::unique_ptr<MessageReader> message_reader_; |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 723 | |
| 724 | // Datastructure to hold the list of messages, cached timestamp for the |
| 725 | // oldest message, and sender to send with. |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 726 | struct MessageHeaderQueue { |
| 727 | // If true, this is a timestamp queue. |
| 728 | bool timestamps = false; |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 729 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 730 | // Returns a reference to the the oldest message. |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 731 | SizePrefixedFlatbufferVector<MessageHeader> &front() { |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 732 | CHECK_GT(data_.size(), 0u); |
| 733 | return data_.front(); |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 734 | } |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 735 | |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 736 | // Adds a message to the back of the queue. Returns true if it was actually |
| 737 | // emplaced. |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 738 | bool emplace_back(SizePrefixedFlatbufferVector<MessageHeader> &&msg); |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 739 | |
| 740 | // Drops the front message. Invalidates the front() reference. |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 741 | void PopFront(); |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 742 | |
| 743 | // The size of the queue. |
| 744 | size_t size() { return data_.size(); } |
| 745 | |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 746 | // Returns a debug string with info about each message in the queue. |
| 747 | std::string DebugString() const; |
| 748 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 749 | // Returns the (timestamp, queue_index, message_header) for the oldest |
| 750 | // message. |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 751 | const std::tuple<monotonic_clock::time_point, uint32_t, |
| 752 | const MessageHeader *> |
| 753 | front_timestamp() { |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 754 | const MessageHeader &message = front().message(); |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 755 | return std::make_tuple( |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 756 | monotonic_clock::time_point( |
| 757 | std::chrono::nanoseconds(message.monotonic_sent_time())), |
| 758 | message.queue_index(), &message); |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 759 | } |
| 760 | |
| 761 | // Pointer to the timestamp merger for this queue if available. |
| 762 | TimestampMerger *timestamp_merger = nullptr; |
| 763 | // Pointer to the reader which feeds this queue. |
| 764 | SplitMessageReader *split_reader = nullptr; |
| 765 | |
| 766 | private: |
| 767 | // The data. |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 768 | std::deque<SizePrefixedFlatbufferVector<MessageHeader>> data_; |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 769 | }; |
| 770 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 771 | // All the queues needed for a channel. There isn't going to be data in all |
| 772 | // of these. |
| 773 | struct ChannelData { |
| 774 | // The data queue for the channel. |
| 775 | MessageHeaderQueue data; |
| 776 | // Queues for timestamps for each node. |
| 777 | std::vector<MessageHeaderQueue> timestamps; |
| 778 | }; |
Austin Schuh | fa89589 | 2020-01-07 20:07:41 -0800 | [diff] [blame] | 779 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 780 | // Data for all the channels. |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 781 | std::vector<ChannelData> channels_; |
| 782 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 783 | // Once we know the node that this SplitMessageReader will be writing as, |
| 784 | // there will be only one MessageHeaderQueue that a specific channel matches. |
| 785 | // Precompute this here for efficiency. |
| 786 | std::vector<MessageHeaderQueue *> channels_to_write_; |
| 787 | |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 788 | monotonic_clock::time_point time_to_queue_ = monotonic_clock::min_time; |
| 789 | |
| 790 | // Latches true when we hit the end of the last log file and there is no sense |
| 791 | // poking it further. |
| 792 | bool at_end_ = false; |
| 793 | |
| 794 | // Timestamp of the newest message that was read and actually queued. We want |
| 795 | // to track this independently from the log file because we need the |
| 796 | // timestamps here to be timestamps of messages that are queued. |
| 797 | monotonic_clock::time_point newest_timestamp_ = monotonic_clock::min_time; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 798 | }; |
| 799 | |
| 800 | class ChannelMerger; |
| 801 | |
| 802 | // Sorts channels (and timestamps) from multiple log files for a single channel. |
| 803 | class TimestampMerger { |
| 804 | public: |
| 805 | TimestampMerger(const Configuration *configuration, |
| 806 | std::vector<SplitMessageReader *> split_message_readers, |
| 807 | int channel_index, const Node *target_node, |
| 808 | ChannelMerger *channel_merger); |
| 809 | |
| 810 | // Metadata used to schedule the message. |
| 811 | struct DeliveryTimestamp { |
| 812 | monotonic_clock::time_point monotonic_event_time = |
| 813 | monotonic_clock::min_time; |
| 814 | realtime_clock::time_point realtime_event_time = realtime_clock::min_time; |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 815 | uint32_t queue_index = 0xffffffff; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 816 | |
| 817 | monotonic_clock::time_point monotonic_remote_time = |
| 818 | monotonic_clock::min_time; |
| 819 | realtime_clock::time_point realtime_remote_time = realtime_clock::min_time; |
| 820 | uint32_t remote_queue_index = 0xffffffff; |
| 821 | }; |
| 822 | |
| 823 | // Pushes SplitMessageReader onto the timestamp heap. This should only be |
| 824 | // called when timestamps are placed in the channel this class is merging for |
| 825 | // the reader. |
| 826 | void UpdateTimestamp( |
| 827 | SplitMessageReader *split_message_reader, |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 828 | std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *> |
| 829 | oldest_message_time) { |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 830 | PushTimestampHeap(oldest_message_time, split_message_reader); |
| 831 | } |
| 832 | // Pushes SplitMessageReader onto the message heap. This should only be |
| 833 | // called when data is placed in the channel this class is merging for the |
| 834 | // reader. |
| 835 | void Update( |
| 836 | SplitMessageReader *split_message_reader, |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 837 | std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *> |
| 838 | oldest_message_time) { |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 839 | PushMessageHeap(oldest_message_time, split_message_reader); |
| 840 | } |
| 841 | |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 842 | // Returns the oldest combined timestamp and data for this channel. If there |
| 843 | // isn't a matching piece of data, returns only the timestamp with no data. |
| 844 | // The caller can determine what the appropriate action is to recover. |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 845 | std::tuple<DeliveryTimestamp, SizePrefixedFlatbufferVector<MessageHeader>> |
| 846 | PopOldest(); |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 847 | |
| 848 | // Tracks if the channel merger has pushed this onto it's heap or not. |
| 849 | bool pushed() { return pushed_; } |
| 850 | // Sets if this has been pushed to the channel merger heap. Should only be |
| 851 | // called by the channel merger. |
| 852 | void set_pushed(bool pushed) { pushed_ = pushed; } |
| 853 | |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 854 | // Returns a debug string with the heaps printed out. |
| 855 | std::string DebugString() const; |
| 856 | |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 857 | // Returns true if we have timestamps. |
| 858 | bool has_timestamps() const { return has_timestamps_; } |
| 859 | |
| 860 | // Records that one of the log files ran out of data. This should only be |
| 861 | // called by a SplitMessageReader. |
| 862 | void NoticeAtEnd(); |
| 863 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 864 | aos::monotonic_clock::time_point channel_merger_time() { |
| 865 | if (has_timestamps_) { |
| 866 | return std::get<0>(timestamp_heap_[0]); |
| 867 | } else { |
| 868 | return std::get<0>(message_heap_[0]); |
| 869 | } |
| 870 | } |
| 871 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 872 | private: |
| 873 | // Pushes messages and timestamps to the corresponding heaps. |
| 874 | void PushMessageHeap( |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 875 | std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *> |
| 876 | timestamp, |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 877 | SplitMessageReader *split_message_reader); |
| 878 | void PushTimestampHeap( |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 879 | std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *> |
| 880 | timestamp, |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 881 | SplitMessageReader *split_message_reader); |
| 882 | |
| 883 | // Pops a message from the message heap. This automatically triggers the |
| 884 | // split message reader to re-fetch any new data. |
| 885 | std::tuple<monotonic_clock::time_point, uint32_t, |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 886 | SizePrefixedFlatbufferVector<MessageHeader>> |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 887 | PopMessageHeap(); |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 888 | |
| 889 | std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *> |
| 890 | oldest_message() const; |
| 891 | std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *> |
| 892 | oldest_timestamp() const; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 893 | // Pops a message from the timestamp heap. This automatically triggers the |
| 894 | // split message reader to re-fetch any new data. |
| 895 | std::tuple<monotonic_clock::time_point, uint32_t, |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 896 | SizePrefixedFlatbufferVector<MessageHeader>> |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 897 | PopTimestampHeap(); |
| 898 | |
| 899 | const Configuration *configuration_; |
| 900 | |
| 901 | // If true, this is a forwarded channel and timestamps should be matched. |
| 902 | bool has_timestamps_ = false; |
| 903 | |
| 904 | // Tracks if the ChannelMerger has pushed this onto it's queue. |
| 905 | bool pushed_ = false; |
| 906 | |
| 907 | // The split message readers used for source data. |
| 908 | std::vector<SplitMessageReader *> split_message_readers_; |
| 909 | |
| 910 | // The channel to merge. |
| 911 | int channel_index_; |
| 912 | |
| 913 | // Our node. |
| 914 | int node_index_; |
| 915 | |
| 916 | // Heaps for messages and timestamps. |
| 917 | std::vector< |
| 918 | std::tuple<monotonic_clock::time_point, uint32_t, SplitMessageReader *>> |
| 919 | message_heap_; |
| 920 | std::vector< |
| 921 | std::tuple<monotonic_clock::time_point, uint32_t, SplitMessageReader *>> |
| 922 | timestamp_heap_; |
| 923 | |
| 924 | // Parent channel merger. |
| 925 | ChannelMerger *channel_merger_; |
| 926 | }; |
| 927 | |
| 928 | // This class handles constructing all the split message readers, channel |
| 929 | // mergers, and combining the results. |
| 930 | class ChannelMerger { |
| 931 | public: |
| 932 | // Builds a ChannelMerger around a set of log files. These are of the format: |
| 933 | // { |
| 934 | // {log1_part0, log1_part1, ...}, |
| 935 | // {log2} |
| 936 | // } |
| 937 | // The inner vector is a list of log file chunks which form up a log file. |
| 938 | // The outer vector is a list of log files with subsets of the messages, or |
| 939 | // messages from different nodes. |
| 940 | ChannelMerger(const std::vector<std::vector<std::string>> &filenames); |
| 941 | |
| 942 | // Returns the nodes that we know how to merge. |
| 943 | const std::vector<const Node *> nodes() const; |
| 944 | // Sets the node that we will return messages as. Returns true if the node |
| 945 | // has log files and will produce data. This can only be called once, and |
| 946 | // will likely corrupt state if called a second time. |
| 947 | bool SetNode(const Node *target_node); |
| 948 | |
| 949 | // Everything else needs the node set before it works. |
| 950 | |
| 951 | // Returns a timestamp for the oldest message in this group of logfiles. |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 952 | monotonic_clock::time_point OldestMessageTime() const; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 953 | // Pops the oldest message. |
| 954 | std::tuple<TimestampMerger::DeliveryTimestamp, int, |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 955 | SizePrefixedFlatbufferVector<MessageHeader>> |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 956 | PopOldest(); |
| 957 | |
| 958 | // Returns the config for this set of log files. |
| 959 | const Configuration *configuration() const { |
| 960 | return log_file_header()->configuration(); |
| 961 | } |
| 962 | |
| 963 | const LogFileHeader *log_file_header() const { |
| 964 | return &log_file_header_.message(); |
| 965 | } |
| 966 | |
| 967 | // Returns the start times for the configured node's log files. |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 968 | monotonic_clock::time_point monotonic_start_time() const { |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 969 | return monotonic_clock::time_point( |
| 970 | std::chrono::nanoseconds(log_file_header()->monotonic_start_time())); |
| 971 | } |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 972 | realtime_clock::time_point realtime_start_time() const { |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 973 | return realtime_clock::time_point( |
| 974 | std::chrono::nanoseconds(log_file_header()->realtime_start_time())); |
| 975 | } |
| 976 | |
| 977 | // Returns the node set by SetNode above. |
| 978 | const Node *node() const { return node_; } |
| 979 | |
| 980 | // Called by the TimestampMerger when new data is available with the provided |
| 981 | // timestamp and channel_index. |
| 982 | void Update(monotonic_clock::time_point timestamp, int channel_index) { |
| 983 | PushChannelHeap(timestamp, channel_index); |
| 984 | } |
| 985 | |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 986 | // Returns a debug string with all the heaps in it. Generally only useful for |
| 987 | // debugging what went wrong. |
| 988 | std::string DebugString() const; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 989 | |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 990 | // Returns true if one of the log files has finished reading everything. When |
| 991 | // log file chunks are involved, this means that the last chunk in a log file |
| 992 | // has been read. It is acceptable to be missing data at this point in time. |
| 993 | bool at_end() const { return at_end_; } |
| 994 | |
| 995 | // Marks that one of the log files is at the end. This should only be called |
| 996 | // by timestamp mergers. |
| 997 | void NoticeAtEnd() { at_end_ = true; } |
| 998 | |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 999 | private: |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 1000 | // Pushes the timestamp for new data on the provided channel. |
| 1001 | void PushChannelHeap(monotonic_clock::time_point timestamp, |
| 1002 | int channel_index); |
| 1003 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 1004 | // CHECKs that channel_heap_ and timestamp_heap_ are valid heaps. |
| 1005 | void VerifyHeaps(); |
| 1006 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 1007 | // All the message readers. |
| 1008 | std::vector<std::unique_ptr<SplitMessageReader>> split_message_readers_; |
| 1009 | |
| 1010 | // The log header we are claiming to be. |
Austin Schuh | add6eb3 | 2020-11-09 21:24:26 -0800 | [diff] [blame] | 1011 | SizePrefixedFlatbufferVector<LogFileHeader> log_file_header_; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 1012 | |
| 1013 | // The timestamp mergers which combine data from the split message readers. |
| 1014 | std::vector<TimestampMerger> timestamp_mergers_; |
| 1015 | |
| 1016 | // A heap of the channel readers and timestamps for the oldest data in each. |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 1017 | std::vector<std::pair<monotonic_clock::time_point, int>> channel_heap_; |
| 1018 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 1019 | // Configured node. |
| 1020 | const Node *node_; |
| 1021 | |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 1022 | bool at_end_ = false; |
| 1023 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 1024 | // Cached copy of the list of nodes. |
| 1025 | std::vector<const Node *> nodes_; |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 1026 | |
| 1027 | // Last time popped. Used to detect events being returned out of order. |
| 1028 | monotonic_clock::time_point last_popped_time_ = monotonic_clock::min_time; |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 1029 | }; |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 1030 | |
Austin Schuh | ee71105 | 2020-08-24 16:06:09 -0700 | [diff] [blame] | 1031 | // Returns the node name with a trailing space, or an empty string if we are on |
| 1032 | // a single node. |
| 1033 | std::string MaybeNodeName(const Node *); |
| 1034 | |
Brian Silverman | f51499a | 2020-09-21 12:49:08 -0700 | [diff] [blame] | 1035 | } // namespace aos::logger |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 1036 | |
| 1037 | #endif // AOS_EVENTS_LOGGING_LOGFILE_UTILS_H_ |