blob: 67cbc4473c94fb4868229810b526fbf1b9339518 [file] [log] [blame]
Austin Schuhba20ea72021-01-21 16:47:01 -08001#include <iostream>
2#include <string>
3#include <vector>
4
Philipp Schrader790cb542023-07-05 21:06:52 -07005#include "gflags/gflags.h"
6
Austin Schuhba20ea72021-01-21 16:47:01 -08007#include "aos/events/logging/logfile_sorting.h"
8#include "aos/events/logging/logfile_utils.h"
9#include "aos/init.h"
10#include "aos/network/multinode_timestamp_filter.h"
Austin Schuhba20ea72021-01-21 16:47:01 -080011
12DECLARE_bool(timestamps_to_csv);
13DEFINE_bool(skip_order_validation, false,
14 "If true, ignore any out of orderness in replay");
15
16namespace aos::logger {
17
18namespace chrono = std::chrono;
19
20std::string LogFileVectorToString(std::vector<logger::LogFile> log_files) {
21 std::stringstream ss;
Austin Schuh05dad8b2021-01-27 22:47:23 -080022 for (const auto &f : log_files) {
Austin Schuhba20ea72021-01-21 16:47:01 -080023 ss << f << "\n";
24 }
25 return ss.str();
26}
27
28int Main(int argc, char **argv) {
29 const std::vector<std::string> unsorted_logfiles = FindLogs(argc, argv);
30 const std::vector<LogFile> log_files = SortParts(unsorted_logfiles);
31
32 CHECK_GT(log_files.size(), 0u);
33 // Validate that we have the same config everwhere. This will be true if
34 // all the parts were sorted together and the configs match.
35 const Configuration *config = nullptr;
36 for (const LogFile &log_file : log_files) {
Austin Schuh3e20c692021-11-16 20:43:16 -080037 VLOG(1) << log_file;
Austin Schuhba20ea72021-01-21 16:47:01 -080038 if (config == nullptr) {
39 config = log_file.config.get();
40 } else {
41 CHECK_EQ(config, log_file.config.get());
42 }
43 }
44
45 CHECK(configuration::MultiNode(config))
46 << ": Timestamps only make sense in a multi-node world.";
47
48 // Now, build up all the TimestampMapper classes to read and sort the data.
49 std::vector<std::unique_ptr<TimestampMapper>> mappers;
50
51 for (const Node *node : configuration::GetNodes(config)) {
52 std::vector<LogParts> filtered_parts =
53 FilterPartsForNode(log_files, node->name()->string_view());
54
55 // Confirm that all the parts are from the same boot if there are enough
56 // parts to not be from the same boot.
57 if (!filtered_parts.empty()) {
Austin Schuhba20ea72021-01-21 16:47:01 -080058 // Filter the parts relevant to each node when building the mapper.
59 mappers.emplace_back(
60 std::make_unique<TimestampMapper>(std::move(filtered_parts)));
61 } else {
62 mappers.emplace_back(nullptr);
63 }
64 }
65
66 // Now, build up the estimator used to solve for time.
67 message_bridge::MultiNodeNoncausalOffsetEstimator multinode_estimator(
Austin Schuh58646e22021-08-23 23:51:46 -070068 config, config, log_files[0].boots, FLAGS_skip_order_validation,
69 chrono::seconds(0));
70 multinode_estimator.set_reboot_found(
71 [config](distributed_clock::time_point reboot_time,
72 const std::vector<logger::BootTimestamp> &node_times) {
73 LOG(INFO) << "Rebooted at distributed " << reboot_time;
74 size_t node_index = 0;
75 for (const logger::BootTimestamp &time : node_times) {
76 LOG(INFO) << " "
77 << config->nodes()->Get(node_index)->name()->string_view()
78 << " " << time;
79 ++node_index;
80 }
81 });
Austin Schuhba20ea72021-01-21 16:47:01 -080082
Austin Schuhe639ea12021-01-25 13:00:22 -080083 {
84 std::vector<TimestampMapper *> timestamp_mappers;
85 for (std::unique_ptr<TimestampMapper> &mapper : mappers) {
86 timestamp_mappers.emplace_back(mapper.get());
87 }
88 multinode_estimator.SetTimestampMappers(std::move(timestamp_mappers));
89 }
90
Austin Schuhba20ea72021-01-21 16:47:01 -080091 // To make things more like the logger and faster, cache the node + channel ->
92 // filter mapping in a set of vectors.
93 std::vector<std::vector<message_bridge::NoncausalOffsetEstimator *>> filters;
94 filters.resize(configuration::NodesCount(config));
95
96 for (const Node *node : configuration::GetNodes(config)) {
97 const size_t node_index = configuration::GetNodeIndex(config, node);
98 filters[node_index].resize(config->channels()->size(), nullptr);
99 for (size_t channel_index = 0; channel_index < config->channels()->size();
100 ++channel_index) {
101 const Channel *channel = config->channels()->Get(channel_index);
102
103 if (!configuration::ChannelIsSendableOnNode(channel, node) &&
104 configuration::ChannelIsReadableOnNode(channel, node)) {
105 // We've got a message which is being forwarded to this node.
106 const Node *source_node = configuration::GetNode(
107 config, channel->source_node()->string_view());
108 filters[node_index][channel_index] =
109 multinode_estimator.GetFilter(node, source_node);
110 }
111 }
112 }
113
Austin Schuhe639ea12021-01-25 13:00:22 -0800114 multinode_estimator.CheckGraph();
115
Austin Schuhba20ea72021-01-21 16:47:01 -0800116 // Now, read all the timestamps for each node. This is simpler than the
117 // logger on purpose. It loads in *all* the timestamps in 1 go per node,
118 // ignoring memory usage.
119 for (const Node *node : configuration::GetNodes(config)) {
120 LOG(INFO) << "Reading all data for " << node->name()->string_view();
121 const size_t node_index = configuration::GetNodeIndex(config, node);
122 TimestampMapper *timestamp_mapper = mappers[node_index].get();
123 if (timestamp_mapper == nullptr) {
124 continue;
125 }
126 while (true) {
127 TimestampedMessage *m = timestamp_mapper->Front();
128 if (m == nullptr) {
129 break;
130 }
Austin Schuhba20ea72021-01-21 16:47:01 -0800131 timestamp_mapper->PopFront();
132 }
133 }
134
135 // Don't get clever. Use the first time as the start time. Note: this is
136 // different than how log_cat and others work.
Austin Schuhdee8ea72021-08-20 19:13:41 -0700137 std::optional<const std::tuple<distributed_clock::time_point,
138 std::vector<BootTimestamp>> *>
139 next_timestamp = multinode_estimator.QueueNextTimestamp();
Austin Schuhba20ea72021-01-21 16:47:01 -0800140 CHECK(next_timestamp);
141 LOG(INFO) << "Starting at:";
142 for (const Node *node : configuration::GetNodes(config)) {
143 const size_t node_index = configuration::GetNodeIndex(config, node);
144 LOG(INFO) << " " << node->name()->string_view() << " -> "
Austin Schuhdee8ea72021-08-20 19:13:41 -0700145 << std::get<1>(*next_timestamp.value())[node_index].time;
Austin Schuhba20ea72021-01-21 16:47:01 -0800146 }
147
Austin Schuh66168842021-08-17 19:42:21 -0700148 std::vector<monotonic_clock::time_point> just_monotonic(
Austin Schuhdee8ea72021-08-20 19:13:41 -0700149 std::get<1>(*next_timestamp.value()).size());
Austin Schuh66168842021-08-17 19:42:21 -0700150 for (size_t i = 0; i < just_monotonic.size(); ++i) {
Austin Schuhdee8ea72021-08-20 19:13:41 -0700151 CHECK_EQ(std::get<1>(*next_timestamp.value())[i].boot, 0u);
152 just_monotonic[i] = std::get<1>(*next_timestamp.value())[i].time;
Austin Schuh66168842021-08-17 19:42:21 -0700153 }
154 multinode_estimator.Start(just_monotonic);
Austin Schuhba20ea72021-01-21 16:47:01 -0800155
156 // As we pull off all the timestamps, the time problem is continually solved,
157 // filling in the CSV files.
158 while (true) {
Austin Schuhdee8ea72021-08-20 19:13:41 -0700159 std::optional<const std::tuple<distributed_clock::time_point,
160 std::vector<BootTimestamp>> *>
161 next_timestamp = multinode_estimator.QueueNextTimestamp();
Austin Schuhba20ea72021-01-21 16:47:01 -0800162 if (!next_timestamp) {
163 break;
164 }
Austin Schuhe589b062022-06-26 21:50:19 -0700165 multinode_estimator.ObserveTimePassed(std::get<0>(*next_timestamp.value()));
Austin Schuhba20ea72021-01-21 16:47:01 -0800166 }
167
Austin Schuhdee8ea72021-08-20 19:13:41 -0700168 LOG(INFO) << "Done";
169
Austin Schuhba20ea72021-01-21 16:47:01 -0800170 return 0;
171}
172
173} // namespace aos::logger
174
175int main(int argc, char **argv) {
176 FLAGS_timestamps_to_csv = true;
177 gflags::SetUsageMessage(
178 "Usage:\n"
179 " timestamp_extractor [args] logfile1 logfile2 ...\n\nThis program "
180 "dumps out all the timestamps from a set of log files for plotting. Use "
181 "--skip_order_validation to skip any time estimation problems we find.");
182 aos::InitGoogle(&argc, &argv);
183
184 return aos::logger::Main(argc, argv);
185}