blob: d4ed786d4d8d4d4bb2e9a5bca07527cfad691da7 [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 Schuh6f3babe2020-01-26 20:34:50 -0800378// We end up with one of the following 3 log file types.
379//
380// Single node logged as the source node.
381// -> Replayed just on the source node.
382//
383// Forwarding timestamps only logged from the perspective of the destination
384// node.
385// -> Matched with data on source node and logged.
386//
387// Forwarding timestamps with data logged as the destination node.
388// -> Replayed just as the destination
389// -> Replayed as the source (Much harder, ordering is not defined)
390//
391// Duplicate data logged. -> CHECK that it matches and explode otherwise.
392//
393// This can be boiled down to a set of constraints and tools.
394//
395// 1) Forwarding timestamps and data need to be logged separately.
396// 2) Any forwarded data logged on the destination node needs to be logged
397// separately such that it can be sorted.
398//
399// 1) Log reader needs to be able to sort a list of log files.
400// 2) Log reader needs to be able to merge sorted lists of log files.
401// 3) Log reader needs to be able to match timestamps with messages.
402//
403// We also need to be able to generate multiple views of a log file depending on
404// the target.
405
Austin Schuhe309d2a2019-11-29 13:25:21 -0800406// Replays all the channels in the logfile to the event loop.
407class LogReader {
408 public:
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800409 // If you want to supply a new configuration that will be used for replay
410 // (e.g., to change message rates, or to populate an updated schema), then
411 // pass it in here. It must provide all the channels that the original logged
412 // config did.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800413 //
414 // Log filenames are in the following format:
415 //
416 // {
417 // {log1_part0, log1_part1, ...},
418 // {log2}
419 // }
420 // The inner vector is a list of log file chunks which form up a log file.
421 // The outer vector is a list of log files with subsets of the messages, or
422 // messages from different nodes.
423 //
424 // If the outer vector isn't provided, it is assumed to be of size 1.
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800425 LogReader(std::string_view filename,
426 const Configuration *replay_configuration = nullptr);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800427 LogReader(const std::vector<std::string> &filenames,
428 const Configuration *replay_configuration = nullptr);
429 LogReader(const std::vector<std::vector<std::string>> &filenames,
Austin Schuhfa895892020-01-07 20:07:41 -0800430 const Configuration *replay_configuration = nullptr);
James Kuszmaul7daef362019-12-31 18:28:17 -0800431 ~LogReader();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800432
Austin Schuh6331ef92020-01-07 18:28:09 -0800433 // Registers all the callbacks to send the log file data out on an event loop
434 // created in event_loop_factory. This also updates time to be at the start
435 // of the log file by running until the log file starts.
436 // Note: the configuration used in the factory should be configuration()
437 // below, but can be anything as long as the locations needed to send
438 // everything are available.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800439 void Register(SimulatedEventLoopFactory *event_loop_factory);
Austin Schuh6331ef92020-01-07 18:28:09 -0800440 // Creates an SimulatedEventLoopFactory accessible via event_loop_factory(),
441 // and then calls Register.
442 void Register();
443 // Registers callbacks for all the events after the log file starts. This is
444 // only useful when replaying live.
Austin Schuhe309d2a2019-11-29 13:25:21 -0800445 void Register(EventLoop *event_loop);
Austin Schuh6331ef92020-01-07 18:28:09 -0800446
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800447 // Unregisters the senders. You only need to call this if you separately
448 // supplied an event loop or event loop factory and the lifetimes are such
449 // that they need to be explicitly destroyed before the LogReader destructor
450 // gets called.
Austin Schuhe309d2a2019-11-29 13:25:21 -0800451 void Deregister();
452
Austin Schuhe309d2a2019-11-29 13:25:21 -0800453 // Returns the configuration from the log file.
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800454 const Configuration *logged_configuration() const;
455 // Returns the configuration being used for replay.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800456 // The pointer is invalidated whenever RemapLoggedChannel is called.
Austin Schuh15649d62019-12-28 16:36:38 -0800457 const Configuration *configuration() const;
458
Austin Schuh6f3babe2020-01-26 20:34:50 -0800459 // Returns the nodes that this log file was created on. This is a list of
460 // pointers to a node in the nodes() list inside configuration(). The
461 // pointers here are invalidated whenever RemapLoggedChannel is called.
462 std::vector<const Node *> Nodes() const;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800463
464 // Returns the starting timestamp for the log file.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800465 monotonic_clock::time_point monotonic_start_time(const Node *node = nullptr);
466 realtime_clock::time_point realtime_start_time(const Node *node = nullptr);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800467
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800468 // Causes the logger to publish the provided channel on a different name so
469 // that replayed applications can publish on the proper channel name without
470 // interference. This operates on raw channel names, without any node or
471 // application specific mappings.
472 void RemapLoggedChannel(std::string_view name, std::string_view type,
473 std::string_view add_prefix = "/original");
474 template <typename T>
475 void RemapLoggedChannel(std::string_view name,
476 std::string_view add_prefix = "/original") {
477 RemapLoggedChannel(name, T::GetFullyQualifiedName(), add_prefix);
478 }
479
Brian Silvermande9f3ff2020-04-28 16:56:58 -0700480 template <typename T>
481 bool HasChannel(std::string_view name) {
482 return configuration::GetChannel(log_file_header()->configuration(), name,
483 T::GetFullyQualifiedName(), "",
484 nullptr) != nullptr;
485 }
486
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800487 SimulatedEventLoopFactory *event_loop_factory() {
488 return event_loop_factory_;
489 }
490
Brian Silvermande9f3ff2020-04-28 16:56:58 -0700491 const LogFileHeader *log_file_header() const {
492 return &log_file_header_.message();
493 }
494
Austin Schuhe309d2a2019-11-29 13:25:21 -0800495 private:
Austin Schuh6f3babe2020-01-26 20:34:50 -0800496 const Channel *RemapChannel(const EventLoop *event_loop,
497 const Channel *channel);
498
Austin Schuhe309d2a2019-11-29 13:25:21 -0800499 // Queues at least max_out_of_order_duration_ messages into channels_.
500 void QueueMessages();
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800501 // Handle constructing a configuration with all the additional remapped
502 // channels from calls to RemapLoggedChannel.
503 void MakeRemappedConfig();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800504
Austin Schuh2f8fd752020-09-01 22:38:28 -0700505 // Returns the number of nodes.
506 size_t nodes_count() const {
507 return !configuration::MultiNode(logged_configuration())
508 ? 1u
509 : logged_configuration()->nodes()->size();
510 }
511
Austin Schuh6f3babe2020-01-26 20:34:50 -0800512 const std::vector<std::vector<std::string>> filenames_;
513
514 // This is *a* log file header used to provide the logged config. The rest of
515 // the header is likely distracting.
516 FlatbufferVector<LogFileHeader> log_file_header_;
517
Austin Schuh2f8fd752020-09-01 22:38:28 -0700518 // Returns [ta; tb; ...] = tuple[0] * t + tuple[1]
519 std::tuple<Eigen::Matrix<double, Eigen::Dynamic, 1>,
520 Eigen::Matrix<double, Eigen::Dynamic, 1>>
521 SolveOffsets();
522
523 void LogFit(std::string_view prefix);
Austin Schuh8bd96322020-02-13 21:18:22 -0800524
Austin Schuh6f3babe2020-01-26 20:34:50 -0800525 // State per node.
Austin Schuh858c9f32020-08-31 16:56:12 -0700526 class State {
527 public:
528 State(std::unique_ptr<ChannelMerger> channel_merger);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800529
Austin Schuh858c9f32020-08-31 16:56:12 -0700530 // Returns the timestamps, channel_index, and message from a channel.
531 // update_time (will be) set to true when popping this message causes the
532 // filter to change the time offset estimation function.
533 std::tuple<TimestampMerger::DeliveryTimestamp, int,
534 FlatbufferVector<MessageHeader>>
535 PopOldest(bool *update_time);
536
537 // Returns the monotonic time of the oldest message.
538 monotonic_clock::time_point OldestMessageTime() const;
539
540 // Primes the queues inside State. Should be called before calling
541 // OldestMessageTime.
542 void SeedSortedMessages();
Austin Schuh8bd96322020-02-13 21:18:22 -0800543
Austin Schuh858c9f32020-08-31 16:56:12 -0700544 // Returns the starting time for this node.
545 monotonic_clock::time_point monotonic_start_time() const {
546 return channel_merger_->monotonic_start_time();
547 }
548 realtime_clock::time_point realtime_start_time() const {
549 return channel_merger_->realtime_start_time();
550 }
551
552 // Sets the node event loop factory for replaying into a
553 // SimulatedEventLoopFactory. Returns the EventLoop to use.
554 EventLoop *SetNodeEventLoopFactory(
555 NodeEventLoopFactory *node_event_loop_factory);
556
557 // Sets and gets the event loop to use.
558 void set_event_loop(EventLoop *event_loop) { event_loop_ = event_loop; }
559 EventLoop *event_loop() { return event_loop_; }
560
Austin Schuh858c9f32020-08-31 16:56:12 -0700561 // Sets the current realtime offset from the monotonic clock for this node
562 // (if we are on a simulated event loop).
563 void SetRealtimeOffset(monotonic_clock::time_point monotonic_time,
564 realtime_clock::time_point realtime_time) {
565 if (node_event_loop_factory_ != nullptr) {
566 node_event_loop_factory_->SetRealtimeOffset(monotonic_time,
567 realtime_time);
568 }
569 }
570
571 // Converts a timestamp from the monotonic clock on this node to the
572 // distributed clock.
573 distributed_clock::time_point ToDistributedClock(
574 monotonic_clock::time_point time) {
575 return node_event_loop_factory_->ToDistributedClock(time);
576 }
577
Austin Schuh2f8fd752020-09-01 22:38:28 -0700578 monotonic_clock::time_point FromDistributedClock(
579 distributed_clock::time_point time) {
580 return node_event_loop_factory_->FromDistributedClock(time);
581 }
582
Austin Schuh858c9f32020-08-31 16:56:12 -0700583 // Sets the offset (and slope) from the distributed clock.
584 void SetDistributedOffset(std::chrono::nanoseconds distributed_offset,
585 double distributed_slope) {
586 node_event_loop_factory_->SetDistributedOffset(distributed_offset,
587 distributed_slope);
588 }
589
590 // Returns the current time on the remote node which sends messages on
591 // channel_index.
592 monotonic_clock::time_point monotonic_remote_now(size_t channel_index) {
593 return channel_target_event_loop_factory_[channel_index]->monotonic_now();
594 }
595
Austin Schuh2f8fd752020-09-01 22:38:28 -0700596 distributed_clock::time_point RemoteToDistributedClock(
597 size_t channel_index, monotonic_clock::time_point time) {
598 return channel_target_event_loop_factory_[channel_index]
599 ->ToDistributedClock(time);
600 }
601
602 const Node *remote_node(size_t channel_index) {
603 return channel_target_event_loop_factory_[channel_index]->node();
604 }
605
606 monotonic_clock::time_point monotonic_now() {
607 return node_event_loop_factory_->monotonic_now();
608 }
609
Austin Schuh858c9f32020-08-31 16:56:12 -0700610 // Sets the node we will be merging as, and returns true if there is any
611 // data on it.
612 bool SetNode() { return channel_merger_->SetNode(event_loop_->node()); }
613
614 // Sets the number of channels.
615 void SetChannelCount(size_t count);
616
617 // Sets the sender, filter, and target factory for a channel.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700618 void SetChannel(size_t channel, std::unique_ptr<RawSender> sender,
619 message_bridge::NoncausalOffsetEstimator *filter,
620 NodeEventLoopFactory *channel_target_event_loop_factory);
Austin Schuh858c9f32020-08-31 16:56:12 -0700621
622 // Returns if we have read all the messages from all the logs.
623 bool at_end() const { return channel_merger_->at_end(); }
624
625 // Unregisters everything so we can destory the event loop.
626 void Deregister();
627
628 // Sets the current TimerHandle for the replay callback.
629 void set_timer_handler(TimerHandler *timer_handler) {
630 timer_handler_ = timer_handler;
631 }
632
633 // Sets the next wakeup time on the replay callback.
634 void Setup(monotonic_clock::time_point next_time) {
635 timer_handler_->Setup(next_time);
636 }
637
638 // Sends a buffer on the provided channel index.
639 bool Send(size_t channel_index, const void *data, size_t size,
640 aos::monotonic_clock::time_point monotonic_remote_time,
641 aos::realtime_clock::time_point realtime_remote_time,
642 uint32_t remote_queue_index) {
643 return channels_[channel_index]->Send(data, size, monotonic_remote_time,
644 realtime_remote_time,
645 remote_queue_index);
646 }
647
648 // Returns a debug string for the channel merger.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700649 std::string DebugString() const {
650 std::stringstream messages;
651 size_t i = 0;
652 for (const auto &message : sorted_messages_) {
653 if (i < 7 || i + 7 > sorted_messages_.size()) {
654 messages << "sorted_messages[" << i
655 << "]: " << std::get<0>(message).monotonic_event_time << " "
656 << configuration::StrippedChannelToString(
657 event_loop_->configuration()->channels()->Get(
658 std::get<2>(message).message().channel_index()))
659 << "\n";
660 } else if (i == 7) {
661 messages << "...\n";
662 }
663 ++i;
664 }
665 return messages.str() + channel_merger_->DebugString();
666 }
Austin Schuh858c9f32020-08-31 16:56:12 -0700667
668 private:
669 // Log file.
670 std::unique_ptr<ChannelMerger> channel_merger_;
671
672 std::deque<std::tuple<TimestampMerger::DeliveryTimestamp, int,
Austin Schuh2f8fd752020-09-01 22:38:28 -0700673 FlatbufferVector<MessageHeader>,
674 message_bridge::NoncausalOffsetEstimator *>>
Austin Schuh858c9f32020-08-31 16:56:12 -0700675 sorted_messages_;
676
677 // Senders.
678 std::vector<std::unique_ptr<RawSender>> channels_;
679
680 // Factory (if we are in sim) that this loop was created on.
681 NodeEventLoopFactory *node_event_loop_factory_ = nullptr;
682 std::unique_ptr<EventLoop> event_loop_unique_ptr_;
683 // Event loop.
684 EventLoop *event_loop_ = nullptr;
685 // And timer used to send messages.
686 TimerHandler *timer_handler_;
687
Austin Schuh8bd96322020-02-13 21:18:22 -0800688 // Filters (or nullptr if it isn't a forwarded channel) for each channel.
689 // This corresponds to the object which is shared among all the channels
690 // going between 2 nodes. The second element in the tuple indicates if this
691 // is the primary direction or not.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700692 std::vector<message_bridge::NoncausalOffsetEstimator *> filters_;
Austin Schuh8bd96322020-02-13 21:18:22 -0800693
694 // List of NodeEventLoopFactorys (or nullptr if it isn't a forwarded
695 // channel) which correspond to the originating node.
Austin Schuh858c9f32020-08-31 16:56:12 -0700696 std::vector<NodeEventLoopFactory *> channel_target_event_loop_factory_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800697 };
698
Austin Schuh8bd96322020-02-13 21:18:22 -0800699 // Node index -> State.
700 std::vector<std::unique_ptr<State>> states_;
701
702 // Creates the requested filter if it doesn't exist, regardless of whether
703 // these nodes can actually communicate directly. The second return value
704 // reports if this is the primary direction or not.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700705 message_bridge::NoncausalOffsetEstimator *GetFilter(const Node *node_a,
706 const Node *node_b);
Austin Schuh8bd96322020-02-13 21:18:22 -0800707
708 // FILE to write offsets to (if populated).
709 FILE *offset_fp_ = nullptr;
710 // Timestamp of the first piece of data used for the horizontal axis on the
711 // plot.
712 aos::realtime_clock::time_point first_time_;
713
714 // List of filters for a connection. The pointer to the first node will be
715 // less than the second node.
716 std::map<std::tuple<const Node *, const Node *>,
Austin Schuh2f8fd752020-09-01 22:38:28 -0700717 std::tuple<message_bridge::NoncausalOffsetEstimator>>
Austin Schuh8bd96322020-02-13 21:18:22 -0800718 filters_;
719
720 // Returns the offset from the monotonic clock for a node to the distributed
Austin Schuh2f8fd752020-09-01 22:38:28 -0700721 // clock. monotonic = distributed * slope() + offset();
722 double slope(int node_index) const {
723 CHECK_LT(node_index, time_slope_matrix_.rows())
James Kuszmaul46d82582020-05-09 19:50:09 -0700724 << ": Got too high of a node index.";
Austin Schuh2f8fd752020-09-01 22:38:28 -0700725 return time_slope_matrix_(node_index);
726 }
727 std::chrono::nanoseconds offset(int node_index) const {
728 CHECK_LT(node_index, time_offset_matrix_.rows())
729 << ": Got too high of a node index.";
730 return std::chrono::duration_cast<std::chrono::nanoseconds>(
731 std::chrono::duration<double>(time_offset_matrix_(node_index)));
Austin Schuh8bd96322020-02-13 21:18:22 -0800732 }
733
734 // Updates the offset matrix solution and sets the per-node distributed
735 // offsets in the factory.
736 void UpdateOffsets();
737
Austin Schuh2f8fd752020-09-01 22:38:28 -0700738 // We have 2 types of equations to do a least squares regression over to fully
739 // constrain our time function.
740 //
741 // One is simple. The distributed clock is the average of all the clocks.
742 // (ta + tb + tc + td) / num_nodex = t_distributed
743 //
744 // The second is a bit more complicated. Our basic time conversion function
745 // is:
746 // tb = ta + (ta * slope + offset)
747 // We can rewrite this as follows
748 // tb - (1 + slope) * ta = offset
749 //
750 // From here, we have enough equations to solve for t{a,b,c,...} We want to
751 // take as an input the offsets and slope, and solve for the per-node times as
752 // a function of the distributed clock.
753 //
754 // We need to massage our equations to make this work. If we solve for the
755 // per-node times at two set distributed clock times, we will be able to
756 // recreate the linear function (we know it is linear). We can do a similar
757 // thing by breaking our equation up into:
758 //
759 // [1/3 1/3 1/3 ] [ta] [t_distributed]
760 // [ 1 -1-m1 0 ] [tb] = [oab]
761 // [ 1 0 -1-m2 ] [tc] [oac]
762 //
763 // This solves to:
764 //
765 // [ta] [ a00 a01 a02] [t_distributed]
766 // [tb] = [ a10 a11 a12] * [oab]
767 // [tc] [ a20 a21 a22] [oac]
768 //
769 // and can be split into:
770 //
771 // [ta] [ a00 ] [a01 a02]
772 // [tb] = [ a10 ] * t_distributed + [a11 a12] * [oab]
773 // [tc] [ a20 ] [a21 a22] [oac]
774 //
775 // (map_matrix_ + slope_matrix_) * [ta; tb; tc] = [offset_matrix_];
776 // offset_matrix_ will be in nanoseconds.
777 Eigen::Matrix<mpq_class, Eigen::Dynamic, Eigen::Dynamic> map_matrix_;
778 Eigen::Matrix<mpq_class, Eigen::Dynamic, Eigen::Dynamic> slope_matrix_;
779 Eigen::Matrix<mpq_class, Eigen::Dynamic, 1> offset_matrix_;
780 // Matrix tracking which offsets are valid.
781 Eigen::Matrix<bool, Eigen::Dynamic, 1> valid_matrix_;
782 // Matrix tracking the last valid matrix we used to determine connected nodes.
783 Eigen::Matrix<bool, Eigen::Dynamic, 1> last_valid_matrix_;
784 size_t cached_valid_node_count_ = 0;
Austin Schuh8bd96322020-02-13 21:18:22 -0800785
Austin Schuh2f8fd752020-09-01 22:38:28 -0700786 // [ta; tb; tc] = time_slope_matrix_ * t + time_offset_matrix;
787 // t is in seconds.
788 Eigen::Matrix<double, Eigen::Dynamic, 1> time_slope_matrix_;
789 Eigen::Matrix<double, Eigen::Dynamic, 1> time_offset_matrix_;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800790
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800791 std::unique_ptr<FlatbufferDetachedBuffer<Configuration>>
792 remapped_configuration_buffer_;
793
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800794 std::unique_ptr<SimulatedEventLoopFactory> event_loop_factory_unique_ptr_;
795 SimulatedEventLoopFactory *event_loop_factory_ = nullptr;
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800796
797 // Map of channel indices to new name. The channel index will be an index into
798 // logged_configuration(), and the string key will be the name of the channel
799 // to send on instead of the logged channel name.
800 std::map<size_t, std::string> remapped_channels_;
801
Austin Schuh6f3babe2020-01-26 20:34:50 -0800802 // Number of nodes which still have data to send. This is used to figure out
803 // when to exit.
804 size_t live_nodes_ = 0;
805
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800806 const Configuration *remapped_configuration_ = nullptr;
807 const Configuration *replay_configuration_ = nullptr;
Austin Schuhcde938c2020-02-02 17:30:07 -0800808
809 // If true, the replay timer will ignore any missing data. This is used
810 // during startup when we are bootstrapping everything and trying to get to
811 // the start of all the log files.
812 bool ignore_missing_data_ = false;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800813};
814
815} // namespace logger
816} // namespace aos
817
818#endif // AOS_EVENTS_LOGGER_H_