blob: c4ce7694460306c38b38e203db2dca6da10a2ed5 [file] [log] [blame]
Austin Schuhe309d2a2019-11-29 13:25:21 -08001#ifndef AOS_EVENTS_LOGGER_H_
2#define AOS_EVENTS_LOGGER_H_
3
Austin Schuh8bd96322020-02-13 21:18:22 -08004#include <chrono>
Austin Schuhe309d2a2019-11-29 13:25:21 -08005#include <deque>
Austin Schuh05b70472020-01-01 17:11:17 -08006#include <string_view>
Austin Schuh2f8fd752020-09-01 22:38:28 -07007#include <tuple>
Austin Schuh6f3babe2020-01-26 20:34:50 -08008#include <vector>
Austin Schuhe309d2a2019-11-29 13:25:21 -08009
Austin Schuh8bd96322020-02-13 21:18:22 -080010#include "Eigen/Dense"
11#include "absl/strings/str_cat.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080012#include "absl/types/span.h"
13#include "aos/events/event_loop.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070014#include "aos/events/logging/eigen_mpq.h"
Austin Schuha36c8902019-12-30 18:07:15 -080015#include "aos/events/logging/logfile_utils.h"
James Kuszmaul38735e82019-12-07 16:42:06 -080016#include "aos/events/logging/logger_generated.h"
Austin Schuh64fab802020-09-09 22:47:47 -070017#include "aos/events/logging/uuid.h"
Austin Schuh92547522019-12-28 14:33:43 -080018#include "aos/events/simulated_event_loop.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070019#include "aos/network/message_bridge_server_generated.h"
Austin Schuh8bd96322020-02-13 21:18:22 -080020#include "aos/network/timestamp_filter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080021#include "aos/time/time.h"
22#include "flatbuffers/flatbuffers.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070023#include "third_party/gmp/gmpxx.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080024
25namespace aos {
26namespace logger {
27
Austin Schuh6f3babe2020-01-26 20:34:50 -080028class LogNamer {
29 public:
30 LogNamer(const Node *node) : node_(node) { nodes_.emplace_back(node_); }
31 virtual ~LogNamer() {}
32
Austin Schuh2f8fd752020-09-01 22:38:28 -070033 virtual void WriteHeader(
Austin Schuh64fab802020-09-09 22:47:47 -070034 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header,
Austin Schuh2f8fd752020-09-01 22:38:28 -070035 const Node *node) = 0;
Austin Schuh6f3babe2020-01-26 20:34:50 -080036 virtual DetachedBufferWriter *MakeWriter(const Channel *channel) = 0;
37
38 virtual DetachedBufferWriter *MakeTimestampWriter(const Channel *channel) = 0;
Austin Schuh2f8fd752020-09-01 22:38:28 -070039 virtual DetachedBufferWriter *MakeForwardedTimestampWriter(
40 const Channel *channel, const Node *node) = 0;
41 virtual void Rotate(
42 const Node *node,
Austin Schuh64fab802020-09-09 22:47:47 -070043 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header) = 0;
Austin Schuh6f3babe2020-01-26 20:34:50 -080044 const std::vector<const Node *> &nodes() const { return nodes_; }
45
46 const Node *node() const { return node_; }
47
48 protected:
Austin Schuh64fab802020-09-09 22:47:47 -070049 void UpdateHeader(
50 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header,
51 const UUID &uuid, int part_id);
52
Austin Schuh6f3babe2020-01-26 20:34:50 -080053 const Node *const node_;
54 std::vector<const Node *> nodes_;
55};
56
57class LocalLogNamer : public LogNamer {
58 public:
Austin Schuh2f8fd752020-09-01 22:38:28 -070059 LocalLogNamer(std::string_view base_name, const Node *node)
Austin Schuh64fab802020-09-09 22:47:47 -070060 : LogNamer(node),
61 base_name_(base_name),
62 uuid_(UUID::Random()),
63 data_writer_(OpenDataWriter()) {}
Austin Schuh6f3babe2020-01-26 20:34:50 -080064
Austin Schuh2f8fd752020-09-01 22:38:28 -070065 void WriteHeader(
Austin Schuh64fab802020-09-09 22:47:47 -070066 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header,
Austin Schuh2f8fd752020-09-01 22:38:28 -070067 const Node *node) override {
Austin Schuh6f3babe2020-01-26 20:34:50 -080068 CHECK_EQ(node, this->node());
Austin Schuh64fab802020-09-09 22:47:47 -070069 UpdateHeader(header, uuid_, part_number_);
70 data_writer_->WriteSizedFlatbuffer(header->full_span());
Austin Schuh6f3babe2020-01-26 20:34:50 -080071 }
72
73 DetachedBufferWriter *MakeWriter(const Channel *channel) override {
74 CHECK(configuration::ChannelIsSendableOnNode(channel, node()));
Austin Schuh2f8fd752020-09-01 22:38:28 -070075 return data_writer_.get();
76 }
77
78 void Rotate(const Node *node,
Austin Schuh64fab802020-09-09 22:47:47 -070079 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header)
80 override {
Austin Schuh2f8fd752020-09-01 22:38:28 -070081 CHECK(node == this->node());
82 ++part_number_;
83 *data_writer_ = std::move(*OpenDataWriter());
Austin Schuh64fab802020-09-09 22:47:47 -070084 UpdateHeader(header, uuid_, part_number_);
85 data_writer_->WriteSizedFlatbuffer(header->full_span());
Austin Schuh6f3babe2020-01-26 20:34:50 -080086 }
87
88 DetachedBufferWriter *MakeTimestampWriter(const Channel *channel) override {
89 CHECK(configuration::ChannelIsReadableOnNode(channel, node_))
90 << ": Message is not delivered to this node.";
91 CHECK(node_ != nullptr) << ": Can't log timestamps in a single node world";
92 CHECK(configuration::ConnectionDeliveryTimeIsLoggedOnNode(channel, node_,
93 node_))
94 << ": Delivery times aren't logged for this channel on this node.";
Austin Schuh2f8fd752020-09-01 22:38:28 -070095 return data_writer_.get();
96 }
97
98 DetachedBufferWriter *MakeForwardedTimestampWriter(
99 const Channel * /*channel*/, const Node * /*node*/) override {
100 LOG(FATAL) << "Can't log forwarded timestamps in a singe log file.";
101 return nullptr;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800102 }
103
104 private:
Austin Schuh2f8fd752020-09-01 22:38:28 -0700105 std::unique_ptr<DetachedBufferWriter> OpenDataWriter() {
106 return std::make_unique<DetachedBufferWriter>(
107 absl::StrCat(base_name_, ".part", part_number_, ".bfbs"));
108 }
109 const std::string base_name_;
Austin Schuh64fab802020-09-09 22:47:47 -0700110 const UUID uuid_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700111 size_t part_number_ = 0;
112 std::unique_ptr<DetachedBufferWriter> data_writer_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800113};
114
115// TODO(austin): Split naming files from making files so we can re-use the
116// naming code to predict the log file names for a provided base name.
117class MultiNodeLogNamer : public LogNamer {
118 public:
119 MultiNodeLogNamer(std::string_view base_name,
120 const Configuration *configuration, const Node *node)
121 : LogNamer(node),
122 base_name_(base_name),
123 configuration_(configuration),
Austin Schuh64fab802020-09-09 22:47:47 -0700124 uuid_(UUID::Random()),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700125 data_writer_(OpenDataWriter()) {}
Austin Schuh6f3babe2020-01-26 20:34:50 -0800126
127 // Writes the header to all log files for a specific node. This function
128 // needs to be called after all the writers are created.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700129 void WriteHeader(
Austin Schuh64fab802020-09-09 22:47:47 -0700130 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header,
Austin Schuh2f8fd752020-09-01 22:38:28 -0700131 const Node *node) override;
132
133 void Rotate(const Node *node,
Austin Schuh64fab802020-09-09 22:47:47 -0700134 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header)
135 override;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800136
137 // Makes a data logger for a specific channel.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700138 DetachedBufferWriter *MakeWriter(const Channel *channel) override {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800139 // See if we can read the data on this node at all.
140 const bool is_readable =
141 configuration::ChannelIsReadableOnNode(channel, this->node());
142 if (!is_readable) {
143 return nullptr;
144 }
145
146 // Then, see if we are supposed to log the data here.
147 const bool log_message =
148 configuration::ChannelMessageIsLoggedOnNode(channel, this->node());
149
150 if (!log_message) {
151 return nullptr;
152 }
153
154 // Now, sort out if this is data generated on this node, or not. It is
155 // generated if it is sendable on this node.
156 if (configuration::ChannelIsSendableOnNode(channel, this->node())) {
157 return data_writer_.get();
Austin Schuh6f3babe2020-01-26 20:34:50 -0800158 }
Austin Schuh2f8fd752020-09-01 22:38:28 -0700159
160 // Ok, we have data that is being forwarded to us that we are supposed to
161 // log. It needs to be logged with send timestamps, but be sorted enough
162 // to be able to be processed.
163 CHECK(data_writers_.find(channel) == data_writers_.end());
164
165 // Track that this node is being logged.
166 const Node *source_node = configuration::GetNode(
167 configuration_, channel->source_node()->string_view());
168
169 if (std::find(nodes_.begin(), nodes_.end(), source_node) == nodes_.end()) {
170 nodes_.emplace_back(source_node);
171 }
172
173 DataWriter data_writer;
174 data_writer.node = source_node;
175 data_writer.rotate = [this](const Channel *channel,
176 DataWriter *data_writer) {
177 OpenWriter(channel, data_writer);
178 };
179 data_writer.rotate(channel, &data_writer);
180
181 return data_writers_.insert(std::make_pair(channel, std::move(data_writer)))
182 .first->second.writer.get();
183 }
184
185 DetachedBufferWriter *MakeForwardedTimestampWriter(
186 const Channel *channel, const Node *node) override {
187 // See if we can read the data on this node at all.
188 const bool is_readable =
189 configuration::ChannelIsReadableOnNode(channel, this->node());
190 CHECK(is_readable) << ": "
191 << configuration::CleanedChannelToString(channel);
192
193 CHECK(data_writers_.find(channel) == data_writers_.end());
194
195 if (std::find(nodes_.begin(), nodes_.end(), node) == nodes_.end()) {
196 nodes_.emplace_back(node);
197 }
198
199 DataWriter data_writer;
200 data_writer.node = node;
201 data_writer.rotate = [this](const Channel *channel,
202 DataWriter *data_writer) {
203 OpenForwardedTimestampWriter(channel, data_writer);
204 };
205 data_writer.rotate(channel, &data_writer);
206
207 return data_writers_.insert(std::make_pair(channel, std::move(data_writer)))
208 .first->second.writer.get();
Austin Schuh6f3babe2020-01-26 20:34:50 -0800209 }
210
211 // Makes a timestamp (or timestamp and data) logger for a channel and
212 // forwarding connection.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700213 DetachedBufferWriter *MakeTimestampWriter(const Channel *channel) override {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800214 const bool log_delivery_times =
215 (this->node() == nullptr)
216 ? false
217 : configuration::ConnectionDeliveryTimeIsLoggedOnNode(
218 channel, this->node(), this->node());
219 if (!log_delivery_times) {
220 return nullptr;
221 }
222
223 return data_writer_.get();
224 }
225
226 const std::vector<const Node *> &nodes() const { return nodes_; }
227
228 private:
Austin Schuh2f8fd752020-09-01 22:38:28 -0700229 // Files to write remote data to. We want one per channel. Maps the channel
230 // to the writer, Node, and part number.
231 struct DataWriter {
232 std::unique_ptr<DetachedBufferWriter> writer = nullptr;
233 const Node *node;
234 size_t part_number = 0;
Austin Schuh64fab802020-09-09 22:47:47 -0700235 UUID uuid = UUID::Random();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700236 std::function<void(const Channel *, DataWriter *)> rotate;
237 };
238
239 void OpenForwardedTimestampWriter(const Channel *channel,
240 DataWriter *data_writer) {
241 std::string filename =
242 absl::StrCat(base_name_, "_timestamps", channel->name()->string_view(),
243 "/", channel->type()->string_view(), ".part",
244 data_writer->part_number, ".bfbs");
245
246 if (!data_writer->writer) {
247 data_writer->writer = std::make_unique<DetachedBufferWriter>(filename);
248 } else {
249 *data_writer->writer = DetachedBufferWriter(filename);
250 }
251 }
252
253 void OpenWriter(const Channel *channel, DataWriter *data_writer) {
254 const std::string filename = absl::StrCat(
255 base_name_, "_", channel->source_node()->string_view(), "_data",
256 channel->name()->string_view(), "/", channel->type()->string_view(),
257 ".part", data_writer->part_number, ".bfbs");
258 if (!data_writer->writer) {
259 data_writer->writer = std::make_unique<DetachedBufferWriter>(filename);
260 } else {
261 *data_writer->writer = DetachedBufferWriter(filename);
262 }
263 }
264
265 std::unique_ptr<DetachedBufferWriter> OpenDataWriter() {
266 return std::make_unique<DetachedBufferWriter>(
267 absl::StrCat(base_name_, "_", node()->name()->string_view(),
268 "_data.part", part_number_, ".bfbs"));
269 }
270
Austin Schuh6f3babe2020-01-26 20:34:50 -0800271 const std::string base_name_;
272 const Configuration *const configuration_;
Austin Schuh64fab802020-09-09 22:47:47 -0700273 const UUID uuid_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800274
Austin Schuh2f8fd752020-09-01 22:38:28 -0700275 size_t part_number_ = 0;
276
Austin Schuh6f3babe2020-01-26 20:34:50 -0800277 // File to write both delivery timestamps and local data to.
278 std::unique_ptr<DetachedBufferWriter> data_writer_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800279
Austin Schuh2f8fd752020-09-01 22:38:28 -0700280 std::map<const Channel *, DataWriter> data_writers_;
281};
Austin Schuh8bd96322020-02-13 21:18:22 -0800282
Austin Schuhe309d2a2019-11-29 13:25:21 -0800283// Logs all channels available in the event loop to disk every 100 ms.
284// Start by logging one message per channel to capture any state and
285// configuration that is sent rately on a channel and would affect execution.
286class Logger {
287 public:
Austin Schuh2f8fd752020-09-01 22:38:28 -0700288 Logger(std::string_view base_name, EventLoop *event_loop,
Austin Schuhe309d2a2019-11-29 13:25:21 -0800289 std::chrono::milliseconds polling_period =
290 std::chrono::milliseconds(100));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800291 Logger(std::unique_ptr<LogNamer> log_namer, EventLoop *event_loop,
292 std::chrono::milliseconds polling_period =
293 std::chrono::milliseconds(100));
Austin Schuhe309d2a2019-11-29 13:25:21 -0800294
Austin Schuh2f8fd752020-09-01 22:38:28 -0700295 // Rotates the log file(s), triggering new part files to be written for each
296 // log file.
297 void Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800298
Austin Schuhe309d2a2019-11-29 13:25:21 -0800299 private:
Austin Schuhfa895892020-01-07 20:07:41 -0800300 void WriteHeader();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700301 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> MakeHeader(
302 const Node *node);
303
304 bool MaybeUpdateTimestamp(
305 const Node *node, int node_index,
306 aos::monotonic_clock::time_point monotonic_start_time,
307 aos::realtime_clock::time_point realtime_start_time);
Austin Schuhfa895892020-01-07 20:07:41 -0800308
Austin Schuhe309d2a2019-11-29 13:25:21 -0800309 void DoLogData();
310
Austin Schuh2f8fd752020-09-01 22:38:28 -0700311 void WriteMissingTimestamps();
312
313 void StartLogging();
314
315 // Fetches from each channel until all the data is logged.
316 void LogUntil(monotonic_clock::time_point t);
317
Austin Schuhe309d2a2019-11-29 13:25:21 -0800318 EventLoop *event_loop_;
Austin Schuh64fab802020-09-09 22:47:47 -0700319 const UUID uuid_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800320 std::unique_ptr<LogNamer> log_namer_;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800321
322 // Structure to track both a fetcher, and if the data fetched has been
323 // written. We may want to delay writing data to disk so that we don't let
324 // data get too far out of order when written to disk so we can avoid making
325 // it too hard to sort when reading.
326 struct FetcherStruct {
327 std::unique_ptr<RawFetcher> fetcher;
328 bool written = false;
Austin Schuh15649d62019-12-28 16:36:38 -0800329
Austin Schuh6f3babe2020-01-26 20:34:50 -0800330 int channel_index = -1;
331
332 LogType log_type = LogType::kLogMessage;
333
334 DetachedBufferWriter *writer = nullptr;
335 DetachedBufferWriter *timestamp_writer = nullptr;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700336 DetachedBufferWriter *contents_writer = nullptr;
337 const Node *writer_node = nullptr;
338 const Node *timestamp_node = nullptr;
339 int node_index = 0;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800340 };
341
342 std::vector<FetcherStruct> fetchers_;
343 TimerHandler *timer_handler_;
344
345 // Period to poll the channels.
346 const std::chrono::milliseconds polling_period_;
347
348 // Last time that data was written for all channels to disk.
349 monotonic_clock::time_point last_synchronized_time_;
350
Austin Schuhfa895892020-01-07 20:07:41 -0800351 monotonic_clock::time_point monotonic_start_time_;
352 realtime_clock::time_point realtime_start_time_;
353
Austin Schuhe309d2a2019-11-29 13:25:21 -0800354 // Max size that the header has consumed. This much extra data will be
355 // reserved in the builder to avoid reallocating.
356 size_t max_header_size_ = 0;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700357
358 // Fetcher for all the statistics from all the nodes.
359 aos::Fetcher<message_bridge::ServerStatistics> server_statistics_fetcher_;
360
361 // Sets the start time for a specific node.
362 void SetStartTime(size_t node_index,
363 aos::monotonic_clock::time_point monotonic_start_time,
364 aos::realtime_clock::time_point realtime_start_time);
365
366 struct NodeState {
367 aos::monotonic_clock::time_point monotonic_start_time =
368 aos::monotonic_clock::min_time;
369 aos::realtime_clock::time_point realtime_start_time =
370 aos::realtime_clock::min_time;
371
372 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> log_file_header =
373 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader>::Empty();
374 };
375 std::vector<NodeState> node_state_;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800376};
377
Austin Schuh5212cad2020-09-09 23:12:09 -0700378// Takes a bunch of parts and sorts them based on part_uuid and part_index.
379std::vector<std::vector<std::string>> SortParts(
380 const std::vector<std::string> &parts);
381
Austin Schuh6f3babe2020-01-26 20:34:50 -0800382// We end up with one of the following 3 log file types.
383//
384// Single node logged as the source node.
385// -> Replayed just on the source node.
386//
387// Forwarding timestamps only logged from the perspective of the destination
388// node.
389// -> Matched with data on source node and logged.
390//
391// Forwarding timestamps with data logged as the destination node.
392// -> Replayed just as the destination
393// -> Replayed as the source (Much harder, ordering is not defined)
394//
395// Duplicate data logged. -> CHECK that it matches and explode otherwise.
396//
397// This can be boiled down to a set of constraints and tools.
398//
399// 1) Forwarding timestamps and data need to be logged separately.
400// 2) Any forwarded data logged on the destination node needs to be logged
401// separately such that it can be sorted.
402//
403// 1) Log reader needs to be able to sort a list of log files.
404// 2) Log reader needs to be able to merge sorted lists of log files.
405// 3) Log reader needs to be able to match timestamps with messages.
406//
407// We also need to be able to generate multiple views of a log file depending on
408// the target.
409
Austin Schuhe309d2a2019-11-29 13:25:21 -0800410// Replays all the channels in the logfile to the event loop.
411class LogReader {
412 public:
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800413 // If you want to supply a new configuration that will be used for replay
414 // (e.g., to change message rates, or to populate an updated schema), then
415 // pass it in here. It must provide all the channels that the original logged
416 // config did.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800417 //
418 // Log filenames are in the following format:
419 //
420 // {
421 // {log1_part0, log1_part1, ...},
422 // {log2}
423 // }
424 // The inner vector is a list of log file chunks which form up a log file.
425 // The outer vector is a list of log files with subsets of the messages, or
426 // messages from different nodes.
427 //
428 // If the outer vector isn't provided, it is assumed to be of size 1.
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800429 LogReader(std::string_view filename,
430 const Configuration *replay_configuration = nullptr);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800431 LogReader(const std::vector<std::string> &filenames,
432 const Configuration *replay_configuration = nullptr);
433 LogReader(const std::vector<std::vector<std::string>> &filenames,
Austin Schuhfa895892020-01-07 20:07:41 -0800434 const Configuration *replay_configuration = nullptr);
James Kuszmaul7daef362019-12-31 18:28:17 -0800435 ~LogReader();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800436
Austin Schuh6331ef92020-01-07 18:28:09 -0800437 // Registers all the callbacks to send the log file data out on an event loop
438 // created in event_loop_factory. This also updates time to be at the start
439 // of the log file by running until the log file starts.
440 // Note: the configuration used in the factory should be configuration()
441 // below, but can be anything as long as the locations needed to send
442 // everything are available.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800443 void Register(SimulatedEventLoopFactory *event_loop_factory);
Austin Schuh6331ef92020-01-07 18:28:09 -0800444 // Creates an SimulatedEventLoopFactory accessible via event_loop_factory(),
445 // and then calls Register.
446 void Register();
447 // Registers callbacks for all the events after the log file starts. This is
448 // only useful when replaying live.
Austin Schuhe309d2a2019-11-29 13:25:21 -0800449 void Register(EventLoop *event_loop);
Austin Schuh6331ef92020-01-07 18:28:09 -0800450
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800451 // Unregisters the senders. You only need to call this if you separately
452 // supplied an event loop or event loop factory and the lifetimes are such
453 // that they need to be explicitly destroyed before the LogReader destructor
454 // gets called.
Austin Schuhe309d2a2019-11-29 13:25:21 -0800455 void Deregister();
456
Austin Schuhe309d2a2019-11-29 13:25:21 -0800457 // Returns the configuration from the log file.
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800458 const Configuration *logged_configuration() const;
459 // Returns the configuration being used for replay.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800460 // The pointer is invalidated whenever RemapLoggedChannel is called.
Austin Schuh15649d62019-12-28 16:36:38 -0800461 const Configuration *configuration() const;
462
Austin Schuh6f3babe2020-01-26 20:34:50 -0800463 // Returns the nodes that this log file was created on. This is a list of
464 // pointers to a node in the nodes() list inside configuration(). The
465 // pointers here are invalidated whenever RemapLoggedChannel is called.
466 std::vector<const Node *> Nodes() const;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800467
468 // Returns the starting timestamp for the log file.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800469 monotonic_clock::time_point monotonic_start_time(const Node *node = nullptr);
470 realtime_clock::time_point realtime_start_time(const Node *node = nullptr);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800471
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800472 // Causes the logger to publish the provided channel on a different name so
473 // that replayed applications can publish on the proper channel name without
474 // interference. This operates on raw channel names, without any node or
475 // application specific mappings.
476 void RemapLoggedChannel(std::string_view name, std::string_view type,
477 std::string_view add_prefix = "/original");
478 template <typename T>
479 void RemapLoggedChannel(std::string_view name,
480 std::string_view add_prefix = "/original") {
481 RemapLoggedChannel(name, T::GetFullyQualifiedName(), add_prefix);
482 }
483
Brian Silvermande9f3ff2020-04-28 16:56:58 -0700484 template <typename T>
485 bool HasChannel(std::string_view name) {
486 return configuration::GetChannel(log_file_header()->configuration(), name,
487 T::GetFullyQualifiedName(), "",
488 nullptr) != nullptr;
489 }
490
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800491 SimulatedEventLoopFactory *event_loop_factory() {
492 return event_loop_factory_;
493 }
494
Brian Silvermande9f3ff2020-04-28 16:56:58 -0700495 const LogFileHeader *log_file_header() const {
496 return &log_file_header_.message();
497 }
498
Austin Schuhe309d2a2019-11-29 13:25:21 -0800499 private:
Austin Schuh6f3babe2020-01-26 20:34:50 -0800500 const Channel *RemapChannel(const EventLoop *event_loop,
501 const Channel *channel);
502
Austin Schuhe309d2a2019-11-29 13:25:21 -0800503 // Queues at least max_out_of_order_duration_ messages into channels_.
504 void QueueMessages();
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800505 // Handle constructing a configuration with all the additional remapped
506 // channels from calls to RemapLoggedChannel.
507 void MakeRemappedConfig();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800508
Austin Schuh2f8fd752020-09-01 22:38:28 -0700509 // Returns the number of nodes.
510 size_t nodes_count() const {
511 return !configuration::MultiNode(logged_configuration())
512 ? 1u
513 : logged_configuration()->nodes()->size();
514 }
515
Austin Schuh6f3babe2020-01-26 20:34:50 -0800516 const std::vector<std::vector<std::string>> filenames_;
517
518 // This is *a* log file header used to provide the logged config. The rest of
519 // the header is likely distracting.
520 FlatbufferVector<LogFileHeader> log_file_header_;
521
Austin Schuh2f8fd752020-09-01 22:38:28 -0700522 // Returns [ta; tb; ...] = tuple[0] * t + tuple[1]
523 std::tuple<Eigen::Matrix<double, Eigen::Dynamic, 1>,
524 Eigen::Matrix<double, Eigen::Dynamic, 1>>
525 SolveOffsets();
526
527 void LogFit(std::string_view prefix);
Austin Schuh8bd96322020-02-13 21:18:22 -0800528
Austin Schuh6f3babe2020-01-26 20:34:50 -0800529 // State per node.
Austin Schuh858c9f32020-08-31 16:56:12 -0700530 class State {
531 public:
532 State(std::unique_ptr<ChannelMerger> channel_merger);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800533
Austin Schuh858c9f32020-08-31 16:56:12 -0700534 // Returns the timestamps, channel_index, and message from a channel.
535 // update_time (will be) set to true when popping this message causes the
536 // filter to change the time offset estimation function.
537 std::tuple<TimestampMerger::DeliveryTimestamp, int,
538 FlatbufferVector<MessageHeader>>
539 PopOldest(bool *update_time);
540
541 // Returns the monotonic time of the oldest message.
542 monotonic_clock::time_point OldestMessageTime() const;
543
544 // Primes the queues inside State. Should be called before calling
545 // OldestMessageTime.
546 void SeedSortedMessages();
Austin Schuh8bd96322020-02-13 21:18:22 -0800547
Austin Schuh858c9f32020-08-31 16:56:12 -0700548 // Returns the starting time for this node.
549 monotonic_clock::time_point monotonic_start_time() const {
550 return channel_merger_->monotonic_start_time();
551 }
552 realtime_clock::time_point realtime_start_time() const {
553 return channel_merger_->realtime_start_time();
554 }
555
556 // Sets the node event loop factory for replaying into a
557 // SimulatedEventLoopFactory. Returns the EventLoop to use.
558 EventLoop *SetNodeEventLoopFactory(
559 NodeEventLoopFactory *node_event_loop_factory);
560
561 // Sets and gets the event loop to use.
562 void set_event_loop(EventLoop *event_loop) { event_loop_ = event_loop; }
563 EventLoop *event_loop() { return event_loop_; }
564
Austin Schuh858c9f32020-08-31 16:56:12 -0700565 // Sets the current realtime offset from the monotonic clock for this node
566 // (if we are on a simulated event loop).
567 void SetRealtimeOffset(monotonic_clock::time_point monotonic_time,
568 realtime_clock::time_point realtime_time) {
569 if (node_event_loop_factory_ != nullptr) {
570 node_event_loop_factory_->SetRealtimeOffset(monotonic_time,
571 realtime_time);
572 }
573 }
574
575 // Converts a timestamp from the monotonic clock on this node to the
576 // distributed clock.
577 distributed_clock::time_point ToDistributedClock(
578 monotonic_clock::time_point time) {
579 return node_event_loop_factory_->ToDistributedClock(time);
580 }
581
Austin Schuh2f8fd752020-09-01 22:38:28 -0700582 monotonic_clock::time_point FromDistributedClock(
583 distributed_clock::time_point time) {
584 return node_event_loop_factory_->FromDistributedClock(time);
585 }
586
Austin Schuh858c9f32020-08-31 16:56:12 -0700587 // Sets the offset (and slope) from the distributed clock.
588 void SetDistributedOffset(std::chrono::nanoseconds distributed_offset,
589 double distributed_slope) {
590 node_event_loop_factory_->SetDistributedOffset(distributed_offset,
591 distributed_slope);
592 }
593
594 // Returns the current time on the remote node which sends messages on
595 // channel_index.
596 monotonic_clock::time_point monotonic_remote_now(size_t channel_index) {
597 return channel_target_event_loop_factory_[channel_index]->monotonic_now();
598 }
599
Austin Schuh2f8fd752020-09-01 22:38:28 -0700600 distributed_clock::time_point RemoteToDistributedClock(
601 size_t channel_index, monotonic_clock::time_point time) {
602 return channel_target_event_loop_factory_[channel_index]
603 ->ToDistributedClock(time);
604 }
605
606 const Node *remote_node(size_t channel_index) {
607 return channel_target_event_loop_factory_[channel_index]->node();
608 }
609
610 monotonic_clock::time_point monotonic_now() {
611 return node_event_loop_factory_->monotonic_now();
612 }
613
Austin Schuh858c9f32020-08-31 16:56:12 -0700614 // Sets the node we will be merging as, and returns true if there is any
615 // data on it.
616 bool SetNode() { return channel_merger_->SetNode(event_loop_->node()); }
617
618 // Sets the number of channels.
619 void SetChannelCount(size_t count);
620
621 // Sets the sender, filter, and target factory for a channel.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700622 void SetChannel(size_t channel, std::unique_ptr<RawSender> sender,
623 message_bridge::NoncausalOffsetEstimator *filter,
624 NodeEventLoopFactory *channel_target_event_loop_factory);
Austin Schuh858c9f32020-08-31 16:56:12 -0700625
626 // Returns if we have read all the messages from all the logs.
627 bool at_end() const { return channel_merger_->at_end(); }
628
629 // Unregisters everything so we can destory the event loop.
630 void Deregister();
631
632 // Sets the current TimerHandle for the replay callback.
633 void set_timer_handler(TimerHandler *timer_handler) {
634 timer_handler_ = timer_handler;
635 }
636
637 // Sets the next wakeup time on the replay callback.
638 void Setup(monotonic_clock::time_point next_time) {
639 timer_handler_->Setup(next_time);
640 }
641
642 // Sends a buffer on the provided channel index.
643 bool Send(size_t channel_index, const void *data, size_t size,
644 aos::monotonic_clock::time_point monotonic_remote_time,
645 aos::realtime_clock::time_point realtime_remote_time,
646 uint32_t remote_queue_index) {
647 return channels_[channel_index]->Send(data, size, monotonic_remote_time,
648 realtime_remote_time,
649 remote_queue_index);
650 }
651
652 // Returns a debug string for the channel merger.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700653 std::string DebugString() const {
654 std::stringstream messages;
655 size_t i = 0;
656 for (const auto &message : sorted_messages_) {
657 if (i < 7 || i + 7 > sorted_messages_.size()) {
658 messages << "sorted_messages[" << i
659 << "]: " << std::get<0>(message).monotonic_event_time << " "
660 << configuration::StrippedChannelToString(
661 event_loop_->configuration()->channels()->Get(
662 std::get<2>(message).message().channel_index()))
663 << "\n";
664 } else if (i == 7) {
665 messages << "...\n";
666 }
667 ++i;
668 }
669 return messages.str() + channel_merger_->DebugString();
670 }
Austin Schuh858c9f32020-08-31 16:56:12 -0700671
672 private:
673 // Log file.
674 std::unique_ptr<ChannelMerger> channel_merger_;
675
676 std::deque<std::tuple<TimestampMerger::DeliveryTimestamp, int,
Austin Schuh2f8fd752020-09-01 22:38:28 -0700677 FlatbufferVector<MessageHeader>,
678 message_bridge::NoncausalOffsetEstimator *>>
Austin Schuh858c9f32020-08-31 16:56:12 -0700679 sorted_messages_;
680
681 // Senders.
682 std::vector<std::unique_ptr<RawSender>> channels_;
683
684 // Factory (if we are in sim) that this loop was created on.
685 NodeEventLoopFactory *node_event_loop_factory_ = nullptr;
686 std::unique_ptr<EventLoop> event_loop_unique_ptr_;
687 // Event loop.
688 EventLoop *event_loop_ = nullptr;
689 // And timer used to send messages.
690 TimerHandler *timer_handler_;
691
Austin Schuh8bd96322020-02-13 21:18:22 -0800692 // Filters (or nullptr if it isn't a forwarded channel) for each channel.
693 // This corresponds to the object which is shared among all the channels
694 // going between 2 nodes. The second element in the tuple indicates if this
695 // is the primary direction or not.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700696 std::vector<message_bridge::NoncausalOffsetEstimator *> filters_;
Austin Schuh8bd96322020-02-13 21:18:22 -0800697
698 // List of NodeEventLoopFactorys (or nullptr if it isn't a forwarded
699 // channel) which correspond to the originating node.
Austin Schuh858c9f32020-08-31 16:56:12 -0700700 std::vector<NodeEventLoopFactory *> channel_target_event_loop_factory_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800701 };
702
Austin Schuh8bd96322020-02-13 21:18:22 -0800703 // Node index -> State.
704 std::vector<std::unique_ptr<State>> states_;
705
706 // Creates the requested filter if it doesn't exist, regardless of whether
707 // these nodes can actually communicate directly. The second return value
708 // reports if this is the primary direction or not.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700709 message_bridge::NoncausalOffsetEstimator *GetFilter(const Node *node_a,
710 const Node *node_b);
Austin Schuh8bd96322020-02-13 21:18:22 -0800711
712 // FILE to write offsets to (if populated).
713 FILE *offset_fp_ = nullptr;
714 // Timestamp of the first piece of data used for the horizontal axis on the
715 // plot.
716 aos::realtime_clock::time_point first_time_;
717
718 // List of filters for a connection. The pointer to the first node will be
719 // less than the second node.
720 std::map<std::tuple<const Node *, const Node *>,
Austin Schuh2f8fd752020-09-01 22:38:28 -0700721 std::tuple<message_bridge::NoncausalOffsetEstimator>>
Austin Schuh8bd96322020-02-13 21:18:22 -0800722 filters_;
723
724 // Returns the offset from the monotonic clock for a node to the distributed
Austin Schuh2f8fd752020-09-01 22:38:28 -0700725 // clock. monotonic = distributed * slope() + offset();
726 double slope(int node_index) const {
727 CHECK_LT(node_index, time_slope_matrix_.rows())
James Kuszmaul46d82582020-05-09 19:50:09 -0700728 << ": Got too high of a node index.";
Austin Schuh2f8fd752020-09-01 22:38:28 -0700729 return time_slope_matrix_(node_index);
730 }
731 std::chrono::nanoseconds offset(int node_index) const {
732 CHECK_LT(node_index, time_offset_matrix_.rows())
733 << ": Got too high of a node index.";
734 return std::chrono::duration_cast<std::chrono::nanoseconds>(
735 std::chrono::duration<double>(time_offset_matrix_(node_index)));
Austin Schuh8bd96322020-02-13 21:18:22 -0800736 }
737
738 // Updates the offset matrix solution and sets the per-node distributed
739 // offsets in the factory.
740 void UpdateOffsets();
741
Austin Schuh2f8fd752020-09-01 22:38:28 -0700742 // We have 2 types of equations to do a least squares regression over to fully
743 // constrain our time function.
744 //
745 // One is simple. The distributed clock is the average of all the clocks.
746 // (ta + tb + tc + td) / num_nodex = t_distributed
747 //
748 // The second is a bit more complicated. Our basic time conversion function
749 // is:
750 // tb = ta + (ta * slope + offset)
751 // We can rewrite this as follows
752 // tb - (1 + slope) * ta = offset
753 //
754 // From here, we have enough equations to solve for t{a,b,c,...} We want to
755 // take as an input the offsets and slope, and solve for the per-node times as
756 // a function of the distributed clock.
757 //
758 // We need to massage our equations to make this work. If we solve for the
759 // per-node times at two set distributed clock times, we will be able to
760 // recreate the linear function (we know it is linear). We can do a similar
761 // thing by breaking our equation up into:
762 //
763 // [1/3 1/3 1/3 ] [ta] [t_distributed]
764 // [ 1 -1-m1 0 ] [tb] = [oab]
765 // [ 1 0 -1-m2 ] [tc] [oac]
766 //
767 // This solves to:
768 //
769 // [ta] [ a00 a01 a02] [t_distributed]
770 // [tb] = [ a10 a11 a12] * [oab]
771 // [tc] [ a20 a21 a22] [oac]
772 //
773 // and can be split into:
774 //
775 // [ta] [ a00 ] [a01 a02]
776 // [tb] = [ a10 ] * t_distributed + [a11 a12] * [oab]
777 // [tc] [ a20 ] [a21 a22] [oac]
778 //
779 // (map_matrix_ + slope_matrix_) * [ta; tb; tc] = [offset_matrix_];
780 // offset_matrix_ will be in nanoseconds.
781 Eigen::Matrix<mpq_class, Eigen::Dynamic, Eigen::Dynamic> map_matrix_;
782 Eigen::Matrix<mpq_class, Eigen::Dynamic, Eigen::Dynamic> slope_matrix_;
783 Eigen::Matrix<mpq_class, Eigen::Dynamic, 1> offset_matrix_;
784 // Matrix tracking which offsets are valid.
785 Eigen::Matrix<bool, Eigen::Dynamic, 1> valid_matrix_;
786 // Matrix tracking the last valid matrix we used to determine connected nodes.
787 Eigen::Matrix<bool, Eigen::Dynamic, 1> last_valid_matrix_;
788 size_t cached_valid_node_count_ = 0;
Austin Schuh8bd96322020-02-13 21:18:22 -0800789
Austin Schuh2f8fd752020-09-01 22:38:28 -0700790 // [ta; tb; tc] = time_slope_matrix_ * t + time_offset_matrix;
791 // t is in seconds.
792 Eigen::Matrix<double, Eigen::Dynamic, 1> time_slope_matrix_;
793 Eigen::Matrix<double, Eigen::Dynamic, 1> time_offset_matrix_;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800794
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800795 std::unique_ptr<FlatbufferDetachedBuffer<Configuration>>
796 remapped_configuration_buffer_;
797
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800798 std::unique_ptr<SimulatedEventLoopFactory> event_loop_factory_unique_ptr_;
799 SimulatedEventLoopFactory *event_loop_factory_ = nullptr;
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800800
801 // Map of channel indices to new name. The channel index will be an index into
802 // logged_configuration(), and the string key will be the name of the channel
803 // to send on instead of the logged channel name.
804 std::map<size_t, std::string> remapped_channels_;
805
Austin Schuh6f3babe2020-01-26 20:34:50 -0800806 // Number of nodes which still have data to send. This is used to figure out
807 // when to exit.
808 size_t live_nodes_ = 0;
809
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800810 const Configuration *remapped_configuration_ = nullptr;
811 const Configuration *replay_configuration_ = nullptr;
Austin Schuhcde938c2020-02-02 17:30:07 -0800812
813 // If true, the replay timer will ignore any missing data. This is used
814 // during startup when we are bootstrapping everything and trying to get to
815 // the start of all the log files.
816 bool ignore_missing_data_ = false;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800817};
818
819} // namespace logger
820} // namespace aos
821
822#endif // AOS_EVENTS_LOGGER_H_