Add boot info to NoncausalTimestampFilter debugging
As part of debugging our log reading issues, we needed to be able to see
exactly which boot everything was from. This improves the logging such
that we can see exactly what is happening.
Change-Id: I2df72bcb1570b515d62838df279bb6fbcf540118
Signed-off-by: James Kuszmaul <james.kuszmaul@bluerivertech.com>
diff --git a/aos/network/timestamp_filter.cc b/aos/network/timestamp_filter.cc
index 914f993..fb89a41 100644
--- a/aos/network/timestamp_filter.cc
+++ b/aos/network/timestamp_filter.cc
@@ -25,6 +25,12 @@
return ss.str();
}
+std::string TimeString(const logger::BootTimestamp t, logger::BootDuration o) {
+ std::stringstream ss;
+ ss << "O(" << t << ") = " << o << ", remote " << t + o;
+ return ss.str();
+}
+
std::string TimeString(const aos::monotonic_clock::time_point t_base, double t,
std::chrono::nanoseconds o_base, double o) {
std::stringstream ss;
@@ -43,6 +49,11 @@
return TimeString(std::get<0>(t), std::get<1>(t));
}
+std::string TimeString(
+ const std::tuple<logger::BootTimestamp, logger::BootDuration> t) {
+ return TimeString(std::get<0>(t), std::get<1>(t));
+}
+
void ClippedAverageFilterPrintHeader(FILE *fp) {
fprintf(fp,
"# time_since_start, sample_ns, filtered_offset, offset, "
@@ -531,6 +542,11 @@
return std::make_pair(pointer, std::make_pair(t0, t1));
}
+ VLOG(1) << "Other points are: " << pointer.other_points_.size();
+ for (const auto &x : pointer.other_points_) {
+ VLOG(1) << " " << TimeString(x.second);
+ }
+
// The invariant of pointer is that other_points is bounded by t0, t1. Confirm
// it before we return things depending on it since it is easy.
CHECK_GT(std::get<0>(pointer.other_points_[0].second), std::get<0>(t0));
@@ -1266,36 +1282,39 @@
void NoncausalTimestampFilter::Sample(BootTimestamp monotonic_now_all,
BootDuration sample_ns) {
filter(monotonic_now_all.boot, sample_ns.boot)
- ->filter.Sample(monotonic_now_all.time, sample_ns.duration);
+ ->filter.Sample(monotonic_now_all, sample_ns);
}
void NoncausalTimestampFilter::SingleFilter::Sample(
- monotonic_clock::time_point monotonic_now, chrono::nanoseconds sample_ns) {
+ logger::BootTimestamp monotonic_now, logger::BootDuration sample_ns) {
// The first sample is easy. Just do it!
if (timestamps_.size() == 0) {
VLOG(1) << node_names_ << " Initial sample of "
<< TimeString(monotonic_now, sample_ns);
- timestamps_.emplace_back(std::make_tuple(monotonic_now, sample_ns));
+ timestamps_.emplace_back(
+ std::make_tuple(monotonic_now.time, sample_ns.duration));
CHECK(!fully_frozen_)
<< ": " << node_names_
<< " Returned a horizontal line previously and then "
"got a new sample at "
<< monotonic_now << ", "
- << chrono::duration<double>(monotonic_now - std::get<0>(timestamps_[0]))
+ << chrono::duration<double>(monotonic_now.time -
+ std::get<0>(timestamps_[0]))
.count()
<< " seconds after the last sample at " << std::get<0>(timestamps_[0])
<< ". Increase --time_estimation_buffer_seconds to greater than "
- << chrono::duration<double>(monotonic_now - std::get<0>(timestamps_[0]))
+ << chrono::duration<double>(monotonic_now.time -
+ std::get<0>(timestamps_[0]))
.count()
<< ", or set --force_timestamp_loading";
return;
}
- CHECK_GT(monotonic_now, frozen_time_)
+ CHECK_GT(monotonic_now.time, frozen_time_)
<< ": " << node_names_ << " Tried to insert " << monotonic_now
<< " before the frozen time of " << frozen_time_
<< ". Increase "
"--time_estimation_buffer_seconds to greater than "
- << chrono::duration<double>(frozen_time_ - monotonic_now).count()
+ << chrono::duration<double>(frozen_time_ - monotonic_now.time).count()
<< ", or set --force_timestamp_loading";
// Future samples get quite a bit harder. We want the line to track the
@@ -1303,12 +1322,13 @@
std::tuple<aos::monotonic_clock::time_point, chrono::nanoseconds> back =
timestamps_.back();
- aos::monotonic_clock::duration dt = monotonic_now - std::get<0>(back);
- aos::monotonic_clock::duration doffset = sample_ns - std::get<1>(back);
+ aos::monotonic_clock::duration dt = monotonic_now.time - std::get<0>(back);
+ aos::monotonic_clock::duration doffset =
+ sample_ns.duration - std::get<1>(back);
if (dt == chrono::nanoseconds(0) && doffset == chrono::nanoseconds(0)) {
VLOG(1) << node_names_ << " Duplicate sample of O(" << monotonic_now
- << ") = " << sample_ns.count() << ", remote time "
+ << ") = " << sample_ns << ", remote time "
<< monotonic_now + sample_ns;
return;
@@ -1337,11 +1357,13 @@
<< " Returned a horizontal line previously and then got a new "
"sample at "
<< monotonic_now << ", "
- << chrono::duration<double>(monotonic_now - std::get<0>(timestamps_[0]))
+ << chrono::duration<double>(monotonic_now.time -
+ std::get<0>(timestamps_[0]))
.count()
<< " seconds after the last sample at " << std::get<0>(timestamps_[0])
<< ". Increase --time_estimation_buffer_seconds to greater than "
- << chrono::duration<double>(monotonic_now - std::get<0>(timestamps_[0]))
+ << chrono::duration<double>(monotonic_now.time -
+ std::get<0>(timestamps_[0]))
.count()
<< ", or set --force_timestamp_loading";
@@ -1364,10 +1386,12 @@
<< ": " << node_names_ << " Can't pop an already frozen sample "
<< TimeString(back) << " while inserting "
<< TimeString(monotonic_now, sample_ns) << ", "
- << chrono::duration<double>(monotonic_now - std::get<0>(back)).count()
+ << chrono::duration<double>(monotonic_now.time - std::get<0>(back))
+ .count()
<< " seconds in the past. Increase --time_estimation_buffer_seconds "
"to greater than "
- << chrono::duration<double>(monotonic_now - std::get<0>(back)).count()
+ << chrono::duration<double>(monotonic_now.time - std::get<0>(back))
+ .count()
<< ", or set --force_timestamp_loading";
VLOG(1) << node_names_
<< " Removing now invalid sample during back propegation of "
@@ -1375,13 +1399,14 @@
timestamps_.pop_back();
back = timestamps_.back();
- dt = monotonic_now - std::get<0>(back);
- doffset = sample_ns - std::get<1>(back);
+ dt = monotonic_now.time - std::get<0>(back);
+ doffset = sample_ns.duration - std::get<1>(back);
}
VLOG(1) << node_names_ << " Added sample of "
<< TimeString(monotonic_now, sample_ns);
- timestamps_.emplace_back(std::make_tuple(monotonic_now, sample_ns));
+ timestamps_.emplace_back(
+ std::make_tuple(monotonic_now.time, sample_ns.duration));
return;
}
@@ -1389,7 +1414,7 @@
// point. lower_bound returns the element which we are supposed to insert
// "before".
auto it = std::lower_bound(
- timestamps_.begin(), timestamps_.end(), monotonic_now,
+ timestamps_.begin(), timestamps_.end(), monotonic_now.time,
[](const std::tuple<aos::monotonic_clock::time_point,
std::chrono::nanoseconds>
x,
@@ -1403,9 +1428,9 @@
if (it == timestamps_.begin()) {
// We are being asked to add at the beginning.
{
- const chrono::nanoseconds dt = std::get<0>(*it) - monotonic_now;
+ const chrono::nanoseconds dt = std::get<0>(*it) - monotonic_now.time;
const chrono::nanoseconds original_offset = std::get<1>(*it);
- const chrono::nanoseconds doffset = original_offset - sample_ns;
+ const chrono::nanoseconds doffset = original_offset - sample_ns.duration;
if (dt == chrono::nanoseconds(0) && doffset >= chrono::nanoseconds(0)) {
VLOG(1) << node_names_ << " Redundant timestamp "
@@ -1418,15 +1443,18 @@
VLOG(1) << node_names_ << " Added sample at beginning "
<< TimeString(monotonic_now, sample_ns);
- timestamps_.insert(it, std::make_tuple(monotonic_now, sample_ns));
+ timestamps_.insert(it,
+ std::make_tuple(monotonic_now.time, sample_ns.duration));
while (true) {
// First point was too positive, so we need to remove points after it
// until we are valid.
auto second = timestamps_.begin() + 1;
if (second != timestamps_.end()) {
- const chrono::nanoseconds dt = std::get<0>(*second) - monotonic_now;
- const chrono::nanoseconds doffset = std::get<1>(*second) - sample_ns;
+ const chrono::nanoseconds dt =
+ std::get<0>(*second) - monotonic_now.time;
+ const chrono::nanoseconds doffset =
+ std::get<1>(*second) - sample_ns.duration;
if (absl::int128(doffset.count()) *
absl::int128(MaxVelocityRatio::den) <
@@ -1477,10 +1505,12 @@
<< " < " << monotonic_now << " < " << std::get<0>(*it);
{
- chrono::nanoseconds prior_dt = monotonic_now - std::get<0>(*(it - 1));
- chrono::nanoseconds prior_doffset = sample_ns - std::get<1>(*(it - 1));
- chrono::nanoseconds next_dt = std::get<0>(*it) - monotonic_now;
- chrono::nanoseconds next_doffset = std::get<1>(*it) - sample_ns;
+ chrono::nanoseconds prior_dt =
+ monotonic_now.time - std::get<0>(*(it - 1));
+ chrono::nanoseconds prior_doffset =
+ sample_ns.duration - std::get<1>(*(it - 1));
+ chrono::nanoseconds next_dt = std::get<0>(*it) - monotonic_now.time;
+ chrono::nanoseconds next_doffset = std::get<1>(*it) - sample_ns.duration;
// If we are worse than either the previous or next point, discard.
if (absl::int128(prior_doffset.count()) *
@@ -1517,8 +1547,8 @@
// Now, insert and start propagating forwards and backwards anything we've
// made invalid. Do this simultaneously so we keep discovering anything
// new.
- auto middle_it =
- timestamps_.insert(it, std::make_tuple(monotonic_now, sample_ns));
+ auto middle_it = timestamps_.insert(
+ it, std::make_tuple(monotonic_now.time, sample_ns.duration));
VLOG(1) << node_names_ << " Inserted " << TimeString(*middle_it);
while (middle_it != timestamps_.end() && middle_it != timestamps_.begin()) {
@@ -1661,16 +1691,80 @@
return next_to_consume_ + 1 < timestamps_.size();
}
+std::optional<std::tuple<logger::BootTimestamp, logger::BootDuration>>
+NoncausalTimestampFilter::Observe() const {
+ if (filters_.size() == 0u) {
+ return std::nullopt;
+ }
+
+ size_t current_filter = std::max(static_cast<ssize_t>(0), current_filter_);
+ while (true) {
+ const BootFilter &filter = *filters_[current_filter];
+ std::optional<
+ std::tuple<monotonic_clock::time_point, std::chrono::nanoseconds>>
+ result = filter.filter.Observe();
+ if (!result) {
+ if (current_filter + 1 == filters_.size()) {
+ return std::nullopt;
+ } else {
+ ++current_filter;
+ continue;
+ }
+ }
+ auto final_result = std::make_tuple(
+ logger::BootTimestamp{static_cast<size_t>(filter.boot.first),
+ std::get<0>(*result)},
+ logger::BootDuration{static_cast<size_t>(filter.boot.second),
+ std::get<1>(*result)});
+ VLOG(1) << NodeNames() << " Observed sample of "
+ << TimeString(final_result);
+ return final_result;
+ }
+}
+
std::optional<std::tuple<monotonic_clock::time_point, std::chrono::nanoseconds>>
NoncausalTimestampFilter::SingleFilter::Observe() const {
if (timestamps_.empty() || next_to_consume_ >= timestamps_.size()) {
return std::nullopt;
}
- VLOG(1) << node_names_ << " Observed sample of "
+ VLOG(2) << node_names_ << " Observed sample of "
<< TimeString(timestamp(next_to_consume_));
return timestamp(next_to_consume_);
}
+std::optional<std::tuple<logger::BootTimestamp, logger::BootDuration>>
+NoncausalTimestampFilter::Consume() {
+ if (filters_.size() == 0u) {
+ return std::nullopt;
+ }
+ DCHECK_LT(current_filter_, static_cast<ssize_t>(filters_.size()));
+
+ while (true) {
+ std::optional<
+ std::tuple<monotonic_clock::time_point, std::chrono::nanoseconds>>
+ result =
+ current_filter_ < 0 ? std::nullopt
+ : filters_[current_filter_]->filter.Consume();
+ if (!result) {
+ if (static_cast<size_t>(current_filter_ + 1) == filters_.size()) {
+ return std::nullopt;
+ } else {
+ ++current_filter_;
+ continue;
+ }
+ }
+ BootFilter &filter = *filters_[current_filter_];
+ auto final_result = std::make_tuple(
+ logger::BootTimestamp{static_cast<size_t>(filter.boot.first),
+ std::get<0>(*result)},
+ logger::BootDuration{static_cast<size_t>(filter.boot.second),
+ std::get<1>(*result)});
+ VLOG(1) << NodeNames() << " Consumed sample of "
+ << TimeString(final_result);
+ return final_result;
+ }
+}
+
std::optional<std::tuple<monotonic_clock::time_point, std::chrono::nanoseconds>>
NoncausalTimestampFilter::SingleFilter::Consume() {
if (timestamps_.empty() || next_to_consume_ >= timestamps_.size()) {
@@ -1678,7 +1772,7 @@
}
auto result = timestamp(next_to_consume_);
- VLOG(1) << node_names_ << " Consumed sample of " << TimeString(result);
+ VLOG(2) << node_names_ << " Consumed sample of " << TimeString(result);
++next_to_consume_;
return result;
}
diff --git a/aos/network/timestamp_filter.h b/aos/network/timestamp_filter.h
index be9318e..2361797 100644
--- a/aos/network/timestamp_filter.h
+++ b/aos/network/timestamp_filter.h
@@ -469,63 +469,11 @@
// because solving for them doesn't add any additional value. We will already
// be solving the other direction.
std::optional<std::tuple<logger::BootTimestamp, logger::BootDuration>>
- Observe() const {
- if (filters_.size() == 0u) {
- return std::nullopt;
- }
-
- size_t current_filter = std::max(static_cast<ssize_t>(0), current_filter_);
- while (true) {
- const BootFilter &filter = *filters_[current_filter];
- std::optional<
- std::tuple<monotonic_clock::time_point, std::chrono::nanoseconds>>
- result = filter.filter.Observe();
- if (!result) {
- if (current_filter + 1 == filters_.size()) {
- return std::nullopt;
- } else {
- ++current_filter;
- continue;
- }
- }
- return std::make_tuple(
- logger::BootTimestamp{static_cast<size_t>(filter.boot.first),
- std::get<0>(*result)},
- logger::BootDuration{static_cast<size_t>(filter.boot.second),
- std::get<1>(*result)});
- }
- }
+ Observe() const;
// Returns the next timestamp in the queue if available, incrementing the
// pointer.
std::optional<std::tuple<logger::BootTimestamp, logger::BootDuration>>
- Consume() {
- if (filters_.size() == 0u) {
- return std::nullopt;
- }
- DCHECK_LT(current_filter_, static_cast<ssize_t>(filters_.size()));
-
- while (true) {
- std::optional<
- std::tuple<monotonic_clock::time_point, std::chrono::nanoseconds>>
- result =
- current_filter_ < 0 ? std::nullopt
- : filters_[current_filter_]->filter.Consume();
- if (!result) {
- if (static_cast<size_t>(current_filter_ + 1) == filters_.size()) {
- return std::nullopt;
- } else {
- ++current_filter_;
- continue;
- }
- }
- BootFilter &filter = *filters_[current_filter_];
- return std::make_tuple(
- logger::BootTimestamp{static_cast<size_t>(filter.boot.first),
- std::get<0>(*result)},
- logger::BootDuration{static_cast<size_t>(filter.boot.second),
- std::get<1>(*result)});
- }
- }
+ Consume();
// Public for testing.
// Assuming that there are at least 2 points in timestamps_, finds the 2
@@ -736,8 +684,8 @@
aos::monotonic_clock::time_point tb_base, double tb,
bool validate_popped, bool quiet) const;
- void Sample(monotonic_clock::time_point monotonic_now,
- std::chrono::nanoseconds sample_ns);
+ void Sample(logger::BootTimestamp monotonic_now,
+ logger::BootDuration sample_ns);
private:
std::string node_names_;
diff --git a/aos/network/timestamp_filter_test.cc b/aos/network/timestamp_filter_test.cc
index f3b7290..0c37ed5 100644
--- a/aos/network/timestamp_filter_test.cc
+++ b/aos/network/timestamp_filter_test.cc
@@ -797,9 +797,10 @@
filter.FreezeUntil(tb, {0, monotonic_clock::min_time});
EXPECT_DEATH({ filter.Sample(tb, oa); },
- "monotonic_now > frozen_time_ \\(0.100000000sec vs. "
+ "monotonic_now.time > frozen_time_ \\(0.100000000sec vs. "
"0.100000000sec\\) : test_a -> test_b Tried to insert "
- "0.100000000sec before the frozen time of 0.100000000sec. "
+ "\\{.boot=0, .time=0.100000000sec\\} before the frozen time "
+ "of 0.100000000sec. "
"Increase --time_estimation_buffer_seconds to greater than 0");
}
@@ -816,7 +817,8 @@
{ filter.Sample(tc, oc); },
"test_a -> test_b Returned a horizontal line previously and then got a "
"new sample at "
- "0.200000000sec, 0.2 seconds after the last sample at 0.000000000sec");
+ "\\{.boot=0, .time=0.200000000sec\\}, 0.2 seconds after the last "
+ "sample at 0.000000000sec");
}
{
@@ -830,9 +832,10 @@
EXPECT_DEATH(
{ filter.Sample(tb, ob); },
- "monotonic_now > frozen_time_ \\(0.100000000sec vs. "
+ "monotonic_now.time > frozen_time_ \\(0.100000000sec vs. "
"0.200000000sec\\) : test_a -> test_b Tried to insert "
- "0.100000000sec before the frozen time of 0.200000000sec. "
+ "\\{.boot=0, .time=0.100000000sec\\} before the frozen time of "
+ "0.200000000sec. "
"Increase --time_estimation_buffer_seconds to greater than 0.1");
}
@@ -848,9 +851,10 @@
filter.FreezeUntil(tb, {0, monotonic_clock::min_time});
EXPECT_DEATH({ filter.Sample(tb, oa); },
- "monotonic_now > frozen_time_ \\(0.100000000sec vs. "
+ "monotonic_now.time > frozen_time_ \\(0.100000000sec vs. "
"0.100000000sec\\) : test_a -> test_b Tried to insert "
- "0.100000000sec before the frozen time of 0.100000000sec. "
+ "\\{.boot=0, .time=0.100000000sec\\} before the frozen time "
+ "of 0.100000000sec. "
"Increase --time_estimation_buffer_seconds to greater than 0");
EXPECT_DEATH({ filter.Sample(tb + chrono::nanoseconds(1), oa); },
"test_a -> test_b Can't pop an already frozen sample");