Log the timestamp each part file is created too
This gives us another tool for helping figure out which boot came first,
and also debug how/when log parts are written.
Change-Id: I015a5024ceaa3b95af7ff621de706ef16cff55e8
Signed-off-by: Austin Schuh <austin.schuh@bluerivertech.com>
diff --git a/aos/events/logging/log_namer.cc b/aos/events/logging/log_namer.cc
index 5ab4636..a4b15e8 100644
--- a/aos/events/logging/log_namer.cc
+++ b/aos/events/logging/log_namer.cc
@@ -125,7 +125,7 @@
const UUID &source_node_boot_uuid = boot_uuids[node_index];
const Node *const source_node =
configuration::GetNode(configuration_, node_index);
- CHECK_EQ(LogFileHeader::MiniReflectTypeTable()->num_elems, 18u);
+ CHECK_EQ(LogFileHeader::MiniReflectTypeTable()->num_elems, 20u);
flatbuffers::FlatBufferBuilder fbb;
fbb.ForceDefaults(true);
@@ -255,6 +255,14 @@
}
log_file_header_builder.add_boot_uuids(boot_uuids_offset);
+ log_file_header_builder.add_logger_part_monotonic_start_time(
+ std::chrono::duration_cast<std::chrono::nanoseconds>(
+ event_loop_->monotonic_now().time_since_epoch())
+ .count());
+ log_file_header_builder.add_logger_part_realtime_start_time(
+ std::chrono::duration_cast<std::chrono::nanoseconds>(
+ event_loop_->realtime_now().time_since_epoch())
+ .count());
fbb.FinishSizePrefixed(log_file_header_builder.Finish());
aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> result(
fbb.Release());
@@ -303,9 +311,8 @@
}
MultiNodeLogNamer::MultiNodeLogNamer(std::string_view base_name,
- const Configuration *configuration,
- const Node *node)
- : LogNamer(configuration, node), base_name_(base_name), old_base_name_() {}
+ EventLoop *event_loop)
+ : LogNamer(event_loop), base_name_(base_name), old_base_name_() {}
MultiNodeLogNamer::~MultiNodeLogNamer() {
if (!ran_out_of_space_) {
diff --git a/aos/events/logging/log_namer.h b/aos/events/logging/log_namer.h
index b6efb80..d9f42db 100644
--- a/aos/events/logging/log_namer.h
+++ b/aos/events/logging/log_namer.h
@@ -96,10 +96,11 @@
public:
// Constructs a LogNamer with the primary node (ie the one the logger runs on)
// being node.
- LogNamer(const Configuration *configuration, const Node *node)
- : configuration_(configuration),
- node_(node),
- logger_node_index_(configuration::GetNodeIndex(configuration_, node)) {
+ LogNamer(EventLoop *event_loop)
+ : event_loop_(event_loop),
+ configuration_(event_loop_->configuration()),
+ node_(event_loop_->node()),
+ logger_node_index_(configuration::GetNodeIndex(configuration_, node_)) {
nodes_.emplace_back(node_);
node_states_.resize(configuration::NodesCount(configuration_));
}
@@ -187,6 +188,7 @@
size_t node_index, const std::vector<UUID> &boot_uuids,
const UUID &parts_uuid, int parts_index) const;
+ EventLoop *event_loop_;
const Configuration *const configuration_;
const Node *const node_;
const size_t logger_node_index_;
@@ -221,11 +223,10 @@
// any other log type.
class LocalLogNamer : public LogNamer {
public:
- LocalLogNamer(std::string_view base_name, const Configuration *configuration,
- const Node *node)
- : LogNamer(configuration, node),
+ LocalLogNamer(std::string_view base_name, aos::EventLoop *event_loop)
+ : LogNamer(event_loop),
base_name_(base_name),
- data_writer_(this, node,
+ data_writer_(this, node(),
[this](NewDataWriter *writer) {
writer->writer = std::make_unique<DetachedBufferWriter>(
absl::StrCat(base_name_, ".part",
@@ -269,8 +270,7 @@
// Log namer which uses a config and a base name to name a bunch of files.
class MultiNodeLogNamer : public LogNamer {
public:
- MultiNodeLogNamer(std::string_view base_name,
- const Configuration *configuration, const Node *node);
+ MultiNodeLogNamer(std::string_view base_name, EventLoop *event_loop);
~MultiNodeLogNamer() override;
std::string_view base_name() const final { return base_name_; }
diff --git a/aos/events/logging/log_writer.h b/aos/events/logging/log_writer.h
index a93da7d..f624028 100644
--- a/aos/events/logging/log_writer.h
+++ b/aos/events/logging/log_writer.h
@@ -149,8 +149,7 @@
// starts.
void StartLoggingLocalNamerOnRun(std::string base_name) {
event_loop_->OnRun([this, base_name]() {
- StartLogging(std::make_unique<LocalLogNamer>(
- base_name, event_loop_->configuration(), event_loop_->node()));
+ StartLogging(std::make_unique<LocalLogNamer>(base_name, event_loop_));
});
}
@@ -158,8 +157,7 @@
// processing starts.
void StartLoggingOnRun(std::string base_name) {
event_loop_->OnRun([this, base_name]() {
- StartLogging(std::make_unique<MultiNodeLogNamer>(
- base_name, event_loop_->configuration(), event_loop_->node()));
+ StartLogging(std::make_unique<MultiNodeLogNamer>(base_name, event_loop_));
});
}
diff --git a/aos/events/logging/logfile_sorting.cc b/aos/events/logging/logfile_sorting.cc
index 118ddf7..1821039 100644
--- a/aos/events/logging/logfile_sorting.cc
+++ b/aos/events/logging/logfile_sorting.cc
@@ -33,7 +33,7 @@
}
bool ConfigOnly(const LogFileHeader *header) {
- CHECK_EQ(LogFileHeader::MiniReflectTypeTable()->num_elems, 18u);
+ CHECK_EQ(LogFileHeader::MiniReflectTypeTable()->num_elems, 20u);
if (header->has_monotonic_start_time()) return false;
if (header->has_realtime_start_time()) return false;
if (header->has_max_out_of_order_duration()) return false;
@@ -51,6 +51,8 @@
if (header->has_parts_index()) return false;
if (header->has_logger_node()) return false;
if (header->has_boot_uuids()) return false;
+ if (header->has_logger_part_monotonic_start_time()) return false;
+ if (header->has_logger_part_realtime_start_time()) return false;
return header->has_configuration();
}
diff --git a/aos/events/logging/logger.fbs b/aos/events/logging/logger.fbs
index d5f1248..23da360 100644
--- a/aos/events/logging/logger.fbs
+++ b/aos/events/logging/logger.fbs
@@ -97,6 +97,10 @@
// The boot UUIDs for all nodes we know them for, or "" for the ones we don't.
// TODO(austin): Actually add this in the log writer.
boot_uuids:[string] (id: 17);
+
+ // Timestamps that the header on this part file was written on the logger node.
+ logger_part_monotonic_start_time:int64 = -9223372036854775808 (id: 18);
+ logger_part_realtime_start_time:int64 = -9223372036854775808 (id: 19);
}
// Table holding a message.
diff --git a/aos/events/logging/logger_main.cc b/aos/events/logging/logger_main.cc
index dd1d8a2..083fdb0 100644
--- a/aos/events/logging/logger_main.cc
+++ b/aos/events/logging/logger_main.cc
@@ -31,8 +31,7 @@
std::unique_ptr<aos::logger::LogNamer> log_namer;
log_namer = std::make_unique<aos::logger::MultiNodeLogNamer>(
- absl::StrCat(aos::logging::GetLogName("fbs_log"), "/"),
- event_loop.configuration(), event_loop.node());
+ absl::StrCat(aos::logging::GetLogName("fbs_log"), "/"), &event_loop);
aos::logger::Logger logger(&event_loop);
event_loop.OnRun([&log_namer, &logger]() {
diff --git a/aos/events/logging/logger_test.cc b/aos/events/logging/logger_test.cc
index a02f4ea..a439f84 100644
--- a/aos/events/logging/logger_test.cc
+++ b/aos/events/logging/logger_test.cc
@@ -170,12 +170,10 @@
logger.set_polling_period(std::chrono::milliseconds(100));
logger_event_loop->OnRun(
[base_name1, base_name2, &logger_event_loop, &logger]() {
- logger.StartLogging(std::make_unique<LocalLogNamer>(
- base_name1, logger_event_loop->configuration(),
- logger_event_loop->node()));
+ logger.StartLogging(
+ std::make_unique<LocalLogNamer>(base_name1, logger_event_loop.get()));
EXPECT_DEATH(logger.StartLogging(std::make_unique<LocalLogNamer>(
- base_name2, logger_event_loop->configuration(),
- logger_event_loop->node())),
+ base_name2, logger_event_loop.get())),
"Already logging");
});
event_loop_factory_.RunFor(chrono::milliseconds(20000));
@@ -205,9 +203,8 @@
logger.set_separate_config(false);
logger.set_polling_period(std::chrono::milliseconds(100));
logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
- logger.StartLogging(std::make_unique<LocalLogNamer>(
- base_name, logger_event_loop->configuration(),
- logger_event_loop->node()));
+ logger.StartLogging(
+ std::make_unique<LocalLogNamer>(base_name, logger_event_loop.get()));
logger.StopLogging(aos::monotonic_clock::min_time);
EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
"Not logging right now");
@@ -243,15 +240,13 @@
Logger logger(logger_event_loop.get());
logger.set_separate_config(false);
logger.set_polling_period(std::chrono::milliseconds(100));
- logger.StartLogging(std::make_unique<LocalLogNamer>(
- base_name1, logger_event_loop->configuration(),
- logger_event_loop->node()));
+ logger.StartLogging(
+ std::make_unique<LocalLogNamer>(base_name1, logger_event_loop.get()));
event_loop_factory_.RunFor(chrono::milliseconds(10000));
logger.StopLogging(logger_event_loop->monotonic_now());
event_loop_factory_.RunFor(chrono::milliseconds(10000));
- logger.StartLogging(std::make_unique<LocalLogNamer>(
- base_name2, logger_event_loop->configuration(),
- logger_event_loop->node()));
+ logger.StartLogging(
+ std::make_unique<LocalLogNamer>(base_name2, logger_event_loop.get()));
event_loop_factory_.RunFor(chrono::milliseconds(10000));
}
@@ -695,9 +690,8 @@
"name_prefix_", logger->event_loop->node()->name()->str()));
logger->event_loop->OnRun([logger, logfile_base, compress]() {
std::unique_ptr<MultiNodeLogNamer> namer =
- std::make_unique<MultiNodeLogNamer>(
- logfile_base, logger->event_loop->configuration(),
- logger->event_loop->node());
+ std::make_unique<MultiNodeLogNamer>(logfile_base,
+ logger->event_loop.get());
if (compress) {
#ifdef LZMA
namer->set_extension(".xz");
diff --git a/y2020/control_loops/drivetrain/drivetrain_replay.cc b/y2020/control_loops/drivetrain/drivetrain_replay.cc
index 8f6ff63..65fc0c4 100644
--- a/y2020/control_loops/drivetrain/drivetrain_replay.cc
+++ b/y2020/control_loops/drivetrain/drivetrain_replay.cc
@@ -33,7 +33,7 @@
namer_(std::make_unique<aos::logger::MultiNodeLogNamer>(
absl::StrCat(FLAGS_output_folder, "/", node->name()->string_view(),
"/"),
- event_loop_->configuration(), node)),
+ event_loop_.get())),
logger_(std::make_unique<aos::logger::Logger>(event_loop_.get())) {
event_loop_->SkipTimingReport();
event_loop_->SkipAosLog();