blob: 25f02f90727eba89850014049640cacb06d1f0a4 [file] [log] [blame]
Austin Schuha36c8902019-12-30 18:07:15 -08001#ifndef AOS_EVENTS_LOGGING_LOGFILE_UTILS_H_
2#define AOS_EVENTS_LOGGING_LOGFILE_UTILS_H_
3
4#include <sys/uio.h>
5
Austin Schuh97789fc2020-08-01 14:42:45 -07006#include <chrono>
Austin Schuh05b70472020-01-01 17:11:17 -08007#include <deque>
Austin Schuh97789fc2020-08-01 14:42:45 -07008#include <limits>
9#include <memory>
Austin Schuh05b70472020-01-01 17:11:17 -080010#include <optional>
Austin Schuhfa895892020-01-07 20:07:41 -080011#include <string>
Austin Schuha36c8902019-12-30 18:07:15 -080012#include <string_view>
Brian Silverman98360e22020-04-28 16:51:20 -070013#include <tuple>
Austin Schuh97789fc2020-08-01 14:42:45 -070014#include <utility>
Austin Schuha36c8902019-12-30 18:07:15 -080015#include <vector>
16
Austin Schuh05b70472020-01-01 17:11:17 -080017#include "absl/types/span.h"
Brian Silvermanf51499a2020-09-21 12:49:08 -070018#include "aos/containers/resizeable_buffer.h"
Austin Schuha36c8902019-12-30 18:07:15 -080019#include "aos/events/event_loop.h"
Brian Silvermanf51499a2020-09-21 12:49:08 -070020#include "aos/events/logging/buffer_encoder.h"
Austin Schuhc41603c2020-10-11 16:17:37 -070021#include "aos/events/logging/logfile_sorting.h"
Austin Schuha36c8902019-12-30 18:07:15 -080022#include "aos/events/logging/logger_generated.h"
Brian Silvermanf51499a2020-09-21 12:49:08 -070023#include "aos/flatbuffers.h"
Austin Schuha36c8902019-12-30 18:07:15 -080024#include "flatbuffers/flatbuffers.h"
25
Brian Silvermanf51499a2020-09-21 12:49:08 -070026namespace aos::logger {
Austin Schuha36c8902019-12-30 18:07:15 -080027
28enum class LogType : uint8_t {
29 // The message originated on this node and should be logged here.
30 kLogMessage,
31 // The message originated on another node, but only the delivery times are
32 // logged here.
33 kLogDeliveryTimeOnly,
34 // The message originated on another node. Log it and the delivery times
35 // together. The message_gateway is responsible for logging any messages
36 // which didn't get delivered.
Austin Schuh6f3babe2020-01-26 20:34:50 -080037 kLogMessageAndDeliveryTime,
38 // The message originated on the other node and should be logged on this node.
39 kLogRemoteMessage
Austin Schuha36c8902019-12-30 18:07:15 -080040};
41
Austin Schuha36c8902019-12-30 18:07:15 -080042// This class manages efficiently writing a sequence of detached buffers to a
Brian Silvermanf51499a2020-09-21 12:49:08 -070043// file. It encodes them, queues them up, and batches the write operation.
Austin Schuha36c8902019-12-30 18:07:15 -080044class DetachedBufferWriter {
45 public:
Brian Silvermana9f2ec92020-10-06 18:00:53 -070046 // Marker struct for one of our constructor overloads.
47 struct already_out_of_space_t {};
48
Brian Silvermanf51499a2020-09-21 12:49:08 -070049 DetachedBufferWriter(std::string_view filename,
50 std::unique_ptr<DetachedBufferEncoder> encoder);
Brian Silvermana9f2ec92020-10-06 18:00:53 -070051 // Creates a dummy instance which won't even open a file. It will act as if
52 // opening the file ran out of space immediately.
53 DetachedBufferWriter(already_out_of_space_t) : ran_out_of_space_(true) {}
Austin Schuh2f8fd752020-09-01 22:38:28 -070054 DetachedBufferWriter(DetachedBufferWriter &&other);
55 DetachedBufferWriter(const DetachedBufferWriter &) = delete;
56
Austin Schuha36c8902019-12-30 18:07:15 -080057 ~DetachedBufferWriter();
58
Austin Schuh2f8fd752020-09-01 22:38:28 -070059 DetachedBufferWriter &operator=(DetachedBufferWriter &&other);
Brian Silverman98360e22020-04-28 16:51:20 -070060 DetachedBufferWriter &operator=(const DetachedBufferWriter &) = delete;
61
Austin Schuh6f3babe2020-01-26 20:34:50 -080062 std::string_view filename() const { return filename_; }
63
Brian Silvermana9f2ec92020-10-06 18:00:53 -070064 // This will be true until Close() is called, unless the file couldn't be
65 // created due to running out of space.
66 bool is_open() const { return fd_ != -1; }
67
Brian Silvermanf51499a2020-09-21 12:49:08 -070068 // Queues up a finished FlatBufferBuilder to be encoded and written.
69 //
70 // Triggers a flush if there's enough data queued up.
71 //
72 // Steals the detached buffer from it.
73 void QueueSizedFlatbuffer(flatbuffers::FlatBufferBuilder *fbb) {
74 QueueSizedFlatbuffer(fbb->Release());
75 }
76 // May steal the backing storage of buffer, or may leave it alone.
77 void QueueSizedFlatbuffer(flatbuffers::DetachedBuffer &&buffer) {
Brian Silvermana9f2ec92020-10-06 18:00:53 -070078 if (ran_out_of_space_) {
79 return;
80 }
Brian Silvermanf51499a2020-09-21 12:49:08 -070081 encoder_->Encode(std::move(buffer));
82 FlushAtThreshold();
83 }
Austin Schuha36c8902019-12-30 18:07:15 -080084
Brian Silvermanf51499a2020-09-21 12:49:08 -070085 // Queues up data in span. May copy or may write it to disk immediately.
86 void QueueSpan(absl::Span<const uint8_t> span);
Austin Schuha36c8902019-12-30 18:07:15 -080087
Brian Silverman0465fcf2020-09-24 00:29:18 -070088 // Indicates we got ENOSPC when trying to write. After this returns true, no
89 // further data is written.
90 bool ran_out_of_space() const { return ran_out_of_space_; }
91
92 // To avoid silently failing to write logfiles, you must call this before
93 // destruction if ran_out_of_space() is true and the situation has been
94 // handled.
95 void acknowledge_out_of_space() {
96 CHECK(ran_out_of_space_);
97 acknowledge_ran_out_of_space_ = true;
98 }
99
100 // Fully flushes and closes the underlying file now. No additional data may be
101 // enqueued after calling this.
102 //
103 // This will be performed in the destructor automatically.
104 //
105 // Note that this may set ran_out_of_space().
106 void Close();
107
Brian Silvermanf51499a2020-09-21 12:49:08 -0700108 // Returns the total number of bytes written and currently queued.
109 size_t total_bytes() const { return encoder_->total_bytes(); }
Austin Schuha36c8902019-12-30 18:07:15 -0800110
Brian Silvermanf51499a2020-09-21 12:49:08 -0700111 // The maximum time for a single write call, or 0 if none have been performed.
112 std::chrono::nanoseconds max_write_time() const { return max_write_time_; }
113 // The number of bytes in the longest write call, or -1 if none have been
114 // performed.
115 int max_write_time_bytes() const { return max_write_time_bytes_; }
116 // The number of buffers in the longest write call, or -1 if none have been
117 // performed.
118 int max_write_time_messages() const { return max_write_time_messages_; }
119 // The total time spent in write calls.
120 std::chrono::nanoseconds total_write_time() const {
121 return total_write_time_;
122 }
123 // The total number of writes which have been performed.
124 int total_write_count() const { return total_write_count_; }
125 // The total number of messages which have been written.
126 int total_write_messages() const { return total_write_messages_; }
127 // The total number of bytes which have been written.
128 int total_write_bytes() const { return total_write_bytes_; }
129 void ResetStatistics() {
130 max_write_time_ = std::chrono::nanoseconds::zero();
131 max_write_time_bytes_ = -1;
132 max_write_time_messages_ = -1;
133 total_write_time_ = std::chrono::nanoseconds::zero();
134 total_write_count_ = 0;
135 total_write_messages_ = 0;
136 total_write_bytes_ = 0;
137 }
Brian Silverman98360e22020-04-28 16:51:20 -0700138
Austin Schuha36c8902019-12-30 18:07:15 -0800139 private:
Brian Silvermanf51499a2020-09-21 12:49:08 -0700140 // Performs a single writev call with as much of the data we have queued up as
141 // possible.
142 //
143 // This will normally take all of the data we have queued up, unless an
144 // encoder has spit out a big enough chunk all at once that we can't manage
145 // all of it.
146 void Flush();
147
Brian Silverman0465fcf2020-09-24 00:29:18 -0700148 // write_return is what write(2) or writev(2) returned. write_size is the
149 // number of bytes we expected it to write.
150 void HandleWriteReturn(ssize_t write_return, size_t write_size);
151
Brian Silvermanf51499a2020-09-21 12:49:08 -0700152 void UpdateStatsForWrite(aos::monotonic_clock::duration duration,
153 ssize_t written, int iovec_size);
154
155 // Flushes data if we've reached the threshold to do that as part of normal
156 // operation.
157 void FlushAtThreshold();
158
Austin Schuh2f8fd752020-09-01 22:38:28 -0700159 std::string filename_;
Brian Silvermanf51499a2020-09-21 12:49:08 -0700160 std::unique_ptr<DetachedBufferEncoder> encoder_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800161
Austin Schuha36c8902019-12-30 18:07:15 -0800162 int fd_ = -1;
Brian Silverman0465fcf2020-09-24 00:29:18 -0700163 bool ran_out_of_space_ = false;
164 bool acknowledge_ran_out_of_space_ = false;
Austin Schuha36c8902019-12-30 18:07:15 -0800165
Austin Schuha36c8902019-12-30 18:07:15 -0800166 // List of iovecs to use with writev. This is a member variable to avoid
167 // churn.
168 std::vector<struct iovec> iovec_;
Brian Silvermanf51499a2020-09-21 12:49:08 -0700169
170 std::chrono::nanoseconds max_write_time_ = std::chrono::nanoseconds::zero();
171 int max_write_time_bytes_ = -1;
172 int max_write_time_messages_ = -1;
173 std::chrono::nanoseconds total_write_time_ = std::chrono::nanoseconds::zero();
174 int total_write_count_ = 0;
175 int total_write_messages_ = 0;
176 int total_write_bytes_ = 0;
Austin Schuha36c8902019-12-30 18:07:15 -0800177};
178
179// Packes a message pointed to by the context into a MessageHeader.
180flatbuffers::Offset<MessageHeader> PackMessage(
181 flatbuffers::FlatBufferBuilder *fbb, const Context &context,
182 int channel_index, LogType log_type);
183
Austin Schuhadd6eb32020-11-09 21:24:26 -0800184std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> ReadHeader(
Austin Schuh3bd4c402020-11-06 18:19:06 -0800185 std::string_view filename);
Austin Schuhadd6eb32020-11-09 21:24:26 -0800186std::optional<SizePrefixedFlatbufferVector<MessageHeader>> ReadNthMessage(
Austin Schuh3bd4c402020-11-06 18:19:06 -0800187 std::string_view filename, size_t n);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800188
Austin Schuh05b70472020-01-01 17:11:17 -0800189// Class to read chunks out of a log file.
190class SpanReader {
191 public:
192 SpanReader(std::string_view filename);
Austin Schuha36c8902019-12-30 18:07:15 -0800193
Austin Schuh6f3babe2020-01-26 20:34:50 -0800194 std::string_view filename() const { return filename_; }
195
Austin Schuh05b70472020-01-01 17:11:17 -0800196 // Returns a span with the data for a message from the log file, excluding
197 // the size.
198 absl::Span<const uint8_t> ReadMessage();
199
Austin Schuh05b70472020-01-01 17:11:17 -0800200 private:
201 // TODO(austin): Optimization:
202 // Allocate the 256k blocks like we do today. But, refcount them with
203 // shared_ptr pointed to by the messageheader that is returned. This avoids
204 // the copy. Need to do more benchmarking.
Brian Silvermanf51499a2020-09-21 12:49:08 -0700205 // And (Brian): Consider just mmapping the file and handing out refcounted
206 // pointers into that too.
Austin Schuh05b70472020-01-01 17:11:17 -0800207
208 // Reads a chunk of data into data_. Returns false if no data was read.
209 bool ReadBlock();
210
Austin Schuhc41603c2020-10-11 16:17:37 -0700211 std::string filename_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800212
Brian Silvermanf51499a2020-09-21 12:49:08 -0700213 // File reader and data decoder.
214 std::unique_ptr<DataDecoder> decoder_;
Austin Schuh05b70472020-01-01 17:11:17 -0800215
Brian Silvermanf51499a2020-09-21 12:49:08 -0700216 // Vector to read into.
217 ResizeableBuffer data_;
Austin Schuh05b70472020-01-01 17:11:17 -0800218
219 // Amount of data consumed already in data_.
220 size_t consumed_data_ = 0;
Austin Schuh05b70472020-01-01 17:11:17 -0800221};
222
223// Class which handles reading the header and messages from the log file. This
224// handles any per-file state left before merging below.
225class MessageReader {
226 public:
227 MessageReader(std::string_view filename);
228
Austin Schuh6f3babe2020-01-26 20:34:50 -0800229 std::string_view filename() const { return span_reader_.filename(); }
230
Austin Schuh05b70472020-01-01 17:11:17 -0800231 // Returns the header from the log file.
232 const LogFileHeader *log_file_header() const {
Austin Schuh97789fc2020-08-01 14:42:45 -0700233 return &raw_log_file_header_.message();
234 }
235
236 // Returns the raw data of the header from the log file.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800237 const SizePrefixedFlatbufferVector<LogFileHeader> &raw_log_file_header()
238 const {
Austin Schuh97789fc2020-08-01 14:42:45 -0700239 return raw_log_file_header_;
Austin Schuh05b70472020-01-01 17:11:17 -0800240 }
241
242 // Returns the minimum maount of data needed to queue up for sorting before
243 // ware guarenteed to not see data out of order.
244 std::chrono::nanoseconds max_out_of_order_duration() const {
245 return max_out_of_order_duration_;
246 }
247
Austin Schuhcde938c2020-02-02 17:30:07 -0800248 // Returns the newest timestamp read out of the log file.
Austin Schuh05b70472020-01-01 17:11:17 -0800249 monotonic_clock::time_point newest_timestamp() const {
250 return newest_timestamp_;
251 }
252
253 // Returns the next message if there is one.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800254 std::optional<SizePrefixedFlatbufferVector<MessageHeader>> ReadMessage();
Austin Schuh05b70472020-01-01 17:11:17 -0800255
256 // The time at which we need to read another chunk from the logfile.
257 monotonic_clock::time_point queue_data_time() const {
258 return newest_timestamp() - max_out_of_order_duration();
259 }
260
261 private:
262 // Log chunk reader.
263 SpanReader span_reader_;
264
Austin Schuh97789fc2020-08-01 14:42:45 -0700265 // Vector holding the raw data for the log file header.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800266 SizePrefixedFlatbufferVector<LogFileHeader> raw_log_file_header_;
Austin Schuh05b70472020-01-01 17:11:17 -0800267
268 // Minimum amount of data to queue up for sorting before we are guarenteed
269 // to not see data out of order.
270 std::chrono::nanoseconds max_out_of_order_duration_;
271
272 // Timestamp of the newest message in a channel queue.
273 monotonic_clock::time_point newest_timestamp_ = monotonic_clock::min_time;
274};
275
Austin Schuhc41603c2020-10-11 16:17:37 -0700276// A class to seamlessly read messages from a list of part files.
277class PartsMessageReader {
278 public:
279 PartsMessageReader(LogParts log_parts);
280
281 std::string_view filename() const { return message_reader_.filename(); }
282
283 // Returns the minimum amount of data needed to queue up for sorting before
284 // we are guarenteed to not see data out of order.
285 std::chrono::nanoseconds max_out_of_order_duration() const {
286 return message_reader_.max_out_of_order_duration();
287 }
288
289 // Returns the newest timestamp read out of the log file.
290 monotonic_clock::time_point newest_timestamp() const {
291 return newest_timestamp_;
292 }
293
294 // Returns the next message if there is one, or nullopt if we have reached the
295 // end of all the files.
296 // Note: reading the next message may change the max_out_of_order_duration().
Austin Schuhadd6eb32020-11-09 21:24:26 -0800297 std::optional<SizePrefixedFlatbufferVector<MessageHeader>> ReadMessage();
Austin Schuhc41603c2020-10-11 16:17:37 -0700298
299 private:
300 // Opens the next log and updates message_reader_. Sets done_ if there is
301 // nothing more to do.
302 void NextLog();
303
304 const LogParts parts_;
305 size_t next_part_index_ = 1u;
306 bool done_ = false;
307 MessageReader message_reader_;
308
309 monotonic_clock::time_point newest_timestamp_ = monotonic_clock::min_time;
310};
311
Austin Schuh1be0ce42020-11-29 22:43:26 -0800312// Struct to hold a message as it gets sorted on a single node.
313struct Message {
314 // The channel.
315 uint32_t channel_index = 0xffffffff;
316 // The local queue index.
317 uint32_t queue_index = 0xffffffff;
318 // The local timestamp on the monotonic clock.
319 monotonic_clock::time_point timestamp = monotonic_clock::min_time;
320 // The data (either a timestamp header, or a data header).
321 SizePrefixedFlatbufferVector<MessageHeader> data;
322
323 bool operator<(const Message &m2) const;
324 bool operator>=(const Message &m2) const;
325};
326
327std::ostream &operator<<(std::ostream &os, const Message &m);
328
Austin Schuh6f3babe2020-01-26 20:34:50 -0800329class TimestampMerger;
Austin Schuh05b70472020-01-01 17:11:17 -0800330
Austin Schuh6f3babe2020-01-26 20:34:50 -0800331// A design requirement is that the relevant data for a channel is not more than
332// max_out_of_order_duration out of order. We approach sorting in layers.
333//
334// 1) Split each (maybe chunked) log file into one queue per channel. Read this
335// log file looking for data pertaining to a specific node.
336// (SplitMessageReader)
337// 2) Merge all the data per channel from the different log files into a sorted
338// list of timestamps and messages. (TimestampMerger)
339// 3) Combine the timestamps and messages. (TimestampMerger)
340// 4) Merge all the channels to produce the next message on a node.
341// (ChannelMerger)
342// 5) Duplicate this entire stack per node.
343
344// This class splits messages and timestamps up into a queue per channel, and
345// handles reading data from multiple chunks.
346class SplitMessageReader {
347 public:
348 SplitMessageReader(const std::vector<std::string> &filenames);
349
350 // Sets the TimestampMerger that gets notified for each channel. The node
351 // that the TimestampMerger is merging as needs to be passed in.
352 void SetTimestampMerger(TimestampMerger *timestamp_merger, int channel,
353 const Node *target_node);
354
Austin Schuh2f8fd752020-09-01 22:38:28 -0700355 // Returns the (timestamp, queue_index, message_header) for the oldest message
356 // in a channel, or max_time if there is nothing in the channel.
Austin Schuhcde938c2020-02-02 17:30:07 -0800357 std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *>
358 oldest_message(int channel) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800359 return channels_[channel].data.front_timestamp();
360 }
361
Austin Schuh2f8fd752020-09-01 22:38:28 -0700362 // Returns the (timestamp, queue_index, message_header) for the oldest
363 // delivery time in a channel, or max_time if there is nothing in the channel.
Austin Schuhcde938c2020-02-02 17:30:07 -0800364 std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *>
365 oldest_message(int channel, int destination_node) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800366 return channels_[channel].timestamps[destination_node].front_timestamp();
367 }
368
369 // Returns the timestamp, queue_index, and message for the oldest data on a
370 // channel. Requeues data as needed.
371 std::tuple<monotonic_clock::time_point, uint32_t,
Austin Schuhadd6eb32020-11-09 21:24:26 -0800372 SizePrefixedFlatbufferVector<MessageHeader>>
Austin Schuh6f3babe2020-01-26 20:34:50 -0800373 PopOldest(int channel_index);
374
375 // Returns the timestamp, queue_index, and message for the oldest timestamp on
376 // a channel delivered to a node. Requeues data as needed.
377 std::tuple<monotonic_clock::time_point, uint32_t,
Austin Schuhadd6eb32020-11-09 21:24:26 -0800378 SizePrefixedFlatbufferVector<MessageHeader>>
Austin Schuh2f8fd752020-09-01 22:38:28 -0700379 PopOldestTimestamp(int channel, int node_index);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800380
381 // Returns the header for the log files.
Austin Schuh05b70472020-01-01 17:11:17 -0800382 const LogFileHeader *log_file_header() const {
Austin Schuhfa895892020-01-07 20:07:41 -0800383 return &log_file_header_.message();
Austin Schuh05b70472020-01-01 17:11:17 -0800384 }
385
Austin Schuhadd6eb32020-11-09 21:24:26 -0800386 const SizePrefixedFlatbufferVector<LogFileHeader> &raw_log_file_header()
387 const {
Austin Schuh97789fc2020-08-01 14:42:45 -0700388 return log_file_header_;
389 }
390
Austin Schuh6f3babe2020-01-26 20:34:50 -0800391 // Returns the starting time for this set of log files.
Austin Schuh05b70472020-01-01 17:11:17 -0800392 monotonic_clock::time_point monotonic_start_time() {
393 return monotonic_clock::time_point(
394 std::chrono::nanoseconds(log_file_header()->monotonic_start_time()));
395 }
396 realtime_clock::time_point realtime_start_time() {
397 return realtime_clock::time_point(
398 std::chrono::nanoseconds(log_file_header()->realtime_start_time()));
399 }
400
Austin Schuh6f3babe2020-01-26 20:34:50 -0800401 // Returns the configuration from the log file header.
402 const Configuration *configuration() const {
403 return log_file_header()->configuration();
404 }
405
Austin Schuh05b70472020-01-01 17:11:17 -0800406 // Returns the node who's point of view this log file is from. Make sure this
407 // is a pointer in the configuration() nodes list so it can be consumed
408 // elsewhere.
409 const Node *node() const {
410 if (configuration()->has_nodes()) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800411 return configuration::GetNodeOrDie(configuration(),
412 log_file_header()->node());
Austin Schuh05b70472020-01-01 17:11:17 -0800413 } else {
414 CHECK(!log_file_header()->has_node());
415 return nullptr;
416 }
417 }
418
Austin Schuh6f3babe2020-01-26 20:34:50 -0800419 // Returns the timestamp of the newest message read from the log file, and the
420 // timestamp that we need to re-queue data.
421 monotonic_clock::time_point newest_timestamp() const {
Austin Schuhcde938c2020-02-02 17:30:07 -0800422 return newest_timestamp_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800423 }
424
Austin Schuhcde938c2020-02-02 17:30:07 -0800425 // Returns the next time to trigger a requeue.
426 monotonic_clock::time_point time_to_queue() const { return time_to_queue_; }
427
428 // Returns the minimum amount of data needed to queue up for sorting before
Austin Schuhc41603c2020-10-11 16:17:37 -0700429 // we are guarenteed to not see data out of order.
Austin Schuhcde938c2020-02-02 17:30:07 -0800430 std::chrono::nanoseconds max_out_of_order_duration() const {
431 return message_reader_->max_out_of_order_duration();
432 }
433
434 std::string_view filename() const { return message_reader_->filename(); }
Austin Schuh6f3babe2020-01-26 20:34:50 -0800435
436 // Adds more messages to the sorted list. This reads enough data such that
437 // oldest_message_time can be replayed safely. Returns false if the log file
438 // has all been read.
439 bool QueueMessages(monotonic_clock::time_point oldest_message_time);
Austin Schuh05b70472020-01-01 17:11:17 -0800440
Austin Schuhcde938c2020-02-02 17:30:07 -0800441 // Returns debug strings for a channel, and timestamps for a node.
442 std::string DebugString(int channel) const;
443 std::string DebugString(int channel, int node_index) const;
444
Austin Schuh8bd96322020-02-13 21:18:22 -0800445 // Returns true if all the messages have been queued from the last log file in
446 // the list of log files chunks.
447 bool at_end() const { return at_end_; }
448
Austin Schuh05b70472020-01-01 17:11:17 -0800449 private:
Austin Schuh6f3babe2020-01-26 20:34:50 -0800450 // TODO(austin): Need to copy or refcount the message instead of running
451 // multiple copies of the reader. Or maybe have a "as_node" index and hide it
452 // inside.
453
Austin Schuhfa895892020-01-07 20:07:41 -0800454 // Moves to the next log file in the list.
455 bool NextLogFile();
456
Austin Schuh6f3babe2020-01-26 20:34:50 -0800457 // Filenames of the log files.
458 std::vector<std::string> filenames_;
459 // And the index of the next file to open.
460 size_t next_filename_index_ = 0;
Austin Schuh05b70472020-01-01 17:11:17 -0800461
Austin Schuhee711052020-08-24 16:06:09 -0700462 // Node we are reading as.
463 const Node *target_node_ = nullptr;
464
Austin Schuh6f3babe2020-01-26 20:34:50 -0800465 // Log file header to report. This is a copy.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800466 SizePrefixedFlatbufferVector<LogFileHeader> log_file_header_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800467 // Current log file being read.
468 std::unique_ptr<MessageReader> message_reader_;
Austin Schuh05b70472020-01-01 17:11:17 -0800469
470 // Datastructure to hold the list of messages, cached timestamp for the
471 // oldest message, and sender to send with.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800472 struct MessageHeaderQueue {
473 // If true, this is a timestamp queue.
474 bool timestamps = false;
Austin Schuh05b70472020-01-01 17:11:17 -0800475
Austin Schuh6f3babe2020-01-26 20:34:50 -0800476 // Returns a reference to the the oldest message.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800477 SizePrefixedFlatbufferVector<MessageHeader> &front() {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800478 CHECK_GT(data_.size(), 0u);
479 return data_.front();
Austin Schuh05b70472020-01-01 17:11:17 -0800480 }
Austin Schuh6f3babe2020-01-26 20:34:50 -0800481
Austin Schuhcde938c2020-02-02 17:30:07 -0800482 // Adds a message to the back of the queue. Returns true if it was actually
483 // emplaced.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800484 bool emplace_back(SizePrefixedFlatbufferVector<MessageHeader> &&msg);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800485
486 // Drops the front message. Invalidates the front() reference.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700487 void PopFront();
Austin Schuh6f3babe2020-01-26 20:34:50 -0800488
489 // The size of the queue.
490 size_t size() { return data_.size(); }
491
Austin Schuhcde938c2020-02-02 17:30:07 -0800492 // Returns a debug string with info about each message in the queue.
493 std::string DebugString() const;
494
Austin Schuh2f8fd752020-09-01 22:38:28 -0700495 // Returns the (timestamp, queue_index, message_header) for the oldest
496 // message.
Austin Schuhcde938c2020-02-02 17:30:07 -0800497 const std::tuple<monotonic_clock::time_point, uint32_t,
498 const MessageHeader *>
499 front_timestamp() {
Austin Schuh2f8fd752020-09-01 22:38:28 -0700500 const MessageHeader &message = front().message();
Austin Schuh6f3babe2020-01-26 20:34:50 -0800501 return std::make_tuple(
Austin Schuh2f8fd752020-09-01 22:38:28 -0700502 monotonic_clock::time_point(
503 std::chrono::nanoseconds(message.monotonic_sent_time())),
504 message.queue_index(), &message);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800505 }
506
507 // Pointer to the timestamp merger for this queue if available.
508 TimestampMerger *timestamp_merger = nullptr;
509 // Pointer to the reader which feeds this queue.
510 SplitMessageReader *split_reader = nullptr;
511
512 private:
513 // The data.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800514 std::deque<SizePrefixedFlatbufferVector<MessageHeader>> data_;
Austin Schuh05b70472020-01-01 17:11:17 -0800515 };
516
Austin Schuh6f3babe2020-01-26 20:34:50 -0800517 // All the queues needed for a channel. There isn't going to be data in all
518 // of these.
519 struct ChannelData {
520 // The data queue for the channel.
521 MessageHeaderQueue data;
522 // Queues for timestamps for each node.
523 std::vector<MessageHeaderQueue> timestamps;
524 };
Austin Schuhfa895892020-01-07 20:07:41 -0800525
Austin Schuh6f3babe2020-01-26 20:34:50 -0800526 // Data for all the channels.
Austin Schuh05b70472020-01-01 17:11:17 -0800527 std::vector<ChannelData> channels_;
528
Austin Schuh6f3babe2020-01-26 20:34:50 -0800529 // Once we know the node that this SplitMessageReader will be writing as,
530 // there will be only one MessageHeaderQueue that a specific channel matches.
531 // Precompute this here for efficiency.
532 std::vector<MessageHeaderQueue *> channels_to_write_;
533
Austin Schuhcde938c2020-02-02 17:30:07 -0800534 monotonic_clock::time_point time_to_queue_ = monotonic_clock::min_time;
535
536 // Latches true when we hit the end of the last log file and there is no sense
537 // poking it further.
538 bool at_end_ = false;
539
540 // Timestamp of the newest message that was read and actually queued. We want
541 // to track this independently from the log file because we need the
542 // timestamps here to be timestamps of messages that are queued.
543 monotonic_clock::time_point newest_timestamp_ = monotonic_clock::min_time;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800544};
545
546class ChannelMerger;
547
548// Sorts channels (and timestamps) from multiple log files for a single channel.
549class TimestampMerger {
550 public:
551 TimestampMerger(const Configuration *configuration,
552 std::vector<SplitMessageReader *> split_message_readers,
553 int channel_index, const Node *target_node,
554 ChannelMerger *channel_merger);
555
556 // Metadata used to schedule the message.
557 struct DeliveryTimestamp {
558 monotonic_clock::time_point monotonic_event_time =
559 monotonic_clock::min_time;
560 realtime_clock::time_point realtime_event_time = realtime_clock::min_time;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700561 uint32_t queue_index = 0xffffffff;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800562
563 monotonic_clock::time_point monotonic_remote_time =
564 monotonic_clock::min_time;
565 realtime_clock::time_point realtime_remote_time = realtime_clock::min_time;
566 uint32_t remote_queue_index = 0xffffffff;
567 };
568
569 // Pushes SplitMessageReader onto the timestamp heap. This should only be
570 // called when timestamps are placed in the channel this class is merging for
571 // the reader.
572 void UpdateTimestamp(
573 SplitMessageReader *split_message_reader,
Austin Schuhcde938c2020-02-02 17:30:07 -0800574 std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *>
575 oldest_message_time) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800576 PushTimestampHeap(oldest_message_time, split_message_reader);
577 }
578 // Pushes SplitMessageReader onto the message heap. This should only be
579 // called when data is placed in the channel this class is merging for the
580 // reader.
581 void Update(
582 SplitMessageReader *split_message_reader,
Austin Schuhcde938c2020-02-02 17:30:07 -0800583 std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *>
584 oldest_message_time) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800585 PushMessageHeap(oldest_message_time, split_message_reader);
586 }
587
Austin Schuhcde938c2020-02-02 17:30:07 -0800588 // Returns the oldest combined timestamp and data for this channel. If there
589 // isn't a matching piece of data, returns only the timestamp with no data.
590 // The caller can determine what the appropriate action is to recover.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800591 std::tuple<DeliveryTimestamp, SizePrefixedFlatbufferVector<MessageHeader>>
592 PopOldest();
Austin Schuh6f3babe2020-01-26 20:34:50 -0800593
594 // Tracks if the channel merger has pushed this onto it's heap or not.
595 bool pushed() { return pushed_; }
596 // Sets if this has been pushed to the channel merger heap. Should only be
597 // called by the channel merger.
598 void set_pushed(bool pushed) { pushed_ = pushed; }
599
Austin Schuhcde938c2020-02-02 17:30:07 -0800600 // Returns a debug string with the heaps printed out.
601 std::string DebugString() const;
602
Austin Schuh8bd96322020-02-13 21:18:22 -0800603 // Returns true if we have timestamps.
604 bool has_timestamps() const { return has_timestamps_; }
605
606 // Records that one of the log files ran out of data. This should only be
607 // called by a SplitMessageReader.
608 void NoticeAtEnd();
609
Austin Schuh2f8fd752020-09-01 22:38:28 -0700610 aos::monotonic_clock::time_point channel_merger_time() {
611 if (has_timestamps_) {
612 return std::get<0>(timestamp_heap_[0]);
613 } else {
614 return std::get<0>(message_heap_[0]);
615 }
616 }
617
Austin Schuh6f3babe2020-01-26 20:34:50 -0800618 private:
619 // Pushes messages and timestamps to the corresponding heaps.
620 void PushMessageHeap(
Austin Schuhcde938c2020-02-02 17:30:07 -0800621 std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *>
622 timestamp,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800623 SplitMessageReader *split_message_reader);
624 void PushTimestampHeap(
Austin Schuhcde938c2020-02-02 17:30:07 -0800625 std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *>
626 timestamp,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800627 SplitMessageReader *split_message_reader);
628
629 // Pops a message from the message heap. This automatically triggers the
630 // split message reader to re-fetch any new data.
631 std::tuple<monotonic_clock::time_point, uint32_t,
Austin Schuhadd6eb32020-11-09 21:24:26 -0800632 SizePrefixedFlatbufferVector<MessageHeader>>
Austin Schuh6f3babe2020-01-26 20:34:50 -0800633 PopMessageHeap();
Austin Schuhcde938c2020-02-02 17:30:07 -0800634
635 std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *>
636 oldest_message() const;
637 std::tuple<monotonic_clock::time_point, uint32_t, const MessageHeader *>
638 oldest_timestamp() const;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800639 // Pops a message from the timestamp heap. This automatically triggers the
640 // split message reader to re-fetch any new data.
641 std::tuple<monotonic_clock::time_point, uint32_t,
Austin Schuhadd6eb32020-11-09 21:24:26 -0800642 SizePrefixedFlatbufferVector<MessageHeader>>
Austin Schuh6f3babe2020-01-26 20:34:50 -0800643 PopTimestampHeap();
644
645 const Configuration *configuration_;
646
647 // If true, this is a forwarded channel and timestamps should be matched.
648 bool has_timestamps_ = false;
649
650 // Tracks if the ChannelMerger has pushed this onto it's queue.
651 bool pushed_ = false;
652
653 // The split message readers used for source data.
654 std::vector<SplitMessageReader *> split_message_readers_;
655
656 // The channel to merge.
657 int channel_index_;
658
659 // Our node.
660 int node_index_;
661
662 // Heaps for messages and timestamps.
663 std::vector<
664 std::tuple<monotonic_clock::time_point, uint32_t, SplitMessageReader *>>
665 message_heap_;
666 std::vector<
667 std::tuple<monotonic_clock::time_point, uint32_t, SplitMessageReader *>>
668 timestamp_heap_;
669
670 // Parent channel merger.
671 ChannelMerger *channel_merger_;
672};
673
674// This class handles constructing all the split message readers, channel
675// mergers, and combining the results.
676class ChannelMerger {
677 public:
678 // Builds a ChannelMerger around a set of log files. These are of the format:
679 // {
680 // {log1_part0, log1_part1, ...},
681 // {log2}
682 // }
683 // The inner vector is a list of log file chunks which form up a log file.
684 // The outer vector is a list of log files with subsets of the messages, or
685 // messages from different nodes.
686 ChannelMerger(const std::vector<std::vector<std::string>> &filenames);
687
688 // Returns the nodes that we know how to merge.
689 const std::vector<const Node *> nodes() const;
690 // Sets the node that we will return messages as. Returns true if the node
691 // has log files and will produce data. This can only be called once, and
692 // will likely corrupt state if called a second time.
693 bool SetNode(const Node *target_node);
694
695 // Everything else needs the node set before it works.
696
697 // Returns a timestamp for the oldest message in this group of logfiles.
Austin Schuh858c9f32020-08-31 16:56:12 -0700698 monotonic_clock::time_point OldestMessageTime() const;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800699 // Pops the oldest message.
700 std::tuple<TimestampMerger::DeliveryTimestamp, int,
Austin Schuhadd6eb32020-11-09 21:24:26 -0800701 SizePrefixedFlatbufferVector<MessageHeader>>
Austin Schuh6f3babe2020-01-26 20:34:50 -0800702 PopOldest();
703
704 // Returns the config for this set of log files.
705 const Configuration *configuration() const {
706 return log_file_header()->configuration();
707 }
708
709 const LogFileHeader *log_file_header() const {
710 return &log_file_header_.message();
711 }
712
713 // Returns the start times for the configured node's log files.
Austin Schuhcde938c2020-02-02 17:30:07 -0800714 monotonic_clock::time_point monotonic_start_time() const {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800715 return monotonic_clock::time_point(
716 std::chrono::nanoseconds(log_file_header()->monotonic_start_time()));
717 }
Austin Schuhcde938c2020-02-02 17:30:07 -0800718 realtime_clock::time_point realtime_start_time() const {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800719 return realtime_clock::time_point(
720 std::chrono::nanoseconds(log_file_header()->realtime_start_time()));
721 }
722
723 // Returns the node set by SetNode above.
724 const Node *node() const { return node_; }
725
726 // Called by the TimestampMerger when new data is available with the provided
727 // timestamp and channel_index.
728 void Update(monotonic_clock::time_point timestamp, int channel_index) {
729 PushChannelHeap(timestamp, channel_index);
730 }
731
Austin Schuhcde938c2020-02-02 17:30:07 -0800732 // Returns a debug string with all the heaps in it. Generally only useful for
733 // debugging what went wrong.
734 std::string DebugString() const;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800735
Austin Schuh8bd96322020-02-13 21:18:22 -0800736 // Returns true if one of the log files has finished reading everything. When
737 // log file chunks are involved, this means that the last chunk in a log file
738 // has been read. It is acceptable to be missing data at this point in time.
739 bool at_end() const { return at_end_; }
740
741 // Marks that one of the log files is at the end. This should only be called
742 // by timestamp mergers.
743 void NoticeAtEnd() { at_end_ = true; }
744
Austin Schuhcde938c2020-02-02 17:30:07 -0800745 private:
Austin Schuh6f3babe2020-01-26 20:34:50 -0800746 // Pushes the timestamp for new data on the provided channel.
747 void PushChannelHeap(monotonic_clock::time_point timestamp,
748 int channel_index);
749
Austin Schuh2f8fd752020-09-01 22:38:28 -0700750 // CHECKs that channel_heap_ and timestamp_heap_ are valid heaps.
751 void VerifyHeaps();
752
Austin Schuh6f3babe2020-01-26 20:34:50 -0800753 // All the message readers.
754 std::vector<std::unique_ptr<SplitMessageReader>> split_message_readers_;
755
756 // The log header we are claiming to be.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800757 SizePrefixedFlatbufferVector<LogFileHeader> log_file_header_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800758
759 // The timestamp mergers which combine data from the split message readers.
760 std::vector<TimestampMerger> timestamp_mergers_;
761
762 // A heap of the channel readers and timestamps for the oldest data in each.
Austin Schuh05b70472020-01-01 17:11:17 -0800763 std::vector<std::pair<monotonic_clock::time_point, int>> channel_heap_;
764
Austin Schuh6f3babe2020-01-26 20:34:50 -0800765 // Configured node.
766 const Node *node_;
767
Austin Schuh8bd96322020-02-13 21:18:22 -0800768 bool at_end_ = false;
769
Austin Schuh6f3babe2020-01-26 20:34:50 -0800770 // Cached copy of the list of nodes.
771 std::vector<const Node *> nodes_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700772
773 // Last time popped. Used to detect events being returned out of order.
774 monotonic_clock::time_point last_popped_time_ = monotonic_clock::min_time;
Austin Schuh05b70472020-01-01 17:11:17 -0800775};
Austin Schuha36c8902019-12-30 18:07:15 -0800776
Austin Schuhee711052020-08-24 16:06:09 -0700777// Returns the node name with a trailing space, or an empty string if we are on
778// a single node.
779std::string MaybeNodeName(const Node *);
780
Brian Silvermanf51499a2020-09-21 12:49:08 -0700781} // namespace aos::logger
Austin Schuha36c8902019-12-30 18:07:15 -0800782
783#endif // AOS_EVENTS_LOGGING_LOGFILE_UTILS_H_