Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 1 | #ifndef AOS_EVENTS_LOGGER_H_ |
| 2 | #define AOS_EVENTS_LOGGER_H_ |
| 3 | |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 4 | #include <chrono> |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 5 | #include <deque> |
Austin Schuh | 05b7047 | 2020-01-01 17:11:17 -0800 | [diff] [blame] | 6 | #include <string_view> |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 7 | #include <tuple> |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 8 | #include <vector> |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 9 | |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 10 | #include "Eigen/Dense" |
| 11 | #include "absl/strings/str_cat.h" |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 12 | #include "absl/types/span.h" |
| 13 | #include "aos/events/event_loop.h" |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 14 | #include "aos/events/logging/eigen_mpq.h" |
Austin Schuh | cb5601b | 2020-09-10 15:29:59 -0700 | [diff] [blame] | 15 | #include "aos/events/logging/log_namer.h" |
Austin Schuh | f6f9bf3 | 2020-10-11 14:37:43 -0700 | [diff] [blame] | 16 | #include "aos/events/logging/logfile_sorting.h" |
Austin Schuh | a36c890 | 2019-12-30 18:07:15 -0800 | [diff] [blame] | 17 | #include "aos/events/logging/logfile_utils.h" |
James Kuszmaul | 38735e8 | 2019-12-07 16:42:06 -0800 | [diff] [blame] | 18 | #include "aos/events/logging/logger_generated.h" |
Austin Schuh | 64fab80 | 2020-09-09 22:47:47 -0700 | [diff] [blame] | 19 | #include "aos/events/logging/uuid.h" |
Austin Schuh | 9254752 | 2019-12-28 14:33:43 -0800 | [diff] [blame] | 20 | #include "aos/events/simulated_event_loop.h" |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 21 | #include "aos/network/message_bridge_server_generated.h" |
Austin Schuh | 0ca1fd3 | 2020-12-18 22:53:05 -0800 | [diff] [blame] | 22 | #include "aos/network/multinode_timestamp_filter.h" |
Austin Schuh | 0de30f3 | 2020-12-06 12:44:28 -0800 | [diff] [blame] | 23 | #include "aos/network/remote_message_generated.h" |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 24 | #include "aos/network/timestamp_filter.h" |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 25 | #include "aos/time/time.h" |
| 26 | #include "flatbuffers/flatbuffers.h" |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 27 | #include "third_party/gmp/gmpxx.h" |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 28 | |
| 29 | namespace aos { |
| 30 | namespace logger { |
| 31 | |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 32 | // Logs all channels available in the event loop to disk every 100 ms. |
| 33 | // Start by logging one message per channel to capture any state and |
| 34 | // configuration that is sent rately on a channel and would affect execution. |
| 35 | class Logger { |
| 36 | public: |
Austin Schuh | 0c29701 | 2020-09-16 18:41:59 -0700 | [diff] [blame] | 37 | // Constructs a logger. |
Austin Schuh | 0c29701 | 2020-09-16 18:41:59 -0700 | [diff] [blame] | 38 | // event_loop: The event loop used to read the messages. |
Austin Schuh | 0c29701 | 2020-09-16 18:41:59 -0700 | [diff] [blame] | 39 | // configuration: When provided, this is the configuration to log, and the |
| 40 | // configuration to use for the channel list to log. If not provided, |
| 41 | // this becomes the configuration from the event loop. |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 42 | // should_log: When provided, a filter for channels to log. If not provided, |
| 43 | // all available channels are logged. |
| 44 | Logger(EventLoop *event_loop) |
| 45 | : Logger(event_loop, event_loop->configuration()) {} |
| 46 | Logger(EventLoop *event_loop, const Configuration *configuration) |
| 47 | : Logger(event_loop, configuration, |
| 48 | [](const Channel *) { return true; }) {} |
| 49 | Logger(EventLoop *event_loop, const Configuration *configuration, |
| 50 | std::function<bool(const Channel *)> should_log); |
Austin Schuh | 0c29701 | 2020-09-16 18:41:59 -0700 | [diff] [blame] | 51 | ~Logger(); |
| 52 | |
| 53 | // Overrides the name in the log file header. |
| 54 | void set_name(std::string_view name) { name_ = name; } |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 55 | |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 56 | // Sets the callback to run after each period of data is logged. Defaults to |
| 57 | // doing nothing. |
| 58 | // |
| 59 | // This callback may safely do things like call Rotate(). |
| 60 | void set_on_logged_period(std::function<void()> on_logged_period) { |
| 61 | on_logged_period_ = std::move(on_logged_period); |
| 62 | } |
| 63 | |
Austin Schuh | 8c39996 | 2020-12-25 21:51:45 -0800 | [diff] [blame] | 64 | void set_separate_config(bool separate_config) { |
| 65 | separate_config_ = separate_config; |
| 66 | } |
| 67 | |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 68 | // Sets the period between polling the data. Defaults to 100ms. |
| 69 | // |
| 70 | // Changing this while a set of files is being written may result in |
| 71 | // unreadable files. |
| 72 | void set_polling_period(std::chrono::nanoseconds polling_period) { |
| 73 | polling_period_ = polling_period; |
| 74 | } |
| 75 | |
Brian Silverman | ae7c033 | 2020-09-30 16:58:23 -0700 | [diff] [blame] | 76 | std::string_view log_start_uuid() const { return log_start_uuid_; } |
Brian Silverman | 035e418 | 2020-10-06 17:13:00 -0700 | [diff] [blame] | 77 | UUID logger_instance_uuid() const { return logger_instance_uuid_; } |
Brian Silverman | ae7c033 | 2020-09-30 16:58:23 -0700 | [diff] [blame] | 78 | |
Brian Silverman | cb80582 | 2020-10-06 17:43:35 -0700 | [diff] [blame] | 79 | // The maximum time for a single fetch which returned a message, or 0 if none |
| 80 | // of those have happened. |
| 81 | std::chrono::nanoseconds max_message_fetch_time() const { |
| 82 | return max_message_fetch_time_; |
| 83 | } |
| 84 | // The channel for that longest fetch which returned a message, or -1 if none |
| 85 | // of those have happened. |
| 86 | int max_message_fetch_time_channel() const { |
| 87 | return max_message_fetch_time_channel_; |
| 88 | } |
| 89 | // The size of the message returned by that longest fetch, or -1 if none of |
| 90 | // those have happened. |
| 91 | int max_message_fetch_time_size() const { |
| 92 | return max_message_fetch_time_size_; |
| 93 | } |
| 94 | // The total time spent fetching messages. |
| 95 | std::chrono::nanoseconds total_message_fetch_time() const { |
| 96 | return total_message_fetch_time_; |
| 97 | } |
| 98 | // The total number of fetch calls which returned messages. |
| 99 | int total_message_fetch_count() const { return total_message_fetch_count_; } |
| 100 | // The total number of bytes fetched. |
| 101 | int64_t total_message_fetch_bytes() const { |
| 102 | return total_message_fetch_bytes_; |
| 103 | } |
| 104 | |
| 105 | // The total time spent in fetches which did not return a message. |
| 106 | std::chrono::nanoseconds total_nop_fetch_time() const { |
| 107 | return total_nop_fetch_time_; |
| 108 | } |
| 109 | // The total number of fetches which did not return a message. |
| 110 | int total_nop_fetch_count() const { return total_nop_fetch_count_; } |
| 111 | |
| 112 | // The maximum time for a single copy, or 0 if none of those have happened. |
| 113 | std::chrono::nanoseconds max_copy_time() const { return max_copy_time_; } |
| 114 | // The channel for that longest copy, or -1 if none of those have happened. |
| 115 | int max_copy_time_channel() const { return max_copy_time_channel_; } |
| 116 | // The size of the message for that longest copy, or -1 if none of those have |
| 117 | // happened. |
| 118 | int max_copy_time_size() const { return max_copy_time_size_; } |
| 119 | // The total time spent copying messages. |
| 120 | std::chrono::nanoseconds total_copy_time() const { return total_copy_time_; } |
| 121 | // The total number of messages copied. |
| 122 | int total_copy_count() const { return total_copy_count_; } |
| 123 | // The total number of bytes copied. |
| 124 | int64_t total_copy_bytes() const { return total_copy_bytes_; } |
| 125 | |
| 126 | void ResetStatisics(); |
| 127 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 128 | // Rotates the log file(s), triggering new part files to be written for each |
| 129 | // log file. |
| 130 | void Rotate(); |
Austin Schuh | fa89589 | 2020-01-07 20:07:41 -0800 | [diff] [blame] | 131 | |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 132 | // Starts logging to files with the given naming scheme. |
Brian Silverman | ae7c033 | 2020-09-30 16:58:23 -0700 | [diff] [blame] | 133 | // |
| 134 | // log_start_uuid may be used to tie this log event to other log events across |
| 135 | // multiple nodes. The default (empty string) indicates there isn't one |
| 136 | // available. |
| 137 | void StartLogging(std::unique_ptr<LogNamer> log_namer, |
| 138 | std::string_view log_start_uuid = ""); |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 139 | |
| 140 | // Stops logging. Ensures any messages through end_time make it into the log. |
| 141 | // |
| 142 | // If you want to stop ASAP, pass min_time to avoid reading any more messages. |
| 143 | // |
| 144 | // Returns the LogNamer in case the caller wants to do anything else with it |
| 145 | // before destroying it. |
| 146 | std::unique_ptr<LogNamer> StopLogging( |
| 147 | aos::monotonic_clock::time_point end_time); |
| 148 | |
| 149 | // Returns whether a log is currently being written. |
| 150 | bool is_started() const { return static_cast<bool>(log_namer_); } |
| 151 | |
| 152 | // Shortcut to call StartLogging with a LocalLogNamer when event processing |
| 153 | // starts. |
| 154 | void StartLoggingLocalNamerOnRun(std::string base_name) { |
| 155 | event_loop_->OnRun([this, base_name]() { |
| 156 | StartLogging( |
| 157 | std::make_unique<LocalLogNamer>(base_name, event_loop_->node())); |
| 158 | }); |
| 159 | } |
| 160 | |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 161 | private: |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 162 | // Structure to track both a fetcher, and if the data fetched has been |
| 163 | // written. We may want to delay writing data to disk so that we don't let |
| 164 | // data get too far out of order when written to disk so we can avoid making |
| 165 | // it too hard to sort when reading. |
| 166 | struct FetcherStruct { |
| 167 | std::unique_ptr<RawFetcher> fetcher; |
| 168 | bool written = false; |
Austin Schuh | 15649d6 | 2019-12-28 16:36:38 -0800 | [diff] [blame] | 169 | |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 170 | // Channel index to log to. |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 171 | int channel_index = -1; |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 172 | const Channel *channel = nullptr; |
| 173 | const Node *timestamp_node = nullptr; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 174 | |
| 175 | LogType log_type = LogType::kLogMessage; |
| 176 | |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 177 | // We fill out the metadata at construction, but the actual writers have to |
| 178 | // be updated each time we start logging. To avoid duplicating the complex |
| 179 | // logic determining whether each writer should be initialized, we just |
| 180 | // stash the answer in separate member variables. |
| 181 | bool wants_writer = false; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 182 | DetachedBufferWriter *writer = nullptr; |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 183 | bool wants_timestamp_writer = false; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 184 | DetachedBufferWriter *timestamp_writer = nullptr; |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 185 | bool wants_contents_writer = false; |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 186 | DetachedBufferWriter *contents_writer = nullptr; |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 187 | |
Austin Schuh | 315b96b | 2020-12-11 21:21:12 -0800 | [diff] [blame] | 188 | // Node which this data is from, or -1 if it is unknown. |
| 189 | int data_node_index = -1; |
| 190 | // Node that this timestamp is for, or -1 if it is known. |
| 191 | int timestamp_node_index = -1; |
| 192 | // Node that the contents this contents_writer will log are from. |
| 193 | int contents_node_index = -1; |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 194 | }; |
| 195 | |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 196 | // Vector mapping from the channel index from the event loop to the logged |
| 197 | // channel index. |
| 198 | std::vector<int> event_loop_to_logged_channel_index_; |
| 199 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 200 | struct NodeState { |
| 201 | aos::monotonic_clock::time_point monotonic_start_time = |
| 202 | aos::monotonic_clock::min_time; |
| 203 | aos::realtime_clock::time_point realtime_start_time = |
| 204 | aos::realtime_clock::min_time; |
| 205 | |
Austin Schuh | 315b96b | 2020-12-11 21:21:12 -0800 | [diff] [blame] | 206 | bool has_source_node_boot_uuid = false; |
| 207 | |
| 208 | // This is an initial UUID that is a valid UUID4 and is pretty obvious that |
| 209 | // it isn't valid. |
| 210 | std::string source_node_boot_uuid = "00000000-0000-4000-8000-000000000000"; |
| 211 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 212 | aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> log_file_header = |
| 213 | aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader>::Empty(); |
Austin Schuh | 315b96b | 2020-12-11 21:21:12 -0800 | [diff] [blame] | 214 | |
| 215 | // True if a header has been written to the start of a log file. |
| 216 | bool header_written = false; |
| 217 | // True if the current written header represents the contents which will |
| 218 | // follow. This is cleared when boot_uuid is known to not match anymore. |
| 219 | bool header_valid = false; |
| 220 | |
| 221 | // Sets the source_node_boot_uuid, properly updating everything. |
| 222 | void SetBootUUID(std::string_view new_source_node_boot_uuid) { |
| 223 | source_node_boot_uuid = new_source_node_boot_uuid; |
| 224 | header_valid = false; |
| 225 | has_source_node_boot_uuid = true; |
| 226 | |
| 227 | flatbuffers::String *source_node_boot_uuid_string = |
| 228 | log_file_header.mutable_message()->mutable_source_node_boot_uuid(); |
| 229 | CHECK_EQ(source_node_boot_uuid.size(), |
| 230 | source_node_boot_uuid_string->size()); |
| 231 | memcpy(source_node_boot_uuid_string->data(), source_node_boot_uuid.data(), |
| 232 | source_node_boot_uuid.size()); |
| 233 | } |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 234 | }; |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 235 | |
| 236 | void WriteHeader(); |
Austin Schuh | 315b96b | 2020-12-11 21:21:12 -0800 | [diff] [blame] | 237 | |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 238 | aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> MakeHeader( |
Austin Schuh | 8c39996 | 2020-12-25 21:51:45 -0800 | [diff] [blame] | 239 | const Node *node, std::string_view config_sha256); |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 240 | |
Austin Schuh | 315b96b | 2020-12-11 21:21:12 -0800 | [diff] [blame] | 241 | // Writes the header for the provided node if enough information is valid. |
| 242 | void MaybeWriteHeader(int node_index); |
| 243 | // Overload for when we already know node as well. |
| 244 | void MaybeWriteHeader(int node_index, const Node *node); |
| 245 | |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 246 | bool MaybeUpdateTimestamp( |
| 247 | const Node *node, int node_index, |
| 248 | aos::monotonic_clock::time_point monotonic_start_time, |
| 249 | aos::realtime_clock::time_point realtime_start_time); |
| 250 | |
| 251 | void DoLogData(const monotonic_clock::time_point end_time); |
| 252 | |
| 253 | void WriteMissingTimestamps(); |
| 254 | |
| 255 | // Fetches from each channel until all the data is logged. |
| 256 | void LogUntil(monotonic_clock::time_point t); |
| 257 | |
Brian Silverman | cb80582 | 2020-10-06 17:43:35 -0700 | [diff] [blame] | 258 | void RecordFetchResult(aos::monotonic_clock::time_point start, |
| 259 | aos::monotonic_clock::time_point end, bool got_new, |
| 260 | FetcherStruct *fetcher); |
| 261 | |
| 262 | void RecordCreateMessageTime(aos::monotonic_clock::time_point start, |
| 263 | aos::monotonic_clock::time_point end, |
| 264 | FetcherStruct *fetcher); |
| 265 | |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 266 | // Sets the start time for a specific node. |
Austin Schuh | 315b96b | 2020-12-11 21:21:12 -0800 | [diff] [blame] | 267 | void SetStartTime( |
| 268 | size_t node_index, aos::monotonic_clock::time_point monotonic_start_time, |
| 269 | aos::realtime_clock::time_point realtime_start_time, |
| 270 | aos::monotonic_clock::time_point logger_monotonic_start_time, |
| 271 | aos::realtime_clock::time_point logger_realtime_start_time); |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 272 | |
Brian Silverman | ae7c033 | 2020-09-30 16:58:23 -0700 | [diff] [blame] | 273 | EventLoop *const event_loop_; |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 274 | // The configuration to place at the top of the log file. |
| 275 | const Configuration *const configuration_; |
| 276 | |
Brian Silverman | ae7c033 | 2020-09-30 16:58:23 -0700 | [diff] [blame] | 277 | UUID log_event_uuid_ = UUID::Zero(); |
| 278 | const UUID logger_instance_uuid_ = UUID::Random(); |
| 279 | std::unique_ptr<LogNamer> log_namer_; |
| 280 | // Empty indicates there isn't one. |
| 281 | std::string log_start_uuid_; |
Brian Silverman | ae7c033 | 2020-09-30 16:58:23 -0700 | [diff] [blame] | 282 | |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 283 | // Name to save in the log file. Defaults to hostname. |
| 284 | std::string name_; |
| 285 | |
| 286 | std::function<void()> on_logged_period_ = []() {}; |
| 287 | |
Brian Silverman | cb80582 | 2020-10-06 17:43:35 -0700 | [diff] [blame] | 288 | std::chrono::nanoseconds max_message_fetch_time_ = |
| 289 | std::chrono::nanoseconds::zero(); |
| 290 | int max_message_fetch_time_channel_ = -1; |
| 291 | int max_message_fetch_time_size_ = -1; |
| 292 | std::chrono::nanoseconds total_message_fetch_time_ = |
| 293 | std::chrono::nanoseconds::zero(); |
| 294 | int total_message_fetch_count_ = 0; |
| 295 | int64_t total_message_fetch_bytes_ = 0; |
| 296 | |
| 297 | std::chrono::nanoseconds total_nop_fetch_time_ = |
| 298 | std::chrono::nanoseconds::zero(); |
| 299 | int total_nop_fetch_count_ = 0; |
| 300 | |
| 301 | std::chrono::nanoseconds max_copy_time_ = std::chrono::nanoseconds::zero(); |
| 302 | int max_copy_time_channel_ = -1; |
| 303 | int max_copy_time_size_ = -1; |
| 304 | std::chrono::nanoseconds total_copy_time_ = std::chrono::nanoseconds::zero(); |
| 305 | int total_copy_count_ = 0; |
| 306 | int64_t total_copy_bytes_ = 0; |
| 307 | |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 308 | std::vector<FetcherStruct> fetchers_; |
| 309 | TimerHandler *timer_handler_; |
| 310 | |
| 311 | // Period to poll the channels. |
| 312 | std::chrono::nanoseconds polling_period_ = std::chrono::milliseconds(100); |
| 313 | |
| 314 | // Last time that data was written for all channels to disk. |
| 315 | monotonic_clock::time_point last_synchronized_time_; |
| 316 | |
| 317 | // Max size that the header has consumed. This much extra data will be |
| 318 | // reserved in the builder to avoid reallocating. |
| 319 | size_t max_header_size_ = 0; |
| 320 | |
Austin Schuh | 8c39996 | 2020-12-25 21:51:45 -0800 | [diff] [blame] | 321 | // If true, write the message header into a separate file. |
| 322 | bool separate_config_ = true; |
| 323 | |
Brian Silverman | 1f34522 | 2020-09-24 21:14:48 -0700 | [diff] [blame] | 324 | // Fetcher for all the statistics from all the nodes. |
| 325 | aos::Fetcher<message_bridge::ServerStatistics> server_statistics_fetcher_; |
| 326 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 327 | std::vector<NodeState> node_state_; |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 328 | }; |
| 329 | |
Austin Schuh | 11d4373 | 2020-09-21 17:28:30 -0700 | [diff] [blame] | 330 | std::vector<std::vector<std::string>> ToLogReaderVector( |
| 331 | const std::vector<LogFile> &log_files); |
Austin Schuh | 5212cad | 2020-09-09 23:12:09 -0700 | [diff] [blame] | 332 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 333 | // We end up with one of the following 3 log file types. |
| 334 | // |
| 335 | // Single node logged as the source node. |
| 336 | // -> Replayed just on the source node. |
| 337 | // |
| 338 | // Forwarding timestamps only logged from the perspective of the destination |
| 339 | // node. |
| 340 | // -> Matched with data on source node and logged. |
| 341 | // |
| 342 | // Forwarding timestamps with data logged as the destination node. |
| 343 | // -> Replayed just as the destination |
| 344 | // -> Replayed as the source (Much harder, ordering is not defined) |
| 345 | // |
| 346 | // Duplicate data logged. -> CHECK that it matches and explode otherwise. |
| 347 | // |
| 348 | // This can be boiled down to a set of constraints and tools. |
| 349 | // |
| 350 | // 1) Forwarding timestamps and data need to be logged separately. |
| 351 | // 2) Any forwarded data logged on the destination node needs to be logged |
| 352 | // separately such that it can be sorted. |
| 353 | // |
| 354 | // 1) Log reader needs to be able to sort a list of log files. |
| 355 | // 2) Log reader needs to be able to merge sorted lists of log files. |
| 356 | // 3) Log reader needs to be able to match timestamps with messages. |
| 357 | // |
| 358 | // We also need to be able to generate multiple views of a log file depending on |
| 359 | // the target. |
| 360 | |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 361 | // Replays all the channels in the logfile to the event loop. |
| 362 | class LogReader { |
| 363 | public: |
James Kuszmaul | c7bbb3e | 2020-01-03 20:01:00 -0800 | [diff] [blame] | 364 | // If you want to supply a new configuration that will be used for replay |
| 365 | // (e.g., to change message rates, or to populate an updated schema), then |
| 366 | // pass it in here. It must provide all the channels that the original logged |
| 367 | // config did. |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 368 | // |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 369 | // The single file constructor calls SortParts internally. |
James Kuszmaul | c7bbb3e | 2020-01-03 20:01:00 -0800 | [diff] [blame] | 370 | LogReader(std::string_view filename, |
| 371 | const Configuration *replay_configuration = nullptr); |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 372 | LogReader(std::vector<LogFile> log_files, |
Austin Schuh | 11d4373 | 2020-09-21 17:28:30 -0700 | [diff] [blame] | 373 | const Configuration *replay_configuration = nullptr); |
James Kuszmaul | 7daef36 | 2019-12-31 18:28:17 -0800 | [diff] [blame] | 374 | ~LogReader(); |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 375 | |
Austin Schuh | 6331ef9 | 2020-01-07 18:28:09 -0800 | [diff] [blame] | 376 | // Registers all the callbacks to send the log file data out on an event loop |
| 377 | // created in event_loop_factory. This also updates time to be at the start |
| 378 | // of the log file by running until the log file starts. |
| 379 | // Note: the configuration used in the factory should be configuration() |
| 380 | // below, but can be anything as long as the locations needed to send |
| 381 | // everything are available. |
James Kuszmaul | 84ff3e5 | 2020-01-03 19:48:53 -0800 | [diff] [blame] | 382 | void Register(SimulatedEventLoopFactory *event_loop_factory); |
Austin Schuh | 6331ef9 | 2020-01-07 18:28:09 -0800 | [diff] [blame] | 383 | // Creates an SimulatedEventLoopFactory accessible via event_loop_factory(), |
| 384 | // and then calls Register. |
| 385 | void Register(); |
| 386 | // Registers callbacks for all the events after the log file starts. This is |
| 387 | // only useful when replaying live. |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 388 | void Register(EventLoop *event_loop); |
Austin Schuh | 6331ef9 | 2020-01-07 18:28:09 -0800 | [diff] [blame] | 389 | |
James Kuszmaul | 84ff3e5 | 2020-01-03 19:48:53 -0800 | [diff] [blame] | 390 | // Unregisters the senders. You only need to call this if you separately |
| 391 | // supplied an event loop or event loop factory and the lifetimes are such |
| 392 | // that they need to be explicitly destroyed before the LogReader destructor |
| 393 | // gets called. |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 394 | void Deregister(); |
| 395 | |
Austin Schuh | 0c29701 | 2020-09-16 18:41:59 -0700 | [diff] [blame] | 396 | // Returns the configuration being used for replay from the log file. |
| 397 | // Note that this may be different from the configuration actually used for |
| 398 | // handling events. You should generally only use this to create a |
| 399 | // SimulatedEventLoopFactory, and then get the configuration from there for |
| 400 | // everything else. |
James Kuszmaul | c7bbb3e | 2020-01-03 20:01:00 -0800 | [diff] [blame] | 401 | const Configuration *logged_configuration() const; |
Austin Schuh | 11d4373 | 2020-09-21 17:28:30 -0700 | [diff] [blame] | 402 | // Returns the configuration being used for replay from the log file. |
| 403 | // Note that this may be different from the configuration actually used for |
| 404 | // handling events. You should generally only use this to create a |
| 405 | // SimulatedEventLoopFactory, and then get the configuration from there for |
| 406 | // everything else. |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 407 | // The pointer is invalidated whenever RemapLoggedChannel is called. |
Austin Schuh | 15649d6 | 2019-12-28 16:36:38 -0800 | [diff] [blame] | 408 | const Configuration *configuration() const; |
| 409 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 410 | // Returns the nodes that this log file was created on. This is a list of |
| 411 | // pointers to a node in the nodes() list inside configuration(). The |
| 412 | // pointers here are invalidated whenever RemapLoggedChannel is called. |
| 413 | std::vector<const Node *> Nodes() const; |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 414 | |
| 415 | // Returns the starting timestamp for the log file. |
Austin Schuh | 11d4373 | 2020-09-21 17:28:30 -0700 | [diff] [blame] | 416 | monotonic_clock::time_point monotonic_start_time( |
| 417 | const Node *node = nullptr) const; |
| 418 | realtime_clock::time_point realtime_start_time( |
| 419 | const Node *node = nullptr) const; |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 420 | |
James Kuszmaul | c7bbb3e | 2020-01-03 20:01:00 -0800 | [diff] [blame] | 421 | // Causes the logger to publish the provided channel on a different name so |
| 422 | // that replayed applications can publish on the proper channel name without |
| 423 | // interference. This operates on raw channel names, without any node or |
| 424 | // application specific mappings. |
| 425 | void RemapLoggedChannel(std::string_view name, std::string_view type, |
Austin Schuh | 0de30f3 | 2020-12-06 12:44:28 -0800 | [diff] [blame] | 426 | std::string_view add_prefix = "/original", |
| 427 | std::string_view new_type = ""); |
James Kuszmaul | c7bbb3e | 2020-01-03 20:01:00 -0800 | [diff] [blame] | 428 | template <typename T> |
| 429 | void RemapLoggedChannel(std::string_view name, |
Austin Schuh | 0de30f3 | 2020-12-06 12:44:28 -0800 | [diff] [blame] | 430 | std::string_view add_prefix = "/original", |
| 431 | std::string_view new_type = "") { |
| 432 | RemapLoggedChannel(name, T::GetFullyQualifiedName(), add_prefix, new_type); |
James Kuszmaul | c7bbb3e | 2020-01-03 20:01:00 -0800 | [diff] [blame] | 433 | } |
| 434 | |
Austin Schuh | 01b4c35 | 2020-09-21 23:09:39 -0700 | [diff] [blame] | 435 | // Remaps the provided channel, though this respects node mappings, and |
| 436 | // preserves them too. This makes it so if /aos -> /pi1/aos on one node, |
| 437 | // /original/aos -> /original/pi1/aos on the same node after renaming, just |
Austin Schuh | 0de30f3 | 2020-12-06 12:44:28 -0800 | [diff] [blame] | 438 | // like you would hope. If new_type is not empty, the new channel will use |
| 439 | // the provided type instead. This allows for renaming messages. |
Austin Schuh | 01b4c35 | 2020-09-21 23:09:39 -0700 | [diff] [blame] | 440 | // |
| 441 | // TODO(austin): If you have 2 nodes remapping something to the same channel, |
| 442 | // this doesn't handle that. No use cases exist yet for that, so it isn't |
| 443 | // being done yet. |
| 444 | void RemapLoggedChannel(std::string_view name, std::string_view type, |
| 445 | const Node *node, |
Austin Schuh | 0de30f3 | 2020-12-06 12:44:28 -0800 | [diff] [blame] | 446 | std::string_view add_prefix = "/original", |
| 447 | std::string_view new_type = ""); |
Brian Silverman | de9f3ff | 2020-04-28 16:56:58 -0700 | [diff] [blame] | 448 | template <typename T> |
Austin Schuh | 01b4c35 | 2020-09-21 23:09:39 -0700 | [diff] [blame] | 449 | void RemapLoggedChannel(std::string_view name, const Node *node, |
Austin Schuh | 0de30f3 | 2020-12-06 12:44:28 -0800 | [diff] [blame] | 450 | std::string_view add_prefix = "/original", |
| 451 | std::string_view new_type = "") { |
| 452 | RemapLoggedChannel(name, T::GetFullyQualifiedName(), node, add_prefix, |
| 453 | new_type); |
Austin Schuh | 01b4c35 | 2020-09-21 23:09:39 -0700 | [diff] [blame] | 454 | } |
| 455 | |
| 456 | template <typename T> |
| 457 | bool HasChannel(std::string_view name, const Node *node = nullptr) { |
Austin Schuh | 0ca51f3 | 2020-12-25 21:51:45 -0800 | [diff] [blame] | 458 | return configuration::GetChannel(logged_configuration(), name, |
Austin Schuh | 0de30f3 | 2020-12-06 12:44:28 -0800 | [diff] [blame] | 459 | T::GetFullyQualifiedName(), "", node, |
| 460 | true) != nullptr; |
Brian Silverman | de9f3ff | 2020-04-28 16:56:58 -0700 | [diff] [blame] | 461 | } |
| 462 | |
James Kuszmaul | 84ff3e5 | 2020-01-03 19:48:53 -0800 | [diff] [blame] | 463 | SimulatedEventLoopFactory *event_loop_factory() { |
| 464 | return event_loop_factory_; |
| 465 | } |
| 466 | |
Austin Schuh | 0ca51f3 | 2020-12-25 21:51:45 -0800 | [diff] [blame] | 467 | std::string_view name() const { return log_files_[0].name; } |
Austin Schuh | 0c29701 | 2020-09-16 18:41:59 -0700 | [diff] [blame] | 468 | |
James Kuszmaul | 71a8193 | 2020-12-15 21:08:01 -0800 | [diff] [blame] | 469 | // Set whether to exit the SimulatedEventLoopFactory when we finish reading |
| 470 | // the logfile. |
| 471 | void set_exit_on_finish(bool exit_on_finish) { |
| 472 | exit_on_finish_ = exit_on_finish; |
| 473 | } |
| 474 | |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 475 | private: |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 476 | const Channel *RemapChannel(const EventLoop *event_loop, |
| 477 | const Channel *channel); |
| 478 | |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 479 | // Queues at least max_out_of_order_duration_ messages into channels_. |
| 480 | void QueueMessages(); |
James Kuszmaul | c7bbb3e | 2020-01-03 20:01:00 -0800 | [diff] [blame] | 481 | // Handle constructing a configuration with all the additional remapped |
| 482 | // channels from calls to RemapLoggedChannel. |
| 483 | void MakeRemappedConfig(); |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 484 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 485 | // Returns the number of nodes. |
| 486 | size_t nodes_count() const { |
| 487 | return !configuration::MultiNode(logged_configuration()) |
| 488 | ? 1u |
| 489 | : logged_configuration()->nodes()->size(); |
| 490 | } |
| 491 | |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 492 | const std::vector<LogFile> log_files_; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 493 | |
Austin Schuh | 969cd60 | 2021-01-03 00:09:45 -0800 | [diff] [blame] | 494 | // Class to manage sending RemoteMessages on the provided node after the |
| 495 | // correct delay. |
| 496 | class RemoteMessageSender{ |
| 497 | public: |
| 498 | RemoteMessageSender(aos::Sender<message_bridge::RemoteMessage> sender, |
| 499 | EventLoop *event_loop); |
| 500 | RemoteMessageSender(RemoteMessageSender const &) = delete; |
| 501 | RemoteMessageSender &operator=(RemoteMessageSender const &) = delete; |
| 502 | |
| 503 | // Sends the provided message. If monotonic_timestamp_time is min_time, |
| 504 | // send it immediately. |
| 505 | void Send( |
| 506 | FlatbufferDetachedBuffer<message_bridge::RemoteMessage> remote_message, |
| 507 | monotonic_clock::time_point monotonic_timestamp_time); |
| 508 | |
| 509 | private: |
| 510 | // Handles actually sending the timestamp if we were delayed. |
| 511 | void SendTimestamp(); |
| 512 | // Handles scheduling the timer to send at the correct time. |
| 513 | void ScheduleTimestamp(); |
| 514 | |
| 515 | EventLoop *event_loop_; |
| 516 | aos::Sender<message_bridge::RemoteMessage> sender_; |
| 517 | aos::TimerHandler *timer_; |
| 518 | |
| 519 | // Time we are scheduled for, or min_time if we aren't scheduled. |
| 520 | monotonic_clock::time_point scheduled_time_ = monotonic_clock::min_time; |
| 521 | |
| 522 | struct Timestamp { |
| 523 | Timestamp(FlatbufferDetachedBuffer<message_bridge::RemoteMessage> |
| 524 | new_remote_message, |
| 525 | monotonic_clock::time_point new_monotonic_timestamp_time) |
| 526 | : remote_message(std::move(new_remote_message)), |
| 527 | monotonic_timestamp_time(new_monotonic_timestamp_time) {} |
| 528 | FlatbufferDetachedBuffer<message_bridge::RemoteMessage> remote_message; |
| 529 | monotonic_clock::time_point monotonic_timestamp_time; |
| 530 | }; |
| 531 | |
| 532 | // List of messages to send. The timer works through them and then disables |
| 533 | // itself automatically. |
| 534 | std::deque<Timestamp> remote_timestamps_; |
| 535 | }; |
| 536 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 537 | // State per node. |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 538 | class State { |
| 539 | public: |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 540 | State(std::unique_ptr<TimestampMapper> timestamp_mapper); |
| 541 | |
| 542 | // Connects up the timestamp mappers. |
| 543 | void AddPeer(State *peer); |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 544 | |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 545 | // Returns the timestamps, channel_index, and message from a channel. |
| 546 | // update_time (will be) set to true when popping this message causes the |
| 547 | // filter to change the time offset estimation function. |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 548 | TimestampedMessage PopOldest(bool *update_time); |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 549 | |
Austin Schuh | 188eabe | 2020-12-29 23:41:13 -0800 | [diff] [blame] | 550 | // Returns the oldest message (if it exists) non destructively. |
| 551 | const TimestampedMessage &PeekOldest(); |
| 552 | |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 553 | // Returns the monotonic time of the oldest message. |
| 554 | monotonic_clock::time_point OldestMessageTime() const; |
| 555 | |
| 556 | // Primes the queues inside State. Should be called before calling |
| 557 | // OldestMessageTime. |
| 558 | void SeedSortedMessages(); |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 559 | |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 560 | // Returns the starting time for this node. |
| 561 | monotonic_clock::time_point monotonic_start_time() const { |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 562 | return timestamp_mapper_ ? timestamp_mapper_->monotonic_start_time() |
| 563 | : monotonic_clock::min_time; |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 564 | } |
| 565 | realtime_clock::time_point realtime_start_time() const { |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 566 | return timestamp_mapper_ ? timestamp_mapper_->realtime_start_time() |
| 567 | : realtime_clock::min_time; |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 568 | } |
| 569 | |
| 570 | // Sets the node event loop factory for replaying into a |
| 571 | // SimulatedEventLoopFactory. Returns the EventLoop to use. |
| 572 | EventLoop *SetNodeEventLoopFactory( |
| 573 | NodeEventLoopFactory *node_event_loop_factory); |
| 574 | |
| 575 | // Sets and gets the event loop to use. |
| 576 | void set_event_loop(EventLoop *event_loop) { event_loop_ = event_loop; } |
| 577 | EventLoop *event_loop() { return event_loop_; } |
| 578 | |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 579 | // Sets the current realtime offset from the monotonic clock for this node |
| 580 | // (if we are on a simulated event loop). |
| 581 | void SetRealtimeOffset(monotonic_clock::time_point monotonic_time, |
| 582 | realtime_clock::time_point realtime_time) { |
| 583 | if (node_event_loop_factory_ != nullptr) { |
| 584 | node_event_loop_factory_->SetRealtimeOffset(monotonic_time, |
| 585 | realtime_time); |
| 586 | } |
| 587 | } |
| 588 | |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 589 | // Returns the MessageHeader sender to log delivery timestamps to for the |
| 590 | // provided remote node. |
Austin Schuh | 969cd60 | 2021-01-03 00:09:45 -0800 | [diff] [blame] | 591 | RemoteMessageSender *RemoteTimestampSender(const Node *delivered_node); |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 592 | |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 593 | // Converts a timestamp from the monotonic clock on this node to the |
| 594 | // distributed clock. |
| 595 | distributed_clock::time_point ToDistributedClock( |
| 596 | monotonic_clock::time_point time) { |
| 597 | return node_event_loop_factory_->ToDistributedClock(time); |
| 598 | } |
| 599 | |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 600 | // Returns the current time on the remote node which sends messages on |
| 601 | // channel_index. |
| 602 | monotonic_clock::time_point monotonic_remote_now(size_t channel_index) { |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 603 | return channel_source_state_[channel_index] |
| 604 | ->node_event_loop_factory_->monotonic_now(); |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 605 | } |
| 606 | |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 607 | distributed_clock::time_point RemoteToDistributedClock( |
| 608 | size_t channel_index, monotonic_clock::time_point time) { |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 609 | return channel_source_state_[channel_index] |
| 610 | ->node_event_loop_factory_->ToDistributedClock(time); |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 611 | } |
| 612 | |
| 613 | const Node *remote_node(size_t channel_index) { |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 614 | return channel_source_state_[channel_index] |
| 615 | ->node_event_loop_factory_->node(); |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 616 | } |
| 617 | |
| 618 | monotonic_clock::time_point monotonic_now() { |
| 619 | return node_event_loop_factory_->monotonic_now(); |
| 620 | } |
| 621 | |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 622 | // Sets the number of channels. |
| 623 | void SetChannelCount(size_t count); |
| 624 | |
| 625 | // Sets the sender, filter, and target factory for a channel. |
Austin Schuh | 969cd60 | 2021-01-03 00:09:45 -0800 | [diff] [blame] | 626 | void SetChannel(size_t logged_channel_index, size_t factory_channel_index, |
| 627 | std::unique_ptr<RawSender> sender, |
| 628 | message_bridge::NoncausalOffsetEstimator *filter, |
| 629 | RemoteMessageSender *remote_timestamp_sender, |
| 630 | State *source_state); |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 631 | |
| 632 | // Returns if we have read all the messages from all the logs. |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 633 | bool at_end() const { |
| 634 | return timestamp_mapper_ ? timestamp_mapper_->Front() == nullptr : true; |
| 635 | } |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 636 | |
| 637 | // Unregisters everything so we can destory the event loop. |
| 638 | void Deregister(); |
| 639 | |
| 640 | // Sets the current TimerHandle for the replay callback. |
| 641 | void set_timer_handler(TimerHandler *timer_handler) { |
| 642 | timer_handler_ = timer_handler; |
| 643 | } |
| 644 | |
| 645 | // Sets the next wakeup time on the replay callback. |
| 646 | void Setup(monotonic_clock::time_point next_time) { |
| 647 | timer_handler_->Setup(next_time); |
| 648 | } |
| 649 | |
| 650 | // Sends a buffer on the provided channel index. |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 651 | bool Send(const TimestampedMessage ×tamped_message); |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 652 | |
| 653 | // Returns a debug string for the channel merger. |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 654 | std::string DebugString() const { |
| 655 | std::stringstream messages; |
| 656 | size_t i = 0; |
| 657 | for (const auto &message : sorted_messages_) { |
| 658 | if (i < 7 || i + 7 > sorted_messages_.size()) { |
| 659 | messages << "sorted_messages[" << i |
| 660 | << "]: " << std::get<0>(message).monotonic_event_time << " " |
| 661 | << configuration::StrippedChannelToString( |
| 662 | event_loop_->configuration()->channels()->Get( |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 663 | std::get<0>(message).channel_index)) |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 664 | << "\n"; |
| 665 | } else if (i == 7) { |
| 666 | messages << "...\n"; |
| 667 | } |
| 668 | ++i; |
| 669 | } |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 670 | if (!timestamp_mapper_) { |
| 671 | return messages.str(); |
| 672 | } |
| 673 | return messages.str() + timestamp_mapper_->DebugString(); |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 674 | } |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 675 | |
| 676 | private: |
| 677 | // Log file. |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 678 | std::unique_ptr<TimestampMapper> timestamp_mapper_; |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 679 | |
Austin Schuh | 287d43d | 2020-12-04 20:19:33 -0800 | [diff] [blame] | 680 | std::deque<std::tuple<TimestampedMessage, |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 681 | message_bridge::NoncausalOffsetEstimator *>> |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 682 | sorted_messages_; |
| 683 | |
| 684 | // Senders. |
| 685 | std::vector<std::unique_ptr<RawSender>> channels_; |
Austin Schuh | 969cd60 | 2021-01-03 00:09:45 -0800 | [diff] [blame] | 686 | std::vector<RemoteMessageSender *> remote_timestamp_senders_; |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 687 | // The mapping from logged channel index to sent channel index. Needed for |
| 688 | // sending out MessageHeaders. |
| 689 | std::vector<int> factory_channel_index_; |
| 690 | |
Austin Schuh | 9942bae | 2021-01-07 22:06:44 -0800 | [diff] [blame^] | 691 | struct ContiguousSentTimestamp { |
| 692 | // Most timestamps make it through the network, so it saves a ton of |
| 693 | // memory and CPU to store the start and end, and search for valid ranges. |
| 694 | // For one of the logs I looked at, we had 2 ranges for 4 days. |
| 695 | // |
| 696 | // Save monotonic times as well to help if a queue index ever wraps. Odds |
| 697 | // are very low, but doesn't hurt. |
| 698 | // |
| 699 | // The starting time and matching queue index. |
| 700 | monotonic_clock::time_point starting_monotonic_event_time = |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 701 | monotonic_clock::min_time; |
Austin Schuh | 9942bae | 2021-01-07 22:06:44 -0800 | [diff] [blame^] | 702 | uint32_t starting_queue_index = 0xffffffff; |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 703 | |
Austin Schuh | 9942bae | 2021-01-07 22:06:44 -0800 | [diff] [blame^] | 704 | // Ending time and queue index. |
| 705 | monotonic_clock::time_point ending_monotonic_event_time = |
| 706 | monotonic_clock::max_time; |
| 707 | uint32_t ending_queue_index = 0xffffffff; |
| 708 | |
| 709 | // The queue index that the first message was *actually* sent with. The |
| 710 | // queue indices are assumed to be contiguous through this range. |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 711 | uint32_t actual_queue_index = 0xffffffff; |
| 712 | }; |
| 713 | |
| 714 | // Stores all the timestamps that have been sent on this channel. This is |
| 715 | // only done for channels which are forwarded and on the node which |
Austin Schuh | 9942bae | 2021-01-07 22:06:44 -0800 | [diff] [blame^] | 716 | // initially sends the message. Compress using ranges and offsets. |
| 717 | std::vector<std::unique_ptr<std::vector<ContiguousSentTimestamp>>> |
| 718 | queue_index_map_; |
Austin Schuh | 858c9f3 | 2020-08-31 16:56:12 -0700 | [diff] [blame] | 719 | |
| 720 | // Factory (if we are in sim) that this loop was created on. |
| 721 | NodeEventLoopFactory *node_event_loop_factory_ = nullptr; |
| 722 | std::unique_ptr<EventLoop> event_loop_unique_ptr_; |
| 723 | // Event loop. |
| 724 | EventLoop *event_loop_ = nullptr; |
| 725 | // And timer used to send messages. |
| 726 | TimerHandler *timer_handler_; |
| 727 | |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 728 | // Filters (or nullptr if it isn't a forwarded channel) for each channel. |
| 729 | // This corresponds to the object which is shared among all the channels |
| 730 | // going between 2 nodes. The second element in the tuple indicates if this |
| 731 | // is the primary direction or not. |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 732 | std::vector<message_bridge::NoncausalOffsetEstimator *> filters_; |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 733 | |
| 734 | // List of NodeEventLoopFactorys (or nullptr if it isn't a forwarded |
| 735 | // channel) which correspond to the originating node. |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 736 | std::vector<State *> channel_source_state_; |
| 737 | |
Austin Schuh | 969cd60 | 2021-01-03 00:09:45 -0800 | [diff] [blame] | 738 | std::map<const Node *, std::unique_ptr<RemoteMessageSender>> |
Austin Schuh | 8d7e0bb | 2020-10-02 17:57:00 -0700 | [diff] [blame] | 739 | remote_timestamp_senders_map_; |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 740 | }; |
| 741 | |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 742 | // Node index -> State. |
| 743 | std::vector<std::unique_ptr<State>> states_; |
| 744 | |
| 745 | // Creates the requested filter if it doesn't exist, regardless of whether |
| 746 | // these nodes can actually communicate directly. The second return value |
| 747 | // reports if this is the primary direction or not. |
Austin Schuh | 2f8fd75 | 2020-09-01 22:38:28 -0700 | [diff] [blame] | 748 | message_bridge::NoncausalOffsetEstimator *GetFilter(const Node *node_a, |
| 749 | const Node *node_b); |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 750 | |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 751 | // List of filters for a connection. The pointer to the first node will be |
| 752 | // less than the second node. |
Austin Schuh | 0ca1fd3 | 2020-12-18 22:53:05 -0800 | [diff] [blame] | 753 | std::unique_ptr<message_bridge::MultiNodeNoncausalOffsetEstimator> filters_; |
Austin Schuh | 8bd9632 | 2020-02-13 21:18:22 -0800 | [diff] [blame] | 754 | |
| 755 | // Updates the offset matrix solution and sets the per-node distributed |
| 756 | // offsets in the factory. |
| 757 | void UpdateOffsets(); |
| 758 | |
James Kuszmaul | 84ff3e5 | 2020-01-03 19:48:53 -0800 | [diff] [blame] | 759 | std::unique_ptr<FlatbufferDetachedBuffer<Configuration>> |
| 760 | remapped_configuration_buffer_; |
| 761 | |
James Kuszmaul | 84ff3e5 | 2020-01-03 19:48:53 -0800 | [diff] [blame] | 762 | std::unique_ptr<SimulatedEventLoopFactory> event_loop_factory_unique_ptr_; |
| 763 | SimulatedEventLoopFactory *event_loop_factory_ = nullptr; |
James Kuszmaul | c7bbb3e | 2020-01-03 20:01:00 -0800 | [diff] [blame] | 764 | |
| 765 | // Map of channel indices to new name. The channel index will be an index into |
| 766 | // logged_configuration(), and the string key will be the name of the channel |
| 767 | // to send on instead of the logged channel name. |
Austin Schuh | 0de30f3 | 2020-12-06 12:44:28 -0800 | [diff] [blame] | 768 | struct RemappedChannel { |
| 769 | std::string remapped_name; |
| 770 | std::string new_type; |
| 771 | }; |
| 772 | std::map<size_t, RemappedChannel> remapped_channels_; |
Austin Schuh | 01b4c35 | 2020-09-21 23:09:39 -0700 | [diff] [blame] | 773 | std::vector<MapT> maps_; |
James Kuszmaul | c7bbb3e | 2020-01-03 20:01:00 -0800 | [diff] [blame] | 774 | |
Austin Schuh | 6f3babe | 2020-01-26 20:34:50 -0800 | [diff] [blame] | 775 | // Number of nodes which still have data to send. This is used to figure out |
| 776 | // when to exit. |
| 777 | size_t live_nodes_ = 0; |
| 778 | |
James Kuszmaul | c7bbb3e | 2020-01-03 20:01:00 -0800 | [diff] [blame] | 779 | const Configuration *remapped_configuration_ = nullptr; |
| 780 | const Configuration *replay_configuration_ = nullptr; |
Austin Schuh | cde938c | 2020-02-02 17:30:07 -0800 | [diff] [blame] | 781 | |
| 782 | // If true, the replay timer will ignore any missing data. This is used |
| 783 | // during startup when we are bootstrapping everything and trying to get to |
| 784 | // the start of all the log files. |
| 785 | bool ignore_missing_data_ = false; |
James Kuszmaul | 71a8193 | 2020-12-15 21:08:01 -0800 | [diff] [blame] | 786 | |
| 787 | // Whether to exit the SimulatedEventLoop when we finish reading the logs. |
| 788 | bool exit_on_finish_ = true; |
Austin Schuh | e309d2a | 2019-11-29 13:25:21 -0800 | [diff] [blame] | 789 | }; |
| 790 | |
| 791 | } // namespace logger |
| 792 | } // namespace aos |
| 793 | |
| 794 | #endif // AOS_EVENTS_LOGGER_H_ |