Make SimulatedEventLoop log the correct time
Mock time out for LOG statements so the logged time is the simulated
time. This makes it so all the plotting tools will work, and makes it
so it's easier to debug simulations.
Change-Id: I902b6c52dc6008e5812cde9ec6cacdf72f13206e
diff --git a/aos/logging/implementations.cc b/aos/logging/implementations.cc
index f37f0ca..273c583 100644
--- a/aos/logging/implementations.cc
+++ b/aos/logging/implementations.cc
@@ -35,7 +35,7 @@
__attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 3, 0)))
void DoLog(log_level level, const char *format, va_list ap) override {
LogMessage message;
- internal::FillInMessage(level, format, ap, &message);
+ internal::FillInMessage(level, monotonic_now(), format, ap, &message);
internal::PrintMessage(stderr, message);
if (!only_implementation_) {
fputs("root logger got used, see stderr for message\n", stdout);
@@ -79,7 +79,9 @@
namespace internal {
namespace {
-void FillInMessageBase(log_level level, LogMessage *message) {
+void FillInMessageBase(log_level level,
+ monotonic_clock::time_point monotonic_now,
+ LogMessage *message) {
Context *context = Context::Get();
message->level = level;
@@ -87,7 +89,6 @@
memcpy(message->name, context->name, context->name_size);
message->name_length = context->name_size;
- monotonic_clock::time_point monotonic_now = monotonic_clock::now();
message->seconds =
chrono::duration_cast<chrono::seconds>(monotonic_now.time_since_epoch())
.count();
@@ -102,6 +103,7 @@
} // namespace
void FillInMessageStructure(bool add_to_type_cache, log_level level,
+ monotonic_clock::time_point monotonic_now,
const ::std::string &message_string, size_t size,
const MessageType *type,
const ::std::function<size_t(char *)> &serialize,
@@ -111,7 +113,7 @@
}
message->structure.type_id = type->id;
- FillInMessageBase(level, message);
+ FillInMessageBase(level, monotonic_now, message);
if (message_string.size() + size > sizeof(message->structure.serialized)) {
LOG(FATAL,
@@ -129,6 +131,7 @@
}
void FillInMessageMatrix(log_level level,
+ monotonic_clock::time_point monotonic_now,
const ::std::string &message_string, uint32_t type_id,
int rows, int cols, const void *data,
LogMessage *message) {
@@ -137,7 +140,7 @@
const auto element_size = MessageType::Sizeof(type_id);
- FillInMessageBase(level, message);
+ FillInMessageBase(level, monotonic_now, message);
message->message_length = rows * cols * element_size;
if (message_string.size() + message->message_length >
@@ -157,9 +160,9 @@
message->type = LogMessage::Type::kMatrix;
}
-void FillInMessage(log_level level, const char *format, va_list ap,
- LogMessage *message) {
- FillInMessageBase(level, message);
+void FillInMessage(log_level level, monotonic_clock::time_point monotonic_now,
+ const char *format, va_list ap, LogMessage *message) {
+ FillInMessageBase(level, monotonic_now, message);
message->message_length =
ExecuteFormat(message->message, sizeof(message->message), format, ap);
@@ -274,7 +277,7 @@
void HandleMessageLogImplementation::DoLog(log_level level, const char *format,
va_list ap) {
LogMessage message;
- internal::FillInMessage(level, format, ap, &message);
+ internal::FillInMessage(level, monotonic_now(), format, ap, &message);
HandleMessage(message);
}
@@ -282,8 +285,9 @@
log_level level, const ::std::string &message_string, size_t size,
const MessageType *type, const ::std::function<size_t(char *)> &serialize) {
LogMessage message;
- internal::FillInMessageStructure(fill_type_cache(), level, message_string,
- size, type, serialize, &message);
+ internal::FillInMessageStructure(fill_type_cache(), level, monotonic_now(),
+ message_string, size, type, serialize,
+ &message);
HandleMessage(message);
}
@@ -291,8 +295,8 @@
log_level level, const ::std::string &message_string, uint32_t type_id,
int rows, int cols, const void *data) {
LogMessage message;
- internal::FillInMessageMatrix(level, message_string, type_id, rows, cols,
- data, &message);
+ internal::FillInMessageMatrix(level, monotonic_now(), message_string, type_id,
+ rows, cols, data, &message);
HandleMessage(message);
}
@@ -367,7 +371,7 @@
chrono::duration_cast<chrono::nanoseconds>(
dropped_start.time_since_epoch() - dropped_start_sec);
internal::FillInMessageVarargs(
- ERROR, dropped_message,
+ ERROR, message_time, dropped_message,
"%d logs starting at %" PRId32 ".%" PRId32 " dropped\n",
dropped_messages, static_cast<int32_t>(dropped_start_sec.count()),
static_cast<int32_t>(dropped_start_nsec.count()));
@@ -394,10 +398,14 @@
}
class LinuxQueueLogImplementation : public LogImplementation {
+ virtual ::aos::monotonic_clock::time_point monotonic_now() const {
+ return ::aos::monotonic_clock::now();
+ }
+
__attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 3, 0)))
void DoLog(log_level level, const char *format, va_list ap) override {
LogMessage *message = GetMessageOrDie();
- internal::FillInMessage(level, format, ap, message);
+ internal::FillInMessage(level, monotonic_now(), format, ap, message);
Write(message);
}
@@ -405,8 +413,9 @@
size_t size, const MessageType *type,
const ::std::function<size_t(char *)> &serialize) override {
LogMessage *message = GetMessageOrDie();
- internal::FillInMessageStructure(fill_type_cache(), level, message_string,
- size, type, serialize, message);
+ internal::FillInMessageStructure(fill_type_cache(), level, monotonic_now(),
+ message_string, size, type, serialize,
+ message);
Write(message);
}
@@ -414,8 +423,8 @@
uint32_t type_id, int rows, int cols,
const void *data) override {
LogMessage *message = GetMessageOrDie();
- internal::FillInMessageMatrix(level, message_string, type_id, rows, cols,
- data, message);
+ internal::FillInMessageMatrix(level, monotonic_now(), message_string,
+ type_id, rows, cols, data, message);
Write(message);
}
};
diff --git a/aos/logging/implementations.h b/aos/logging/implementations.h
index 69a805b..5f7e1c5 100644
--- a/aos/logging/implementations.h
+++ b/aos/logging/implementations.h
@@ -19,8 +19,9 @@
#include "aos/logging/sizes.h"
#include "aos/macros.h"
#include "aos/mutex/mutex.h"
-#include "aos/type_traits/type_traits.h"
#include "aos/once.h"
+#include "aos/time/time.h"
+#include "aos/type_traits/type_traits.h"
namespace aos {
@@ -102,6 +103,11 @@
// A LogImplementation where LogStruct and LogMatrix just create a string with
// PrintMessage and then forward on to DoLog.
class SimpleLogImplementation : public LogImplementation {
+ protected:
+ virtual ::aos::monotonic_clock::time_point monotonic_now() const {
+ return ::aos::monotonic_clock::now();
+ }
+
private:
void LogStruct(log_level level, const ::std::string &message, size_t size,
const MessageType *type,
@@ -114,6 +120,11 @@
// Implements all of the DoLog* methods in terms of a (pure virtual in this
// class) HandleMessage method that takes a pointer to the message.
class HandleMessageLogImplementation : public LogImplementation {
+ protected:
+ virtual ::aos::monotonic_clock::time_point monotonic_now() const {
+ return ::aos::monotonic_clock::now();
+ }
+
private:
__attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 3, 0)))
void DoLog(log_level level, const char *format, va_list ap) override;
@@ -177,7 +188,8 @@
// Fills in all the parts of message according to the given inputs (with type
// kStruct).
-void FillInMessageStructure(log_level level,
+void FillInMessageStructure(bool add_to_type_cache, log_level level,
+ ::aos::monotonic_clock::time_point monotonic_now,
const ::std::string &message_string, size_t size,
const MessageType *type,
const ::std::function<size_t(char *)> &serialize,
@@ -186,22 +198,25 @@
// Fills in all the parts of the message according to the given inputs (with
// type kMatrix).
void FillInMessageMatrix(log_level level,
+ ::aos::monotonic_clock::time_point monotonic_now,
const ::std::string &message_string, uint32_t type_id,
int rows, int cols, const void *data,
LogMessage *message);
// Fills in *message according to the given inputs (with type kString).
// Used for implementing LogImplementation::DoLog.
-void FillInMessage(log_level level, const char *format, va_list ap,
- LogMessage *message)
- __attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 2, 0)));
+void FillInMessage(log_level level,
+ ::aos::monotonic_clock::time_point monotonic_now,
+ const char *format, va_list ap, LogMessage *message)
+ __attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 3, 0)));
-__attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 3, 4)))
-static inline void FillInMessageVarargs(log_level level, LogMessage *message,
- const char *format, ...) {
+__attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 4, 5))) static inline void
+FillInMessageVarargs(log_level level,
+ ::aos::monotonic_clock::time_point monotonic_now,
+ LogMessage *message, const char *format, ...) {
va_list ap;
va_start(ap, format);
- FillInMessage(level, format, ap, message);
+ FillInMessage(level, monotonic_now, format, ap, message);
va_end(ap);
}
diff --git a/aos/logging/implementations_test.cc b/aos/logging/implementations_test.cc
index ef69658..ecf66e9 100644
--- a/aos/logging/implementations_test.cc
+++ b/aos/logging/implementations_test.cc
@@ -22,7 +22,7 @@
class TestLogImplementation : public SimpleLogImplementation {
__attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 3, 0)))
void DoLog(log_level level, const char *format, va_list ap) override {
- internal::FillInMessage(level, format, ap, &message_);
+ internal::FillInMessage(level, monotonic_now(), format, ap, &message_);
if (level == FATAL) {
internal::PrintMessage(stderr, message_);