Record some helpful statistics in Logger
These can be useful for examining and improving the performance.
Change-Id: Ic673ca99cef987ea1aa0388d7884aee4b9ae6ab6
diff --git a/aos/events/logging/log_namer.cc b/aos/events/logging/log_namer.cc
index 06243b0..748da7c 100644
--- a/aos/events/logging/log_namer.cc
+++ b/aos/events/logging/log_namer.cc
@@ -69,15 +69,8 @@
MultiNodeLogNamer::MultiNodeLogNamer(std::string_view base_name,
const Configuration *configuration,
- const Node *node,
- std::string_view temp_suffix)
- : LogNamer(node),
- base_name_(base_name),
- temp_suffix_(temp_suffix),
- configuration_(configuration),
- uuid_(UUID::Random()) {
- OpenDataWriter();
-}
+ const Node *node)
+ : LogNamer(node), base_name_(base_name), configuration_(configuration) {}
MultiNodeLogNamer::~MultiNodeLogNamer() {
if (!ran_out_of_space_) {
@@ -90,8 +83,11 @@
aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header,
const Node *node) {
if (node == this->node()) {
- UpdateHeader(header, uuid_, part_number_);
- data_writer_->QueueSpan(header->full_span());
+ if (!data_writer_.writer) {
+ OpenDataWriter();
+ }
+ UpdateHeader(header, data_writer_.uuid, data_writer_.part_number);
+ data_writer_.writer->QueueSpan(header->full_span());
} else {
for (std::pair<const Channel *const, DataWriter> &data_writer :
data_writers_) {
@@ -108,10 +104,12 @@
const Node *node,
aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header) {
if (node == this->node()) {
- ++part_number_;
+ if (data_writer_.writer) {
+ ++data_writer_.part_number;
+ }
OpenDataWriter();
- UpdateHeader(header, uuid_, part_number_);
- data_writer_->QueueSpan(header->full_span());
+ UpdateHeader(header, data_writer_.uuid, data_writer_.part_number);
+ data_writer_.writer->QueueSpan(header->full_span());
} else {
for (std::pair<const Channel *const, DataWriter> &data_writer :
data_writers_) {
@@ -145,7 +143,10 @@
// Now, sort out if this is data generated on this node, or not. It is
// generated if it is sendable on this node.
if (configuration::ChannelIsSendableOnNode(channel, this->node())) {
- return data_writer_.get();
+ if (!data_writer_.writer) {
+ OpenDataWriter();
+ }
+ return data_writer_.writer.get();
}
// Ok, we have data that is being forwarded to us that we are supposed to
@@ -207,31 +208,37 @@
return nullptr;
}
- return data_writer_.get();
+ if (!data_writer_.writer) {
+ OpenDataWriter();
+ }
+ return data_writer_.writer.get();
}
void MultiNodeLogNamer::Close() {
for (std::pair<const Channel *const, DataWriter> &data_writer :
data_writers_) {
- if (data_writer.second.writer) {
- data_writer.second.writer->Close();
- if (data_writer.second.writer->ran_out_of_space()) {
- ran_out_of_space_ = true;
- data_writer.second.writer->acknowledge_out_of_space();
- }
- RenameTempFile(data_writer.second.writer.get());
- data_writer.second.writer.reset();
- }
+ CloseWriter(&data_writer.second.writer);
+ data_writer.second.writer.reset();
}
- if (data_writer_) {
- data_writer_->Close();
- if (data_writer_->ran_out_of_space()) {
- ran_out_of_space_ = true;
- data_writer_->acknowledge_out_of_space();
- }
- RenameTempFile(data_writer_.get());
- data_writer_.reset();
+ CloseWriter(&data_writer_.writer);
+ data_writer_.writer.reset();
+}
+
+void MultiNodeLogNamer::ResetStatistics() {
+ for (std::pair<const Channel *const, DataWriter> &data_writer :
+ data_writers_) {
+ data_writer.second.writer->ResetStatistics();
}
+ if (data_writer_.writer) {
+ data_writer_.writer->ResetStatistics();
+ }
+ max_write_time_ = std::chrono::nanoseconds::zero();
+ max_write_time_bytes_ = -1;
+ max_write_time_messages_ = -1;
+ total_write_time_ = std::chrono::nanoseconds::zero();
+ total_write_count_ = 0;
+ total_write_messages_ = 0;
+ total_write_bytes_ = 0;
}
void MultiNodeLogNamer::OpenForwardedTimestampWriter(const Channel *channel,
@@ -248,7 +255,7 @@
const std::string filename = absl::StrCat(
"_", CHECK_NOTNULL(channel->source_node())->string_view(), "_data",
channel->name()->string_view(), "/", channel->type()->string_view(),
- ".part", data_writer->part_number, ".bfbs");
+ ".part", data_writer->part_number, ".bfbs", extension_);
CreateBufferWriter(filename, &data_writer->writer);
}
@@ -257,8 +264,9 @@
if (node() != nullptr) {
name = absl::StrCat(name, "_", node()->name()->string_view());
}
- absl::StrAppend(&name, "_data.part", part_number_, ".bfbs");
- CreateBufferWriter(name, &data_writer_);
+ absl::StrAppend(&name, "_data.part", data_writer_.part_number, ".bfbs",
+ extension_);
+ CreateBufferWriter(name, &data_writer_.writer);
}
void MultiNodeLogNamer::CreateBufferWriter(
@@ -272,19 +280,17 @@
const std::string filename = absl::StrCat(base_name_, path, temp_suffix_);
if (!destination->get()) {
all_filenames_.emplace_back(path);
- *destination = std::make_unique<DetachedBufferWriter>(
- filename, std::make_unique<DummyEncoder>());
+ *destination =
+ std::make_unique<DetachedBufferWriter>(filename, encoder_factory_());
return;
}
- destination->get()->Close();
- if (destination->get()->ran_out_of_space()) {
- ran_out_of_space_ = true;
+
+ CloseWriter(destination);
+ if (ran_out_of_space_) {
return;
}
- RenameTempFile(destination->get());
all_filenames_.emplace_back(path);
- *destination->get() =
- DetachedBufferWriter(filename, std::make_unique<DummyEncoder>());
+ *destination->get() = DetachedBufferWriter(filename, encoder_factory_());
}
void MultiNodeLogNamer::RenameTempFile(DetachedBufferWriter *destination) {
@@ -307,5 +313,30 @@
}
}
+void MultiNodeLogNamer::CloseWriter(
+ std::unique_ptr<DetachedBufferWriter> *writer_pointer) {
+ DetachedBufferWriter *const writer = writer_pointer->get();
+ if (!writer) {
+ return;
+ }
+ writer->Close();
+
+ if (writer->max_write_time() > max_write_time_) {
+ max_write_time_ = writer->max_write_time();
+ max_write_time_bytes_ = writer->max_write_time_bytes();
+ max_write_time_messages_ = writer->max_write_time_messages();
+ }
+ total_write_time_ += writer->total_write_time();
+ total_write_count_ += writer->total_write_count();
+ total_write_messages_ += writer->total_write_messages();
+ total_write_bytes_ += writer->total_write_bytes();
+
+ if (writer->ran_out_of_space()) {
+ ran_out_of_space_ = true;
+ writer->acknowledge_out_of_space();
+ }
+ RenameTempFile(writer);
+}
+
} // namespace logger
} // namespace aos
diff --git a/aos/events/logging/log_namer.h b/aos/events/logging/log_namer.h
index d9601ae..6d91b69 100644
--- a/aos/events/logging/log_namer.h
+++ b/aos/events/logging/log_namer.h
@@ -122,6 +122,12 @@
// 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() override;
+
+ std::string_view base_name() const { return base_name_; }
+
// If temp_suffix is set, then this will write files under names beginning
// with the specified suffix, and then rename them to the desired name after
// they are fully written.
@@ -129,12 +135,22 @@
// This is useful to enable incremental copying of the log files.
//
// Defaults to writing directly to the final filename.
- MultiNodeLogNamer(std::string_view base_name,
- const Configuration *configuration, const Node *node,
- std::string_view temp_suffix = "");
- ~MultiNodeLogNamer() override;
+ void set_temp_suffix(std::string_view temp_suffix) {
+ temp_suffix_ = temp_suffix;
+ }
- std::string_view base_name() const { return base_name_; }
+ // Sets the function for creating encoders.
+ //
+ // Defaults to just creating DummyEncoders.
+ void set_encoder_factory(
+ std::function<std::unique_ptr<DetachedBufferEncoder>()> encoder_factory) {
+ encoder_factory_ = std::move(encoder_factory);
+ }
+
+ // Sets an additional file extension.
+ //
+ // Defaults to nothing.
+ void set_extension(std::string_view extension) { extension_ = extension; }
// A list of all the filenames we've written.
//
@@ -172,15 +188,10 @@
//
// Returns 0 if no files are open.
size_t maximum_total_bytes() const {
- size_t result = 0;
- for (const std::pair<const Channel *const, DataWriter> &data_writer :
- data_writers_) {
- result = std::max(result, data_writer.second.writer->total_bytes());
- }
- if (data_writer_) {
- result = std::max(result, data_writer_->total_bytes());
- }
- return result;
+ return accumulate_data_writers<size_t>(
+ 0, [](size_t x, const DataWriter &data_writer) {
+ return std::max(x, data_writer.writer->total_bytes());
+ });
}
// Closes all existing log files. No more data may be written after this.
@@ -188,6 +199,69 @@
// This may set ran_out_of_space().
void Close();
+ // Accessors for various statistics. See the identically-named methods in
+ // DetachedBufferWriter for documentation. These are aggregated across all
+ // past and present DetachedBufferWriters.
+ std::chrono::nanoseconds max_write_time() const {
+ return accumulate_data_writers(
+ max_write_time_,
+ [](std::chrono::nanoseconds x, const DataWriter &data_writer) {
+ return std::max(x, data_writer.writer->max_write_time());
+ });
+ }
+ int max_write_time_bytes() const {
+ return std::get<0>(accumulate_data_writers(
+ std::make_tuple(max_write_time_bytes_, max_write_time_),
+ [](std::tuple<int, std::chrono::nanoseconds> x,
+ const DataWriter &data_writer) {
+ if (data_writer.writer->max_write_time() > std::get<1>(x)) {
+ return std::make_tuple(data_writer.writer->max_write_time_bytes(),
+ data_writer.writer->max_write_time());
+ }
+ return x;
+ }));
+ }
+ int max_write_time_messages() const {
+ return std::get<0>(accumulate_data_writers(
+ std::make_tuple(max_write_time_messages_, max_write_time_),
+ [](std::tuple<int, std::chrono::nanoseconds> x,
+ const DataWriter &data_writer) {
+ if (data_writer.writer->max_write_time() > std::get<1>(x)) {
+ return std::make_tuple(
+ data_writer.writer->max_write_time_messages(),
+ data_writer.writer->max_write_time());
+ }
+ return x;
+ }));
+ }
+ std::chrono::nanoseconds total_write_time() const {
+ return accumulate_data_writers(
+ total_write_time_,
+ [](std::chrono::nanoseconds x, const DataWriter &data_writer) {
+ return x + data_writer.writer->total_write_time();
+ });
+ }
+ int total_write_count() const {
+ return accumulate_data_writers(
+ total_write_count_, [](int x, const DataWriter &data_writer) {
+ return x + data_writer.writer->total_write_count();
+ });
+ }
+ int total_write_messages() const {
+ return accumulate_data_writers(
+ total_write_messages_, [](int x, const DataWriter &data_writer) {
+ return x + data_writer.writer->total_write_messages();
+ });
+ }
+ int total_write_bytes() const {
+ return accumulate_data_writers(
+ total_write_bytes_, [](int x, const DataWriter &data_writer) {
+ return x + data_writer.writer->total_write_bytes();
+ });
+ }
+
+ void ResetStatistics();
+
private:
// Files to write remote data to. We want one per channel. Maps the channel
// to the writer, Node, and part number.
@@ -195,7 +269,7 @@
std::unique_ptr<DetachedBufferWriter> writer = nullptr;
const Node *node;
size_t part_number = 0;
- UUID uuid = UUID::Random();
+ const UUID uuid = UUID::Random();
std::function<void(const Channel *, DataWriter *)> rotate;
};
@@ -214,18 +288,43 @@
void RenameTempFile(DetachedBufferWriter *destination);
- const std::string base_name_;
- const std::string temp_suffix_;
- const Configuration *const configuration_;
- const UUID uuid_;
+ void CloseWriter(std::unique_ptr<DetachedBufferWriter> *writer_pointer);
- size_t part_number_ = 0;
+ // A version of std::accumulate which operates over all of our DataWriters.
+ template <typename T, typename BinaryOperation>
+ T accumulate_data_writers(T t, BinaryOperation op) const {
+ for (const std::pair<const Channel *const, DataWriter> &data_writer :
+ data_writers_) {
+ t = op(std::move(t), data_writer.second);
+ }
+ if (data_writer_.writer) {
+ t = op(std::move(t), data_writer_);
+ }
+ return t;
+ }
+
+ const std::string base_name_;
+ const Configuration *const configuration_;
bool ran_out_of_space_ = false;
std::vector<std::string> all_filenames_;
+ std::string temp_suffix_;
+ std::function<std::unique_ptr<DetachedBufferEncoder>()> encoder_factory_ =
+ []() { return std::make_unique<DummyEncoder>(); };
+ std::string extension_;
+
+ // Storage for statistics from previously-rotated DetachedBufferWriters.
+ std::chrono::nanoseconds max_write_time_ = std::chrono::nanoseconds::zero();
+ int max_write_time_bytes_ = -1;
+ int max_write_time_messages_ = -1;
+ std::chrono::nanoseconds total_write_time_ = std::chrono::nanoseconds::zero();
+ int total_write_count_ = 0;
+ int total_write_messages_ = 0;
+ int total_write_bytes_ = 0;
+
// File to write both delivery timestamps and local data to.
- std::unique_ptr<DetachedBufferWriter> data_writer_;
+ DataWriter data_writer_;
std::map<const Channel *, DataWriter> data_writers_;
};
diff --git a/aos/events/logging/logger.cc b/aos/events/logging/logger.cc
index 33d2abb..d206d5d 100644
--- a/aos/events/logging/logger.cc
+++ b/aos/events/logging/logger.cc
@@ -230,7 +230,13 @@
// so we can capture the latest message on each channel. This lets us have
// non periodic messages with configuration that now get logged.
for (FetcherStruct &f : fetchers_) {
- f.written = !f.fetcher->Fetch();
+ const auto start = event_loop_->monotonic_now();
+ const bool got_new = f.fetcher->Fetch();
+ const auto end = event_loop_->monotonic_now();
+ RecordFetchResult(start, end, got_new, &f);
+
+ // If there is a message, we want to write it.
+ f.written = f.fetcher->context().data == nullptr;
}
// Clear out any old timestamps in case we are re-starting logging.
@@ -476,6 +482,23 @@
return fbb.Release();
}
+void Logger::ResetStatisics() {
+ max_message_fetch_time_ = std::chrono::nanoseconds::zero();
+ max_message_fetch_time_channel_ = -1;
+ max_message_fetch_time_size_ = -1;
+ total_message_fetch_time_ = std::chrono::nanoseconds::zero();
+ total_message_fetch_count_ = 0;
+ total_message_fetch_bytes_ = 0;
+ total_nop_fetch_time_ = std::chrono::nanoseconds::zero();
+ total_nop_fetch_count_ = 0;
+ max_copy_time_ = std::chrono::nanoseconds::zero();
+ max_copy_time_channel_ = -1;
+ max_copy_time_size_ = -1;
+ total_copy_time_ = std::chrono::nanoseconds::zero();
+ total_copy_count_ = 0;
+ total_copy_bytes_ = 0;
+}
+
void Logger::Rotate() {
for (const Node *node : log_namer_->nodes()) {
const int node_index = configuration::GetNodeIndex(configuration_, node);
@@ -490,110 +513,119 @@
for (FetcherStruct &f : fetchers_) {
while (true) {
if (f.written) {
- if (!f.fetcher->FetchNext()) {
+ const auto start = event_loop_->monotonic_now();
+ const bool got_new = f.fetcher->FetchNext();
+ const auto end = event_loop_->monotonic_now();
+ RecordFetchResult(start, end, got_new, &f);
+ if (!got_new) {
VLOG(2) << "No new data on "
<< configuration::CleanedChannelToString(
f.fetcher->channel());
break;
- } else {
- f.written = false;
}
+ f.written = false;
}
- CHECK(!f.written);
-
// TODO(james): Write tests to exercise this logic.
- if (f.fetcher->context().monotonic_event_time < t) {
- if (f.writer != nullptr) {
- // Write!
- flatbuffers::FlatBufferBuilder fbb(f.fetcher->context().size +
- max_header_size_);
- fbb.ForceDefaults(true);
-
- fbb.FinishSizePrefixed(PackMessage(&fbb, f.fetcher->context(),
- f.channel_index, f.log_type));
-
- VLOG(2) << "Writing data as node "
- << FlatbufferToJson(event_loop_->node()) << " for channel "
- << configuration::CleanedChannelToString(f.fetcher->channel())
- << " to " << f.writer->filename() << " data "
- << FlatbufferToJson(
- flatbuffers::GetSizePrefixedRoot<MessageHeader>(
- fbb.GetBufferPointer()));
-
- max_header_size_ = std::max(
- max_header_size_, fbb.GetSize() - f.fetcher->context().size);
- f.writer->QueueSizedFlatbuffer(&fbb);
- }
-
- if (f.timestamp_writer != nullptr) {
- // And now handle timestamps.
- flatbuffers::FlatBufferBuilder fbb;
- fbb.ForceDefaults(true);
-
- fbb.FinishSizePrefixed(PackMessage(&fbb, f.fetcher->context(),
- f.channel_index,
- LogType::kLogDeliveryTimeOnly));
-
- VLOG(2) << "Writing timestamps as node "
- << FlatbufferToJson(event_loop_->node()) << " for channel "
- << configuration::CleanedChannelToString(f.fetcher->channel())
- << " to " << f.timestamp_writer->filename() << " timestamp "
- << FlatbufferToJson(
- flatbuffers::GetSizePrefixedRoot<MessageHeader>(
- fbb.GetBufferPointer()));
-
- f.timestamp_writer->QueueSizedFlatbuffer(&fbb);
- }
-
- if (f.contents_writer != nullptr) {
- // And now handle the special message contents channel. Copy the
- // message into a FlatBufferBuilder and save it to disk.
- // TODO(austin): We can be more efficient here when we start to
- // care...
- flatbuffers::FlatBufferBuilder fbb;
- fbb.ForceDefaults(true);
-
- const MessageHeader *msg =
- flatbuffers::GetRoot<MessageHeader>(f.fetcher->context().data);
-
- logger::MessageHeader::Builder message_header_builder(fbb);
-
- // TODO(austin): This needs to check the channel_index and confirm
- // that it should be logged before squirreling away the timestamp to
- // disk. We don't want to log irrelevant timestamps.
-
- // Note: this must match the same order as MessageBridgeServer and
- // PackMessage. We want identical headers to have identical
- // on-the-wire formats to make comparing them easier.
-
- // Translate from the channel index that the event loop uses to the
- // channel index in the log file.
- message_header_builder.add_channel_index(
- event_loop_to_logged_channel_index_[msg->channel_index()]);
-
- message_header_builder.add_queue_index(msg->queue_index());
- message_header_builder.add_monotonic_sent_time(
- msg->monotonic_sent_time());
- message_header_builder.add_realtime_sent_time(
- msg->realtime_sent_time());
-
- message_header_builder.add_monotonic_remote_time(
- msg->monotonic_remote_time());
- message_header_builder.add_realtime_remote_time(
- msg->realtime_remote_time());
- message_header_builder.add_remote_queue_index(
- msg->remote_queue_index());
-
- fbb.FinishSizePrefixed(message_header_builder.Finish());
-
- f.contents_writer->QueueSizedFlatbuffer(&fbb);
- }
-
- f.written = true;
- } else {
+ if (f.fetcher->context().monotonic_event_time >= t) {
break;
}
+ if (f.writer != nullptr) {
+ // Write!
+ const auto start = event_loop_->monotonic_now();
+ flatbuffers::FlatBufferBuilder fbb(f.fetcher->context().size +
+ max_header_size_);
+ fbb.ForceDefaults(true);
+
+ fbb.FinishSizePrefixed(PackMessage(&fbb, f.fetcher->context(),
+ f.channel_index, f.log_type));
+ const auto end = event_loop_->monotonic_now();
+ RecordCreateMessageTime(start, end, &f);
+
+ VLOG(2) << "Writing data as node "
+ << FlatbufferToJson(event_loop_->node()) << " for channel "
+ << configuration::CleanedChannelToString(f.fetcher->channel())
+ << " to " << f.writer->filename() << " data "
+ << FlatbufferToJson(
+ flatbuffers::GetSizePrefixedRoot<MessageHeader>(
+ fbb.GetBufferPointer()));
+
+ max_header_size_ = std::max(max_header_size_,
+ fbb.GetSize() - f.fetcher->context().size);
+ f.writer->QueueSizedFlatbuffer(&fbb);
+ }
+
+ if (f.timestamp_writer != nullptr) {
+ // And now handle timestamps.
+ const auto start = event_loop_->monotonic_now();
+ flatbuffers::FlatBufferBuilder fbb;
+ fbb.ForceDefaults(true);
+
+ fbb.FinishSizePrefixed(PackMessage(&fbb, f.fetcher->context(),
+ f.channel_index,
+ LogType::kLogDeliveryTimeOnly));
+ const auto end = event_loop_->monotonic_now();
+ RecordCreateMessageTime(start, end, &f);
+
+ VLOG(2) << "Writing timestamps as node "
+ << FlatbufferToJson(event_loop_->node()) << " for channel "
+ << configuration::CleanedChannelToString(f.fetcher->channel())
+ << " to " << f.timestamp_writer->filename() << " timestamp "
+ << FlatbufferToJson(
+ flatbuffers::GetSizePrefixedRoot<MessageHeader>(
+ fbb.GetBufferPointer()));
+
+ f.timestamp_writer->QueueSizedFlatbuffer(&fbb);
+ }
+
+ if (f.contents_writer != nullptr) {
+ const auto start = event_loop_->monotonic_now();
+ // And now handle the special message contents channel. Copy the
+ // message into a FlatBufferBuilder and save it to disk.
+ // TODO(austin): We can be more efficient here when we start to
+ // care...
+ flatbuffers::FlatBufferBuilder fbb;
+ fbb.ForceDefaults(true);
+
+ const MessageHeader *msg =
+ flatbuffers::GetRoot<MessageHeader>(f.fetcher->context().data);
+
+ logger::MessageHeader::Builder message_header_builder(fbb);
+
+ // TODO(austin): This needs to check the channel_index and confirm
+ // that it should be logged before squirreling away the timestamp to
+ // disk. We don't want to log irrelevant timestamps.
+
+ // Note: this must match the same order as MessageBridgeServer and
+ // PackMessage. We want identical headers to have identical
+ // on-the-wire formats to make comparing them easier.
+
+ // Translate from the channel index that the event loop uses to the
+ // channel index in the log file.
+ message_header_builder.add_channel_index(
+ event_loop_to_logged_channel_index_[msg->channel_index()]);
+
+ message_header_builder.add_queue_index(msg->queue_index());
+ message_header_builder.add_monotonic_sent_time(
+ msg->monotonic_sent_time());
+ message_header_builder.add_realtime_sent_time(
+ msg->realtime_sent_time());
+
+ message_header_builder.add_monotonic_remote_time(
+ msg->monotonic_remote_time());
+ message_header_builder.add_realtime_remote_time(
+ msg->realtime_remote_time());
+ message_header_builder.add_remote_queue_index(
+ msg->remote_queue_index());
+
+ fbb.FinishSizePrefixed(message_header_builder.Finish());
+ const auto end = event_loop_->monotonic_now();
+ RecordCreateMessageTime(start, end, &f);
+
+ f.contents_writer->QueueSizedFlatbuffer(&fbb);
+ }
+
+ f.written = true;
}
}
last_synchronized_time_ = t;
@@ -616,6 +648,39 @@
} while (last_synchronized_time_ + polling_period_ < end_time);
}
+void Logger::RecordFetchResult(aos::monotonic_clock::time_point start,
+ aos::monotonic_clock::time_point end,
+ bool got_new, FetcherStruct *fetcher) {
+ const auto duration = end - start;
+ if (!got_new) {
+ ++total_nop_fetch_count_;
+ total_nop_fetch_time_ += duration;
+ return;
+ }
+ ++total_message_fetch_count_;
+ total_message_fetch_bytes_ += fetcher->fetcher->context().size;
+ total_message_fetch_time_ += duration;
+ if (duration > max_message_fetch_time_) {
+ max_message_fetch_time_ = duration;
+ max_message_fetch_time_channel_ = fetcher->channel_index;
+ max_message_fetch_time_size_ = fetcher->fetcher->context().size;
+ }
+}
+
+void Logger::RecordCreateMessageTime(aos::monotonic_clock::time_point start,
+ aos::monotonic_clock::time_point end,
+ FetcherStruct *fetcher) {
+ const auto duration = end - start;
+ total_copy_time_ += duration;
+ ++total_copy_count_;
+ total_copy_bytes_ += fetcher->fetcher->context().size;
+ if (duration > max_copy_time_) {
+ max_copy_time_ = duration;
+ max_copy_time_channel_ = fetcher->channel_index;
+ max_copy_time_size_ = fetcher->fetcher->context().size;
+ }
+}
+
std::vector<LogFile> SortParts(const std::vector<std::string> &parts) {
// Start by grouping all parts by UUID, and extracting the part index.
// Datastructure to hold all the info extracted from a set of parts which go
diff --git a/aos/events/logging/logger.h b/aos/events/logging/logger.h
index 230f773..ca4630f 100644
--- a/aos/events/logging/logger.h
+++ b/aos/events/logging/logger.h
@@ -69,6 +69,55 @@
std::string_view log_start_uuid() const { return log_start_uuid_; }
UUID logger_instance_uuid() const { return logger_instance_uuid_; }
+ // The maximum time for a single fetch which returned a message, or 0 if none
+ // of those have happened.
+ std::chrono::nanoseconds max_message_fetch_time() const {
+ return max_message_fetch_time_;
+ }
+ // The channel for that longest fetch which returned a message, or -1 if none
+ // of those have happened.
+ int max_message_fetch_time_channel() const {
+ return max_message_fetch_time_channel_;
+ }
+ // The size of the message returned by that longest fetch, or -1 if none of
+ // those have happened.
+ int max_message_fetch_time_size() const {
+ return max_message_fetch_time_size_;
+ }
+ // The total time spent fetching messages.
+ std::chrono::nanoseconds total_message_fetch_time() const {
+ return total_message_fetch_time_;
+ }
+ // The total number of fetch calls which returned messages.
+ int total_message_fetch_count() const { return total_message_fetch_count_; }
+ // The total number of bytes fetched.
+ int64_t total_message_fetch_bytes() const {
+ return total_message_fetch_bytes_;
+ }
+
+ // The total time spent in fetches which did not return a message.
+ std::chrono::nanoseconds total_nop_fetch_time() const {
+ return total_nop_fetch_time_;
+ }
+ // The total number of fetches which did not return a message.
+ int total_nop_fetch_count() const { return total_nop_fetch_count_; }
+
+ // The maximum time for a single copy, or 0 if none of those have happened.
+ std::chrono::nanoseconds max_copy_time() const { return max_copy_time_; }
+ // The channel for that longest copy, or -1 if none of those have happened.
+ int max_copy_time_channel() const { return max_copy_time_channel_; }
+ // The size of the message for that longest copy, or -1 if none of those have
+ // happened.
+ int max_copy_time_size() const { return max_copy_time_size_; }
+ // The total time spent copying messages.
+ std::chrono::nanoseconds total_copy_time() const { return total_copy_time_; }
+ // The total number of messages copied.
+ int total_copy_count() const { return total_copy_count_; }
+ // The total number of bytes copied.
+ int64_t total_copy_bytes() const { return total_copy_bytes_; }
+
+ void ResetStatisics();
+
// Rotates the log file(s), triggering new part files to be written for each
// log file.
void Rotate();
@@ -162,6 +211,14 @@
// Fetches from each channel until all the data is logged.
void LogUntil(monotonic_clock::time_point t);
+ void RecordFetchResult(aos::monotonic_clock::time_point start,
+ aos::monotonic_clock::time_point end, bool got_new,
+ FetcherStruct *fetcher);
+
+ void RecordCreateMessageTime(aos::monotonic_clock::time_point start,
+ aos::monotonic_clock::time_point end,
+ FetcherStruct *fetcher);
+
// Sets the start time for a specific node.
void SetStartTime(size_t node_index,
aos::monotonic_clock::time_point monotonic_start_time,
@@ -183,6 +240,26 @@
std::function<void()> on_logged_period_ = []() {};
+ std::chrono::nanoseconds max_message_fetch_time_ =
+ std::chrono::nanoseconds::zero();
+ int max_message_fetch_time_channel_ = -1;
+ int max_message_fetch_time_size_ = -1;
+ std::chrono::nanoseconds total_message_fetch_time_ =
+ std::chrono::nanoseconds::zero();
+ int total_message_fetch_count_ = 0;
+ int64_t total_message_fetch_bytes_ = 0;
+
+ std::chrono::nanoseconds total_nop_fetch_time_ =
+ std::chrono::nanoseconds::zero();
+ int total_nop_fetch_count_ = 0;
+
+ std::chrono::nanoseconds max_copy_time_ = std::chrono::nanoseconds::zero();
+ int max_copy_time_channel_ = -1;
+ int max_copy_time_size_ = -1;
+ std::chrono::nanoseconds total_copy_time_ = std::chrono::nanoseconds::zero();
+ int total_copy_count_ = 0;
+ int64_t total_copy_bytes_ = 0;
+
std::vector<FetcherStruct> fetchers_;
TimerHandler *timer_handler_;