blob: f6a037b1640ada9bd0158efad036755fa5974564 [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 Schuhcb5601b2020-09-10 15:29:59 -070015#include "aos/events/logging/log_namer.h"
Austin Schuhf6f9bf32020-10-11 14:37:43 -070016#include "aos/events/logging/logfile_sorting.h"
Austin Schuha36c8902019-12-30 18:07:15 -080017#include "aos/events/logging/logfile_utils.h"
James Kuszmaul38735e82019-12-07 16:42:06 -080018#include "aos/events/logging/logger_generated.h"
Austin Schuh64fab802020-09-09 22:47:47 -070019#include "aos/events/logging/uuid.h"
Austin Schuh92547522019-12-28 14:33:43 -080020#include "aos/events/simulated_event_loop.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070021#include "aos/network/message_bridge_server_generated.h"
Austin Schuh8bd96322020-02-13 21:18:22 -080022#include "aos/network/timestamp_filter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080023#include "aos/time/time.h"
24#include "flatbuffers/flatbuffers.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070025#include "third_party/gmp/gmpxx.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080026
27namespace aos {
28namespace logger {
29
Austin Schuhe309d2a2019-11-29 13:25:21 -080030// Logs all channels available in the event loop to disk every 100 ms.
31// Start by logging one message per channel to capture any state and
32// configuration that is sent rately on a channel and would affect execution.
33class Logger {
34 public:
Austin Schuh0c297012020-09-16 18:41:59 -070035 // Constructs a logger.
Austin Schuh0c297012020-09-16 18:41:59 -070036 // event_loop: The event loop used to read the messages.
Austin Schuh0c297012020-09-16 18:41:59 -070037 // configuration: When provided, this is the configuration to log, and the
38 // configuration to use for the channel list to log. If not provided,
39 // this becomes the configuration from the event loop.
Brian Silverman1f345222020-09-24 21:14:48 -070040 // should_log: When provided, a filter for channels to log. If not provided,
41 // all available channels are logged.
42 Logger(EventLoop *event_loop)
43 : Logger(event_loop, event_loop->configuration()) {}
44 Logger(EventLoop *event_loop, const Configuration *configuration)
45 : Logger(event_loop, configuration,
46 [](const Channel *) { return true; }) {}
47 Logger(EventLoop *event_loop, const Configuration *configuration,
48 std::function<bool(const Channel *)> should_log);
Austin Schuh0c297012020-09-16 18:41:59 -070049 ~Logger();
50
51 // Overrides the name in the log file header.
52 void set_name(std::string_view name) { name_ = name; }
Austin Schuhe309d2a2019-11-29 13:25:21 -080053
Brian Silverman1f345222020-09-24 21:14:48 -070054 // Sets the callback to run after each period of data is logged. Defaults to
55 // doing nothing.
56 //
57 // This callback may safely do things like call Rotate().
58 void set_on_logged_period(std::function<void()> on_logged_period) {
59 on_logged_period_ = std::move(on_logged_period);
60 }
61
62 // Sets the period between polling the data. Defaults to 100ms.
63 //
64 // Changing this while a set of files is being written may result in
65 // unreadable files.
66 void set_polling_period(std::chrono::nanoseconds polling_period) {
67 polling_period_ = polling_period;
68 }
69
Brian Silvermanae7c0332020-09-30 16:58:23 -070070 std::string_view log_start_uuid() const { return log_start_uuid_; }
Brian Silverman035e4182020-10-06 17:13:00 -070071 UUID logger_instance_uuid() const { return logger_instance_uuid_; }
Brian Silvermanae7c0332020-09-30 16:58:23 -070072
Brian Silvermancb805822020-10-06 17:43:35 -070073 // The maximum time for a single fetch which returned a message, or 0 if none
74 // of those have happened.
75 std::chrono::nanoseconds max_message_fetch_time() const {
76 return max_message_fetch_time_;
77 }
78 // The channel for that longest fetch which returned a message, or -1 if none
79 // of those have happened.
80 int max_message_fetch_time_channel() const {
81 return max_message_fetch_time_channel_;
82 }
83 // The size of the message returned by that longest fetch, or -1 if none of
84 // those have happened.
85 int max_message_fetch_time_size() const {
86 return max_message_fetch_time_size_;
87 }
88 // The total time spent fetching messages.
89 std::chrono::nanoseconds total_message_fetch_time() const {
90 return total_message_fetch_time_;
91 }
92 // The total number of fetch calls which returned messages.
93 int total_message_fetch_count() const { return total_message_fetch_count_; }
94 // The total number of bytes fetched.
95 int64_t total_message_fetch_bytes() const {
96 return total_message_fetch_bytes_;
97 }
98
99 // The total time spent in fetches which did not return a message.
100 std::chrono::nanoseconds total_nop_fetch_time() const {
101 return total_nop_fetch_time_;
102 }
103 // The total number of fetches which did not return a message.
104 int total_nop_fetch_count() const { return total_nop_fetch_count_; }
105
106 // The maximum time for a single copy, or 0 if none of those have happened.
107 std::chrono::nanoseconds max_copy_time() const { return max_copy_time_; }
108 // The channel for that longest copy, or -1 if none of those have happened.
109 int max_copy_time_channel() const { return max_copy_time_channel_; }
110 // The size of the message for that longest copy, or -1 if none of those have
111 // happened.
112 int max_copy_time_size() const { return max_copy_time_size_; }
113 // The total time spent copying messages.
114 std::chrono::nanoseconds total_copy_time() const { return total_copy_time_; }
115 // The total number of messages copied.
116 int total_copy_count() const { return total_copy_count_; }
117 // The total number of bytes copied.
118 int64_t total_copy_bytes() const { return total_copy_bytes_; }
119
120 void ResetStatisics();
121
Austin Schuh2f8fd752020-09-01 22:38:28 -0700122 // Rotates the log file(s), triggering new part files to be written for each
123 // log file.
124 void Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800125
Brian Silverman1f345222020-09-24 21:14:48 -0700126 // Starts logging to files with the given naming scheme.
Brian Silvermanae7c0332020-09-30 16:58:23 -0700127 //
128 // log_start_uuid may be used to tie this log event to other log events across
129 // multiple nodes. The default (empty string) indicates there isn't one
130 // available.
131 void StartLogging(std::unique_ptr<LogNamer> log_namer,
132 std::string_view log_start_uuid = "");
Brian Silverman1f345222020-09-24 21:14:48 -0700133
134 // Stops logging. Ensures any messages through end_time make it into the log.
135 //
136 // If you want to stop ASAP, pass min_time to avoid reading any more messages.
137 //
138 // Returns the LogNamer in case the caller wants to do anything else with it
139 // before destroying it.
140 std::unique_ptr<LogNamer> StopLogging(
141 aos::monotonic_clock::time_point end_time);
142
143 // Returns whether a log is currently being written.
144 bool is_started() const { return static_cast<bool>(log_namer_); }
145
146 // Shortcut to call StartLogging with a LocalLogNamer when event processing
147 // starts.
148 void StartLoggingLocalNamerOnRun(std::string base_name) {
149 event_loop_->OnRun([this, base_name]() {
150 StartLogging(
151 std::make_unique<LocalLogNamer>(base_name, event_loop_->node()));
152 });
153 }
154
Austin Schuhe309d2a2019-11-29 13:25:21 -0800155 private:
Austin Schuhe309d2a2019-11-29 13:25:21 -0800156 // Structure to track both a fetcher, and if the data fetched has been
157 // written. We may want to delay writing data to disk so that we don't let
158 // data get too far out of order when written to disk so we can avoid making
159 // it too hard to sort when reading.
160 struct FetcherStruct {
161 std::unique_ptr<RawFetcher> fetcher;
162 bool written = false;
Austin Schuh15649d62019-12-28 16:36:38 -0800163
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700164 // Channel index to log to.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800165 int channel_index = -1;
Brian Silverman1f345222020-09-24 21:14:48 -0700166 const Channel *channel = nullptr;
167 const Node *timestamp_node = nullptr;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800168
169 LogType log_type = LogType::kLogMessage;
170
Brian Silverman1f345222020-09-24 21:14:48 -0700171 // We fill out the metadata at construction, but the actual writers have to
172 // be updated each time we start logging. To avoid duplicating the complex
173 // logic determining whether each writer should be initialized, we just
174 // stash the answer in separate member variables.
175 bool wants_writer = false;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800176 DetachedBufferWriter *writer = nullptr;
Brian Silverman1f345222020-09-24 21:14:48 -0700177 bool wants_timestamp_writer = false;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800178 DetachedBufferWriter *timestamp_writer = nullptr;
Brian Silverman1f345222020-09-24 21:14:48 -0700179 bool wants_contents_writer = false;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700180 DetachedBufferWriter *contents_writer = nullptr;
Brian Silverman1f345222020-09-24 21:14:48 -0700181
Austin Schuh2f8fd752020-09-01 22:38:28 -0700182 int node_index = 0;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800183 };
184
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700185 // Vector mapping from the channel index from the event loop to the logged
186 // channel index.
187 std::vector<int> event_loop_to_logged_channel_index_;
188
Austin Schuh2f8fd752020-09-01 22:38:28 -0700189 struct NodeState {
190 aos::monotonic_clock::time_point monotonic_start_time =
191 aos::monotonic_clock::min_time;
192 aos::realtime_clock::time_point realtime_start_time =
193 aos::realtime_clock::min_time;
194
195 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> log_file_header =
196 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader>::Empty();
197 };
Brian Silverman1f345222020-09-24 21:14:48 -0700198
199 void WriteHeader();
200 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> MakeHeader(
201 const Node *node);
202
203 bool MaybeUpdateTimestamp(
204 const Node *node, int node_index,
205 aos::monotonic_clock::time_point monotonic_start_time,
206 aos::realtime_clock::time_point realtime_start_time);
207
208 void DoLogData(const monotonic_clock::time_point end_time);
209
210 void WriteMissingTimestamps();
211
212 // Fetches from each channel until all the data is logged.
213 void LogUntil(monotonic_clock::time_point t);
214
Brian Silvermancb805822020-10-06 17:43:35 -0700215 void RecordFetchResult(aos::monotonic_clock::time_point start,
216 aos::monotonic_clock::time_point end, bool got_new,
217 FetcherStruct *fetcher);
218
219 void RecordCreateMessageTime(aos::monotonic_clock::time_point start,
220 aos::monotonic_clock::time_point end,
221 FetcherStruct *fetcher);
222
Brian Silverman1f345222020-09-24 21:14:48 -0700223 // Sets the start time for a specific node.
224 void SetStartTime(size_t node_index,
225 aos::monotonic_clock::time_point monotonic_start_time,
226 aos::realtime_clock::time_point realtime_start_time);
227
Brian Silvermanae7c0332020-09-30 16:58:23 -0700228 EventLoop *const event_loop_;
Brian Silverman1f345222020-09-24 21:14:48 -0700229 // The configuration to place at the top of the log file.
230 const Configuration *const configuration_;
231
Brian Silvermanae7c0332020-09-30 16:58:23 -0700232 UUID log_event_uuid_ = UUID::Zero();
233 const UUID logger_instance_uuid_ = UUID::Random();
234 std::unique_ptr<LogNamer> log_namer_;
235 // Empty indicates there isn't one.
236 std::string log_start_uuid_;
237 const std::string boot_uuid_;
238
Brian Silverman1f345222020-09-24 21:14:48 -0700239 // Name to save in the log file. Defaults to hostname.
240 std::string name_;
241
242 std::function<void()> on_logged_period_ = []() {};
243
Brian Silvermancb805822020-10-06 17:43:35 -0700244 std::chrono::nanoseconds max_message_fetch_time_ =
245 std::chrono::nanoseconds::zero();
246 int max_message_fetch_time_channel_ = -1;
247 int max_message_fetch_time_size_ = -1;
248 std::chrono::nanoseconds total_message_fetch_time_ =
249 std::chrono::nanoseconds::zero();
250 int total_message_fetch_count_ = 0;
251 int64_t total_message_fetch_bytes_ = 0;
252
253 std::chrono::nanoseconds total_nop_fetch_time_ =
254 std::chrono::nanoseconds::zero();
255 int total_nop_fetch_count_ = 0;
256
257 std::chrono::nanoseconds max_copy_time_ = std::chrono::nanoseconds::zero();
258 int max_copy_time_channel_ = -1;
259 int max_copy_time_size_ = -1;
260 std::chrono::nanoseconds total_copy_time_ = std::chrono::nanoseconds::zero();
261 int total_copy_count_ = 0;
262 int64_t total_copy_bytes_ = 0;
263
Brian Silverman1f345222020-09-24 21:14:48 -0700264 std::vector<FetcherStruct> fetchers_;
265 TimerHandler *timer_handler_;
266
267 // Period to poll the channels.
268 std::chrono::nanoseconds polling_period_ = std::chrono::milliseconds(100);
269
270 // Last time that data was written for all channels to disk.
271 monotonic_clock::time_point last_synchronized_time_;
272
273 // Max size that the header has consumed. This much extra data will be
274 // reserved in the builder to avoid reallocating.
275 size_t max_header_size_ = 0;
276
277 // Fetcher for all the statistics from all the nodes.
278 aos::Fetcher<message_bridge::ServerStatistics> server_statistics_fetcher_;
279
Austin Schuh2f8fd752020-09-01 22:38:28 -0700280 std::vector<NodeState> node_state_;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800281};
282
Austin Schuh11d43732020-09-21 17:28:30 -0700283std::vector<std::vector<std::string>> ToLogReaderVector(
284 const std::vector<LogFile> &log_files);
Austin Schuh5212cad2020-09-09 23:12:09 -0700285
Austin Schuh6f3babe2020-01-26 20:34:50 -0800286// We end up with one of the following 3 log file types.
287//
288// Single node logged as the source node.
289// -> Replayed just on the source node.
290//
291// Forwarding timestamps only logged from the perspective of the destination
292// node.
293// -> Matched with data on source node and logged.
294//
295// Forwarding timestamps with data logged as the destination node.
296// -> Replayed just as the destination
297// -> Replayed as the source (Much harder, ordering is not defined)
298//
299// Duplicate data logged. -> CHECK that it matches and explode otherwise.
300//
301// This can be boiled down to a set of constraints and tools.
302//
303// 1) Forwarding timestamps and data need to be logged separately.
304// 2) Any forwarded data logged on the destination node needs to be logged
305// separately such that it can be sorted.
306//
307// 1) Log reader needs to be able to sort a list of log files.
308// 2) Log reader needs to be able to merge sorted lists of log files.
309// 3) Log reader needs to be able to match timestamps with messages.
310//
311// We also need to be able to generate multiple views of a log file depending on
312// the target.
313
Austin Schuhe309d2a2019-11-29 13:25:21 -0800314// Replays all the channels in the logfile to the event loop.
315class LogReader {
316 public:
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800317 // If you want to supply a new configuration that will be used for replay
318 // (e.g., to change message rates, or to populate an updated schema), then
319 // pass it in here. It must provide all the channels that the original logged
320 // config did.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800321 //
322 // Log filenames are in the following format:
323 //
324 // {
325 // {log1_part0, log1_part1, ...},
326 // {log2}
327 // }
328 // The inner vector is a list of log file chunks which form up a log file.
329 // The outer vector is a list of log files with subsets of the messages, or
330 // messages from different nodes.
331 //
332 // If the outer vector isn't provided, it is assumed to be of size 1.
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800333 LogReader(std::string_view filename,
334 const Configuration *replay_configuration = nullptr);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800335 LogReader(const std::vector<std::string> &filenames,
336 const Configuration *replay_configuration = nullptr);
337 LogReader(const std::vector<std::vector<std::string>> &filenames,
Austin Schuhfa895892020-01-07 20:07:41 -0800338 const Configuration *replay_configuration = nullptr);
Austin Schuh11d43732020-09-21 17:28:30 -0700339 LogReader(const std::vector<LogFile> &log_files,
340 const Configuration *replay_configuration = nullptr);
James Kuszmaul7daef362019-12-31 18:28:17 -0800341 ~LogReader();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800342
Austin Schuh6331ef92020-01-07 18:28:09 -0800343 // Registers all the callbacks to send the log file data out on an event loop
344 // created in event_loop_factory. This also updates time to be at the start
345 // of the log file by running until the log file starts.
346 // Note: the configuration used in the factory should be configuration()
347 // below, but can be anything as long as the locations needed to send
348 // everything are available.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800349 void Register(SimulatedEventLoopFactory *event_loop_factory);
Austin Schuh6331ef92020-01-07 18:28:09 -0800350 // Creates an SimulatedEventLoopFactory accessible via event_loop_factory(),
351 // and then calls Register.
352 void Register();
353 // Registers callbacks for all the events after the log file starts. This is
354 // only useful when replaying live.
Austin Schuhe309d2a2019-11-29 13:25:21 -0800355 void Register(EventLoop *event_loop);
Austin Schuh6331ef92020-01-07 18:28:09 -0800356
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800357 // Unregisters the senders. You only need to call this if you separately
358 // supplied an event loop or event loop factory and the lifetimes are such
359 // that they need to be explicitly destroyed before the LogReader destructor
360 // gets called.
Austin Schuhe309d2a2019-11-29 13:25:21 -0800361 void Deregister();
362
Austin Schuh0c297012020-09-16 18:41:59 -0700363 // Returns the configuration being used for replay from the log file.
364 // Note that this may be different from the configuration actually used for
365 // handling events. You should generally only use this to create a
366 // SimulatedEventLoopFactory, and then get the configuration from there for
367 // everything else.
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800368 const Configuration *logged_configuration() const;
Austin Schuh11d43732020-09-21 17:28:30 -0700369 // Returns the configuration being used for replay from the log file.
370 // Note that this may be different from the configuration actually used for
371 // handling events. You should generally only use this to create a
372 // SimulatedEventLoopFactory, and then get the configuration from there for
373 // everything else.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800374 // The pointer is invalidated whenever RemapLoggedChannel is called.
Austin Schuh15649d62019-12-28 16:36:38 -0800375 const Configuration *configuration() const;
376
Austin Schuh6f3babe2020-01-26 20:34:50 -0800377 // Returns the nodes that this log file was created on. This is a list of
378 // pointers to a node in the nodes() list inside configuration(). The
379 // pointers here are invalidated whenever RemapLoggedChannel is called.
380 std::vector<const Node *> Nodes() const;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800381
382 // Returns the starting timestamp for the log file.
Austin Schuh11d43732020-09-21 17:28:30 -0700383 monotonic_clock::time_point monotonic_start_time(
384 const Node *node = nullptr) const;
385 realtime_clock::time_point realtime_start_time(
386 const Node *node = nullptr) const;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800387
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800388 // Causes the logger to publish the provided channel on a different name so
389 // that replayed applications can publish on the proper channel name without
390 // interference. This operates on raw channel names, without any node or
391 // application specific mappings.
392 void RemapLoggedChannel(std::string_view name, std::string_view type,
393 std::string_view add_prefix = "/original");
394 template <typename T>
395 void RemapLoggedChannel(std::string_view name,
396 std::string_view add_prefix = "/original") {
397 RemapLoggedChannel(name, T::GetFullyQualifiedName(), add_prefix);
398 }
399
Austin Schuh01b4c352020-09-21 23:09:39 -0700400 // Remaps the provided channel, though this respects node mappings, and
401 // preserves them too. This makes it so if /aos -> /pi1/aos on one node,
402 // /original/aos -> /original/pi1/aos on the same node after renaming, just
403 // like you would hope.
404 //
405 // TODO(austin): If you have 2 nodes remapping something to the same channel,
406 // this doesn't handle that. No use cases exist yet for that, so it isn't
407 // being done yet.
408 void RemapLoggedChannel(std::string_view name, std::string_view type,
409 const Node *node,
410 std::string_view add_prefix = "/original");
Brian Silvermande9f3ff2020-04-28 16:56:58 -0700411 template <typename T>
Austin Schuh01b4c352020-09-21 23:09:39 -0700412 void RemapLoggedChannel(std::string_view name, const Node *node,
413 std::string_view add_prefix = "/original") {
414 RemapLoggedChannel(name, T::GetFullyQualifiedName(), node, add_prefix);
415 }
416
417 template <typename T>
418 bool HasChannel(std::string_view name, const Node *node = nullptr) {
Brian Silvermande9f3ff2020-04-28 16:56:58 -0700419 return configuration::GetChannel(log_file_header()->configuration(), name,
420 T::GetFullyQualifiedName(), "",
Austin Schuh01b4c352020-09-21 23:09:39 -0700421 node) != nullptr;
Brian Silvermande9f3ff2020-04-28 16:56:58 -0700422 }
423
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800424 SimulatedEventLoopFactory *event_loop_factory() {
425 return event_loop_factory_;
426 }
427
Brian Silvermande9f3ff2020-04-28 16:56:58 -0700428 const LogFileHeader *log_file_header() const {
429 return &log_file_header_.message();
430 }
431
Austin Schuh0c297012020-09-16 18:41:59 -0700432 std::string_view name() const {
433 return log_file_header()->name()->string_view();
434 }
435
Austin Schuhe309d2a2019-11-29 13:25:21 -0800436 private:
Austin Schuh6f3babe2020-01-26 20:34:50 -0800437 const Channel *RemapChannel(const EventLoop *event_loop,
438 const Channel *channel);
439
Austin Schuhe309d2a2019-11-29 13:25:21 -0800440 // Queues at least max_out_of_order_duration_ messages into channels_.
441 void QueueMessages();
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800442 // Handle constructing a configuration with all the additional remapped
443 // channels from calls to RemapLoggedChannel.
444 void MakeRemappedConfig();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800445
Austin Schuh2f8fd752020-09-01 22:38:28 -0700446 // Returns the number of nodes.
447 size_t nodes_count() const {
448 return !configuration::MultiNode(logged_configuration())
449 ? 1u
450 : logged_configuration()->nodes()->size();
451 }
452
Austin Schuh6f3babe2020-01-26 20:34:50 -0800453 const std::vector<std::vector<std::string>> filenames_;
454
455 // This is *a* log file header used to provide the logged config. The rest of
456 // the header is likely distracting.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800457 SizePrefixedFlatbufferVector<LogFileHeader> log_file_header_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800458
Austin Schuh2f8fd752020-09-01 22:38:28 -0700459 // Returns [ta; tb; ...] = tuple[0] * t + tuple[1]
460 std::tuple<Eigen::Matrix<double, Eigen::Dynamic, 1>,
461 Eigen::Matrix<double, Eigen::Dynamic, 1>>
462 SolveOffsets();
463
464 void LogFit(std::string_view prefix);
Austin Schuh8bd96322020-02-13 21:18:22 -0800465
Austin Schuh6f3babe2020-01-26 20:34:50 -0800466 // State per node.
Austin Schuh858c9f32020-08-31 16:56:12 -0700467 class State {
468 public:
469 State(std::unique_ptr<ChannelMerger> channel_merger);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800470
Austin Schuh858c9f32020-08-31 16:56:12 -0700471 // Returns the timestamps, channel_index, and message from a channel.
472 // update_time (will be) set to true when popping this message causes the
473 // filter to change the time offset estimation function.
474 std::tuple<TimestampMerger::DeliveryTimestamp, int,
Austin Schuhadd6eb32020-11-09 21:24:26 -0800475 SizePrefixedFlatbufferVector<MessageHeader>>
Austin Schuh858c9f32020-08-31 16:56:12 -0700476 PopOldest(bool *update_time);
477
478 // Returns the monotonic time of the oldest message.
479 monotonic_clock::time_point OldestMessageTime() const;
480
481 // Primes the queues inside State. Should be called before calling
482 // OldestMessageTime.
483 void SeedSortedMessages();
Austin Schuh8bd96322020-02-13 21:18:22 -0800484
Austin Schuh858c9f32020-08-31 16:56:12 -0700485 // Returns the starting time for this node.
486 monotonic_clock::time_point monotonic_start_time() const {
487 return channel_merger_->monotonic_start_time();
488 }
489 realtime_clock::time_point realtime_start_time() const {
490 return channel_merger_->realtime_start_time();
491 }
492
493 // Sets the node event loop factory for replaying into a
494 // SimulatedEventLoopFactory. Returns the EventLoop to use.
495 EventLoop *SetNodeEventLoopFactory(
496 NodeEventLoopFactory *node_event_loop_factory);
497
498 // Sets and gets the event loop to use.
499 void set_event_loop(EventLoop *event_loop) { event_loop_ = event_loop; }
500 EventLoop *event_loop() { return event_loop_; }
501
Austin Schuh858c9f32020-08-31 16:56:12 -0700502 // Sets the current realtime offset from the monotonic clock for this node
503 // (if we are on a simulated event loop).
504 void SetRealtimeOffset(monotonic_clock::time_point monotonic_time,
505 realtime_clock::time_point realtime_time) {
506 if (node_event_loop_factory_ != nullptr) {
507 node_event_loop_factory_->SetRealtimeOffset(monotonic_time,
508 realtime_time);
509 }
510 }
511
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700512 // Returns the MessageHeader sender to log delivery timestamps to for the
513 // provided remote node.
514 aos::Sender<MessageHeader> *RemoteTimestampSender(
515 const Node *delivered_node);
516
Austin Schuh858c9f32020-08-31 16:56:12 -0700517 // Converts a timestamp from the monotonic clock on this node to the
518 // distributed clock.
519 distributed_clock::time_point ToDistributedClock(
520 monotonic_clock::time_point time) {
521 return node_event_loop_factory_->ToDistributedClock(time);
522 }
523
Austin Schuh2f8fd752020-09-01 22:38:28 -0700524 monotonic_clock::time_point FromDistributedClock(
525 distributed_clock::time_point time) {
526 return node_event_loop_factory_->FromDistributedClock(time);
527 }
528
Austin Schuh858c9f32020-08-31 16:56:12 -0700529 // Sets the offset (and slope) from the distributed clock.
530 void SetDistributedOffset(std::chrono::nanoseconds distributed_offset,
531 double distributed_slope) {
532 node_event_loop_factory_->SetDistributedOffset(distributed_offset,
533 distributed_slope);
534 }
535
536 // Returns the current time on the remote node which sends messages on
537 // channel_index.
538 monotonic_clock::time_point monotonic_remote_now(size_t channel_index) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700539 return channel_source_state_[channel_index]
540 ->node_event_loop_factory_->monotonic_now();
Austin Schuh858c9f32020-08-31 16:56:12 -0700541 }
542
Austin Schuh2f8fd752020-09-01 22:38:28 -0700543 distributed_clock::time_point RemoteToDistributedClock(
544 size_t channel_index, monotonic_clock::time_point time) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700545 return channel_source_state_[channel_index]
546 ->node_event_loop_factory_->ToDistributedClock(time);
Austin Schuh2f8fd752020-09-01 22:38:28 -0700547 }
548
549 const Node *remote_node(size_t channel_index) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700550 return channel_source_state_[channel_index]
551 ->node_event_loop_factory_->node();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700552 }
553
554 monotonic_clock::time_point monotonic_now() {
555 return node_event_loop_factory_->monotonic_now();
556 }
557
Austin Schuh858c9f32020-08-31 16:56:12 -0700558 // Sets the node we will be merging as, and returns true if there is any
559 // data on it.
560 bool SetNode() { return channel_merger_->SetNode(event_loop_->node()); }
561
562 // Sets the number of channels.
563 void SetChannelCount(size_t count);
564
565 // Sets the sender, filter, and target factory for a channel.
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700566 void SetChannel(size_t logged_channel_index, size_t factory_channel_index,
567 std::unique_ptr<RawSender> sender,
Austin Schuh2f8fd752020-09-01 22:38:28 -0700568 message_bridge::NoncausalOffsetEstimator *filter,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700569 aos::Sender<MessageHeader> *remote_timestamp_sender,
570 State *source_state);
Austin Schuh858c9f32020-08-31 16:56:12 -0700571
572 // Returns if we have read all the messages from all the logs.
573 bool at_end() const { return channel_merger_->at_end(); }
574
575 // Unregisters everything so we can destory the event loop.
576 void Deregister();
577
578 // Sets the current TimerHandle for the replay callback.
579 void set_timer_handler(TimerHandler *timer_handler) {
580 timer_handler_ = timer_handler;
581 }
582
583 // Sets the next wakeup time on the replay callback.
584 void Setup(monotonic_clock::time_point next_time) {
585 timer_handler_->Setup(next_time);
586 }
587
588 // Sends a buffer on the provided channel index.
589 bool Send(size_t channel_index, const void *data, size_t size,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700590 const TimestampMerger::DeliveryTimestamp &delivery_timestamp);
Austin Schuh858c9f32020-08-31 16:56:12 -0700591
592 // Returns a debug string for the channel merger.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700593 std::string DebugString() const {
594 std::stringstream messages;
595 size_t i = 0;
596 for (const auto &message : sorted_messages_) {
597 if (i < 7 || i + 7 > sorted_messages_.size()) {
598 messages << "sorted_messages[" << i
599 << "]: " << std::get<0>(message).monotonic_event_time << " "
600 << configuration::StrippedChannelToString(
601 event_loop_->configuration()->channels()->Get(
602 std::get<2>(message).message().channel_index()))
603 << "\n";
604 } else if (i == 7) {
605 messages << "...\n";
606 }
607 ++i;
608 }
609 return messages.str() + channel_merger_->DebugString();
610 }
Austin Schuh858c9f32020-08-31 16:56:12 -0700611
612 private:
613 // Log file.
614 std::unique_ptr<ChannelMerger> channel_merger_;
615
616 std::deque<std::tuple<TimestampMerger::DeliveryTimestamp, int,
Austin Schuhadd6eb32020-11-09 21:24:26 -0800617 SizePrefixedFlatbufferVector<MessageHeader>,
Austin Schuh2f8fd752020-09-01 22:38:28 -0700618 message_bridge::NoncausalOffsetEstimator *>>
Austin Schuh858c9f32020-08-31 16:56:12 -0700619 sorted_messages_;
620
621 // Senders.
622 std::vector<std::unique_ptr<RawSender>> channels_;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700623 std::vector<aos::Sender<MessageHeader> *> remote_timestamp_senders_;
624 // The mapping from logged channel index to sent channel index. Needed for
625 // sending out MessageHeaders.
626 std::vector<int> factory_channel_index_;
627
628 struct SentTimestamp {
629 monotonic_clock::time_point monotonic_event_time =
630 monotonic_clock::min_time;
631 realtime_clock::time_point realtime_event_time = realtime_clock::min_time;
632 uint32_t queue_index = 0xffffffff;
633
634 // The queue index that this message *actually* was sent with.
635 uint32_t actual_queue_index = 0xffffffff;
636 };
637
638 // Stores all the timestamps that have been sent on this channel. This is
639 // only done for channels which are forwarded and on the node which
640 // initially sends the message.
641 //
642 // TODO(austin): This whole concept is a hack. We should be able to
643 // associate state with the message as it gets sorted and recover it.
644 std::vector<std::unique_ptr<std::vector<SentTimestamp>>> queue_index_map_;
Austin Schuh858c9f32020-08-31 16:56:12 -0700645
646 // Factory (if we are in sim) that this loop was created on.
647 NodeEventLoopFactory *node_event_loop_factory_ = nullptr;
648 std::unique_ptr<EventLoop> event_loop_unique_ptr_;
649 // Event loop.
650 EventLoop *event_loop_ = nullptr;
651 // And timer used to send messages.
652 TimerHandler *timer_handler_;
653
Austin Schuh8bd96322020-02-13 21:18:22 -0800654 // Filters (or nullptr if it isn't a forwarded channel) for each channel.
655 // This corresponds to the object which is shared among all the channels
656 // going between 2 nodes. The second element in the tuple indicates if this
657 // is the primary direction or not.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700658 std::vector<message_bridge::NoncausalOffsetEstimator *> filters_;
Austin Schuh8bd96322020-02-13 21:18:22 -0800659
660 // List of NodeEventLoopFactorys (or nullptr if it isn't a forwarded
661 // channel) which correspond to the originating node.
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700662 std::vector<State *> channel_source_state_;
663
664 std::map<const Node *, aos::Sender<MessageHeader>>
665 remote_timestamp_senders_map_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800666 };
667
Austin Schuh8bd96322020-02-13 21:18:22 -0800668 // Node index -> State.
669 std::vector<std::unique_ptr<State>> states_;
670
671 // Creates the requested filter if it doesn't exist, regardless of whether
672 // these nodes can actually communicate directly. The second return value
673 // reports if this is the primary direction or not.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700674 message_bridge::NoncausalOffsetEstimator *GetFilter(const Node *node_a,
675 const Node *node_b);
Austin Schuh8bd96322020-02-13 21:18:22 -0800676
677 // FILE to write offsets to (if populated).
678 FILE *offset_fp_ = nullptr;
679 // Timestamp of the first piece of data used for the horizontal axis on the
680 // plot.
681 aos::realtime_clock::time_point first_time_;
682
683 // List of filters for a connection. The pointer to the first node will be
684 // less than the second node.
685 std::map<std::tuple<const Node *, const Node *>,
Austin Schuh2f8fd752020-09-01 22:38:28 -0700686 std::tuple<message_bridge::NoncausalOffsetEstimator>>
Austin Schuh8bd96322020-02-13 21:18:22 -0800687 filters_;
688
689 // Returns the offset from the monotonic clock for a node to the distributed
Austin Schuh2f8fd752020-09-01 22:38:28 -0700690 // clock. monotonic = distributed * slope() + offset();
691 double slope(int node_index) const {
692 CHECK_LT(node_index, time_slope_matrix_.rows())
James Kuszmaul46d82582020-05-09 19:50:09 -0700693 << ": Got too high of a node index.";
Austin Schuh2f8fd752020-09-01 22:38:28 -0700694 return time_slope_matrix_(node_index);
695 }
696 std::chrono::nanoseconds offset(int node_index) const {
697 CHECK_LT(node_index, time_offset_matrix_.rows())
698 << ": Got too high of a node index.";
699 return std::chrono::duration_cast<std::chrono::nanoseconds>(
700 std::chrono::duration<double>(time_offset_matrix_(node_index)));
Austin Schuh8bd96322020-02-13 21:18:22 -0800701 }
702
703 // Updates the offset matrix solution and sets the per-node distributed
704 // offsets in the factory.
705 void UpdateOffsets();
706
Austin Schuh2f8fd752020-09-01 22:38:28 -0700707 // We have 2 types of equations to do a least squares regression over to fully
708 // constrain our time function.
709 //
710 // One is simple. The distributed clock is the average of all the clocks.
Brian Silverman87ac0402020-09-17 14:47:01 -0700711 // (ta + tb + tc + td) / num_nodes = t_distributed
Austin Schuh2f8fd752020-09-01 22:38:28 -0700712 //
713 // The second is a bit more complicated. Our basic time conversion function
714 // is:
715 // tb = ta + (ta * slope + offset)
716 // We can rewrite this as follows
717 // tb - (1 + slope) * ta = offset
718 //
719 // From here, we have enough equations to solve for t{a,b,c,...} We want to
720 // take as an input the offsets and slope, and solve for the per-node times as
721 // a function of the distributed clock.
722 //
723 // We need to massage our equations to make this work. If we solve for the
724 // per-node times at two set distributed clock times, we will be able to
725 // recreate the linear function (we know it is linear). We can do a similar
726 // thing by breaking our equation up into:
Brian Silverman87ac0402020-09-17 14:47:01 -0700727 //
Austin Schuh2f8fd752020-09-01 22:38:28 -0700728 // [1/3 1/3 1/3 ] [ta] [t_distributed]
729 // [ 1 -1-m1 0 ] [tb] = [oab]
730 // [ 1 0 -1-m2 ] [tc] [oac]
731 //
732 // This solves to:
733 //
734 // [ta] [ a00 a01 a02] [t_distributed]
735 // [tb] = [ a10 a11 a12] * [oab]
736 // [tc] [ a20 a21 a22] [oac]
737 //
738 // and can be split into:
739 //
740 // [ta] [ a00 ] [a01 a02]
741 // [tb] = [ a10 ] * t_distributed + [a11 a12] * [oab]
742 // [tc] [ a20 ] [a21 a22] [oac]
743 //
744 // (map_matrix_ + slope_matrix_) * [ta; tb; tc] = [offset_matrix_];
745 // offset_matrix_ will be in nanoseconds.
746 Eigen::Matrix<mpq_class, Eigen::Dynamic, Eigen::Dynamic> map_matrix_;
747 Eigen::Matrix<mpq_class, Eigen::Dynamic, Eigen::Dynamic> slope_matrix_;
748 Eigen::Matrix<mpq_class, Eigen::Dynamic, 1> offset_matrix_;
749 // Matrix tracking which offsets are valid.
750 Eigen::Matrix<bool, Eigen::Dynamic, 1> valid_matrix_;
751 // Matrix tracking the last valid matrix we used to determine connected nodes.
752 Eigen::Matrix<bool, Eigen::Dynamic, 1> last_valid_matrix_;
753 size_t cached_valid_node_count_ = 0;
Austin Schuh8bd96322020-02-13 21:18:22 -0800754
Austin Schuh2f8fd752020-09-01 22:38:28 -0700755 // [ta; tb; tc] = time_slope_matrix_ * t + time_offset_matrix;
756 // t is in seconds.
757 Eigen::Matrix<double, Eigen::Dynamic, 1> time_slope_matrix_;
758 Eigen::Matrix<double, Eigen::Dynamic, 1> time_offset_matrix_;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800759
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800760 std::unique_ptr<FlatbufferDetachedBuffer<Configuration>>
761 remapped_configuration_buffer_;
762
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800763 std::unique_ptr<SimulatedEventLoopFactory> event_loop_factory_unique_ptr_;
764 SimulatedEventLoopFactory *event_loop_factory_ = nullptr;
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800765
766 // Map of channel indices to new name. The channel index will be an index into
767 // logged_configuration(), and the string key will be the name of the channel
768 // to send on instead of the logged channel name.
769 std::map<size_t, std::string> remapped_channels_;
Austin Schuh01b4c352020-09-21 23:09:39 -0700770 std::vector<MapT> maps_;
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800771
Austin Schuh6f3babe2020-01-26 20:34:50 -0800772 // Number of nodes which still have data to send. This is used to figure out
773 // when to exit.
774 size_t live_nodes_ = 0;
775
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800776 const Configuration *remapped_configuration_ = nullptr;
777 const Configuration *replay_configuration_ = nullptr;
Austin Schuhcde938c2020-02-02 17:30:07 -0800778
779 // If true, the replay timer will ignore any missing data. This is used
780 // during startup when we are bootstrapping everything and trying to get to
781 // the start of all the log files.
782 bool ignore_missing_data_ = false;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800783};
784
785} // namespace logger
786} // namespace aos
787
788#endif // AOS_EVENTS_LOGGER_H_