Estimate the distributed clock with boots accounted for
Route the current boot through both the noncausal filter, and the
timestamp solver code. This gets us 1 step closer to exposing boots
to the user.
This stops before changing log_reader though. We still CHECK on the way
into the SimulatedEventLoopFactory that actually runs reading. This
felt like a reasonable intermediate point.
Change-Id: I85d0735c449a2aacf8cc457bdbcdbd667f1809ef
Signed-off-by: Austin Schuh <austin.schuh@bluerivertech.com>
diff --git a/aos/events/logging/BUILD b/aos/events/logging/BUILD
index fead91d..952c16d 100644
--- a/aos/events/logging/BUILD
+++ b/aos/events/logging/BUILD
@@ -13,20 +13,30 @@
)
cc_library(
+ name = "boot_timestamp",
+ srcs = ["boot_timestamp.cc"],
+ hdrs = ["boot_timestamp.h"],
+ target_compatible_with = ["@platforms//os:linux"],
+ visibility = ["//visibility:public"],
+ deps = [
+ "//aos/time",
+ ],
+)
+
+cc_library(
name = "logfile_utils",
srcs = [
- "boot_timestamp.cc",
"logfile_sorting.cc",
"logfile_utils.cc",
],
hdrs = [
- "boot_timestamp.h",
"logfile_sorting.h",
"logfile_utils.h",
],
target_compatible_with = ["@platforms//os:linux"],
visibility = ["//visibility:public"],
deps = [
+ ":boot_timestamp",
":buffer_encoder",
":logger_fbs",
"//aos:uuid",
diff --git a/aos/events/logging/boot_timestamp.cc b/aos/events/logging/boot_timestamp.cc
index c037633..cdd33b6 100644
--- a/aos/events/logging/boot_timestamp.cc
+++ b/aos/events/logging/boot_timestamp.cc
@@ -11,4 +11,10 @@
<< "}";
}
+std::ostream &operator<<(std::ostream &os,
+ const struct BootDuration &duration) {
+ return os << "{.boot=" << duration.boot
+ << ", .duration=" << duration.duration.count() << "ns}";
+}
+
} // namespace aos::logger
diff --git a/aos/events/logging/boot_timestamp.h b/aos/events/logging/boot_timestamp.h
index ea66c8e..64c824a 100644
--- a/aos/events/logging/boot_timestamp.h
+++ b/aos/events/logging/boot_timestamp.h
@@ -7,6 +7,23 @@
namespace aos::logger {
+// Simple class representing a duration in time and a boot it is from. This
+// gives us something to use for storing the time offset when filtering.
+struct BootDuration {
+ // Boot number for this timestamp.
+ size_t boot = 0u;
+ // Monotonic time in that boot.
+ monotonic_clock::duration duration{0};
+
+ BootDuration operator+(monotonic_clock::duration d) const {
+ return {boot, duration + d};
+ }
+
+ bool operator==(const BootDuration &m2) const {
+ return boot == m2.boot && duration == m2.duration;
+ }
+};
+
// Simple class representing which boot and what monotonic time in that boot.
// Boots are assumed to be sequential, and the monotonic clock resets on reboot
// for all the compare operations.
@@ -16,13 +33,21 @@
// Monotonic time in that boot.
monotonic_clock::time_point time = monotonic_clock::min_time;
+ monotonic_clock::duration time_since_epoch() const {
+ return time.time_since_epoch();
+ }
+
static constexpr BootTimestamp min_time() {
- return BootTimestamp{.boot = 0u, .time = monotonic_clock::min_time};
+ return BootTimestamp{.boot = std::numeric_limits<size_t>::min(),
+ .time = monotonic_clock::min_time};
}
static constexpr BootTimestamp max_time() {
return BootTimestamp{.boot = std::numeric_limits<size_t>::max(),
.time = monotonic_clock::max_time};
}
+ static constexpr BootTimestamp epoch() {
+ return BootTimestamp{.boot = 0, .time = monotonic_clock::epoch()};
+ }
// Compare operators. These are implemented such that earlier boots always
// compare less than later boots, and the times are only compared in a single
@@ -33,10 +58,21 @@
bool operator>(const BootTimestamp &m2) const;
bool operator==(const BootTimestamp &m2) const;
bool operator!=(const BootTimestamp &m2) const;
+
+ BootTimestamp operator+(monotonic_clock::duration d) const {
+ return {boot, time + d};
+ }
+ BootTimestamp operator-(monotonic_clock::duration d) const {
+ return {boot, time - d};
+ }
+ BootTimestamp operator+(BootDuration d) const {
+ return {boot, time + d.duration};
+ }
};
std::ostream &operator<<(std::ostream &os,
const struct BootTimestamp ×tamp);
+std::ostream &operator<<(std::ostream &os, const struct BootDuration &duration);
inline bool BootTimestamp::operator<(const BootTimestamp &m2) const {
if (boot != m2.boot) {
diff --git a/aos/events/logging/log_reader.cc b/aos/events/logging/log_reader.cc
index 8a8f5af..b320474 100644
--- a/aos/events/logging/log_reader.cc
+++ b/aos/events/logging/log_reader.cc
@@ -1484,7 +1484,8 @@
// TODO(austin): We probably want to push this down into the timestamp
// mapper directly.
- filter->Pop(event_loop_->node(), event_loop_->monotonic_now());
+ // TODO(austin): This hard-codes the boot to 0. We need to fix that.
+ filter->Pop(event_loop_->node(), {0, event_loop_->monotonic_now()});
}
VLOG(1) << "Popped " << result
<< configuration::CleanedChannelToString(
diff --git a/aos/events/logging/logger_test.cc b/aos/events/logging/logger_test.cc
index d6ad8fe..195d442 100644
--- a/aos/events/logging/logger_test.cc
+++ b/aos/events/logging/logger_test.cc
@@ -1466,8 +1466,8 @@
// TODO(austin): Negate...
const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
- time_converter_.AddMonotonic({monotonic_clock::epoch(),
- monotonic_clock::epoch() + initial_pi2_offset});
+ time_converter_.AddMonotonic(
+ {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
// Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
// skew to be 200 uS/s
const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
@@ -2169,8 +2169,8 @@
// up a clock difference between 2 nodes and looking at the resulting parts.
TEST_P(MultinodeLoggerTest, LoggerStartTime) {
time_converter_.AddMonotonic(
- {monotonic_clock::epoch(),
- monotonic_clock::epoch() + chrono::seconds(1000)});
+ {BootTimestamp::epoch(),
+ BootTimestamp::epoch() + chrono::seconds(1000)});
{
LoggerState pi1_logger = MakeLogger(pi1_);
LoggerState pi2_logger = MakeLogger(pi2_);
@@ -2208,8 +2208,8 @@
util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
util::UnlinkRecursive(tmp_dir_ + "/new-good");
time_converter_.AddMonotonic(
- {monotonic_clock::epoch(),
- monotonic_clock::epoch() + chrono::seconds(1000)});
+ {BootTimestamp::epoch(),
+ BootTimestamp::epoch() + chrono::seconds(1000)});
logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
@@ -2234,8 +2234,8 @@
// Test that renaming the file base dies.
TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
time_converter_.AddMonotonic(
- {monotonic_clock::epoch(),
- monotonic_clock::epoch() + chrono::seconds(1000)});
+ {BootTimestamp::epoch(),
+ BootTimestamp::epoch() + chrono::seconds(1000)});
util::UnlinkRecursive(tmp_dir_ + "/renamefile");
logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
@@ -2413,8 +2413,8 @@
TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
time_converter_.AddMonotonic(
- {monotonic_clock::epoch(),
- monotonic_clock::epoch() + chrono::seconds(1000)});
+ {BootTimestamp::epoch(),
+ BootTimestamp::epoch() + chrono::seconds(1000)});
time_converter_.AddMonotonic(
{chrono::milliseconds(10000),
@@ -2439,8 +2439,8 @@
TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
time_converter_.AddMonotonic(
- {monotonic_clock::epoch(),
- monotonic_clock::epoch() + chrono::seconds(500)});
+ {BootTimestamp::epoch(),
+ BootTimestamp::epoch() + chrono::seconds(500)});
time_converter_.AddMonotonic(
{chrono::milliseconds(10000),
@@ -2466,8 +2466,8 @@
event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Disconnect(pi1_);
time_converter_.AddMonotonic(
- {monotonic_clock::epoch(),
- monotonic_clock::epoch() + chrono::seconds(1000)});
+ {BootTimestamp::epoch(),
+ BootTimestamp::epoch() + chrono::seconds(1000)});
{
LoggerState pi1_logger = MakeLogger(pi1_);
diff --git a/aos/events/logging/timestamp_extractor.cc b/aos/events/logging/timestamp_extractor.cc
index 232b842..ae3c4cc 100644
--- a/aos/events/logging/timestamp_extractor.cc
+++ b/aos/events/logging/timestamp_extractor.cc
@@ -53,13 +53,6 @@
// Confirm that all the parts are from the same boot if there are enough
// parts to not be from the same boot.
if (!filtered_parts.empty()) {
- for (size_t i = 1; i < filtered_parts.size(); ++i) {
- CHECK_EQ(filtered_parts[i].source_boot_uuid,
- filtered_parts[0].source_boot_uuid)
- << ": Found parts from different boots "
- << LogFileVectorToString(log_files);
- }
-
// Filter the parts relevant to each node when building the mapper.
mappers.emplace_back(
std::make_unique<TimestampMapper>(std::move(filtered_parts)));
@@ -126,25 +119,32 @@
// Don't get clever. Use the first time as the start time. Note: this is
// different than how log_cat and others work.
- std::optional<std::tuple<distributed_clock::time_point,
- std::vector<monotonic_clock::time_point>>>
+ std::optional<
+ std::tuple<distributed_clock::time_point, std::vector<BootTimestamp>>>
next_timestamp = multinode_estimator.NextTimestamp();
CHECK(next_timestamp);
LOG(INFO) << "Starting at:";
for (const Node *node : configuration::GetNodes(config)) {
const size_t node_index = configuration::GetNodeIndex(config, node);
LOG(INFO) << " " << node->name()->string_view() << " -> "
- << std::get<1>(*next_timestamp)[node_index];
+ << std::get<1>(*next_timestamp)[node_index].time;
}
- multinode_estimator.Start(std::get<1>(*next_timestamp));
+ std::vector<monotonic_clock::time_point> just_monotonic(
+ std::get<1>(*next_timestamp).size());
+ for (size_t i = 0; i < just_monotonic.size(); ++i) {
+ CHECK_EQ(std::get<1>(*next_timestamp)[i].boot, 0u);
+ just_monotonic[i] = std::get<1>(*next_timestamp)[i].time;
+ }
+ multinode_estimator.Start(just_monotonic);
// As we pull off all the timestamps, the time problem is continually solved,
// filling in the CSV files.
while (true) {
- std::optional<std::tuple<distributed_clock::time_point,
- std::vector<monotonic_clock::time_point>>>
+ std::optional<
+ std::tuple<distributed_clock::time_point, std::vector<BootTimestamp>>>
next_timestamp = multinode_estimator.NextTimestamp();
+ // TODO(austin): Figure out how to make the plot work across reboots.
if (!next_timestamp) {
break;
}
diff --git a/aos/events/simulated_event_loop_test.cc b/aos/events/simulated_event_loop_test.cc
index 4cb51de..83568da 100644
--- a/aos/events/simulated_event_loop_test.cc
+++ b/aos/events/simulated_event_loop_test.cc
@@ -73,10 +73,10 @@
}
INSTANTIATE_TEST_SUITE_P(SimulatedEventLoopCommonTest, AbstractEventLoopTest,
- CommonParameters());
+ CommonParameters());
INSTANTIATE_TEST_SUITE_P(SimulatedEventLoopCommonDeathTest,
- AbstractEventLoopDeathTest, CommonParameters());
+ AbstractEventLoopDeathTest, CommonParameters());
// Parameters to run all the tests with.
struct Param {
@@ -785,8 +785,8 @@
constexpr chrono::milliseconds kOffset{1501};
time.AddNextTimestamp(
distributed_clock::epoch(),
- {monotonic_clock::epoch(), monotonic_clock::epoch() + kOffset,
- monotonic_clock::epoch()});
+ {logger::BootTimestamp::epoch(), logger::BootTimestamp::epoch() + kOffset,
+ logger::BootTimestamp::epoch()});
std::unique_ptr<EventLoop> ping_event_loop =
simulated_event_loop_factory.MakeEventLoop("ping", pi1);
@@ -1293,13 +1293,13 @@
constexpr chrono::milliseconds kOffset{150100};
time.AddNextTimestamp(
distributed_clock::epoch(),
- {monotonic_clock::epoch(), monotonic_clock::epoch() + kOffset,
- monotonic_clock::epoch()});
+ {logger::BootTimestamp::epoch(), logger::BootTimestamp::epoch() + kOffset,
+ logger::BootTimestamp::epoch()});
time.AddNextTimestamp(
distributed_clock::epoch() + chrono::seconds(10),
- {monotonic_clock::epoch() + chrono::milliseconds(9999),
- monotonic_clock::epoch() + kOffset + chrono::seconds(10),
- monotonic_clock::epoch() + chrono::milliseconds(9999)});
+ {logger::BootTimestamp::epoch() + chrono::milliseconds(9999),
+ logger::BootTimestamp::epoch() + kOffset + chrono::seconds(10),
+ logger::BootTimestamp::epoch() + chrono::milliseconds(9999)});
std::unique_ptr<EventLoop> ping_event_loop =
simulated_event_loop_factory.MakeEventLoop("ping", pi1);