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/events/BUILD b/aos/events/BUILD
index dc5ac9c..1850a6c 100644
--- a/aos/events/BUILD
+++ b/aos/events/BUILD
@@ -57,7 +57,6 @@
cc_test(
name = "simulated_event_loop_test",
- testonly = True,
srcs = ["simulated-event-loop_test.cc"],
deps = [
":event-loop_param_test",
@@ -68,6 +67,7 @@
cc_library(
name = "simulated_event_loop",
+ testonly = True,
srcs = ["simulated-event-loop.cc"],
hdrs = ["simulated-event-loop.h"],
visibility = ["//visibility:public"],
@@ -75,5 +75,6 @@
":event-loop",
"//aos:queues",
"//aos/logging",
+ "//aos/testing:test_logging",
],
)
diff --git a/aos/events/simulated-event-loop.cc b/aos/events/simulated-event-loop.cc
index ce08a00..d5a0f67 100644
--- a/aos/events/simulated-event-loop.cc
+++ b/aos/events/simulated-event-loop.cc
@@ -5,6 +5,7 @@
#include "aos/logging/logging.h"
#include "aos/queue.h"
+#include "aos/testing/test_logging.h"
namespace aos {
namespace {
@@ -205,6 +206,7 @@
void EventScheduler::RunFor(monotonic_clock::duration duration) {
const ::aos::monotonic_clock::time_point end_time =
monotonic_now() + duration;
+ testing::MockTime(monotonic_now());
for (RawEventLoop *event_loop : raw_event_loops_) {
event_loop->set_is_running(true);
}
@@ -216,6 +218,7 @@
break;
}
now_ = iter->first;
+ testing::MockTime(now_);
::std::function<void()> callback = ::std::move(iter->second);
events_list_.erase(iter);
callback();
@@ -226,9 +229,11 @@
event_loop->set_is_running(false);
}
}
+ testing::UnMockTime();
}
void EventScheduler::Run() {
+ testing::MockTime(monotonic_now());
for (RawEventLoop *event_loop : raw_event_loops_) {
event_loop->set_is_running(true);
}
@@ -236,6 +241,7 @@
while (!events_list_.empty() && is_running_) {
auto iter = events_list_.begin();
now_ = iter->first;
+ testing::MockTime(now_);
::std::function<void()> callback = ::std::move(iter->second);
events_list_.erase(iter);
callback();
@@ -245,6 +251,7 @@
event_loop->set_is_running(false);
}
}
+ testing::UnMockTime();
}
void SimulatedEventLoop::MakeRawWatcher(
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_);
diff --git a/aos/testing/test_logging.cc b/aos/testing/test_logging.cc
index fa70d47..bc60081 100644
--- a/aos/testing/test_logging.cc
+++ b/aos/testing/test_logging.cc
@@ -20,6 +20,22 @@
public:
const ::std::vector<LogMessage> &messages() { return messages_; }
+ // Sets the current thread's time to be monotonic_now for logging.
+ void MockTime(::aos::monotonic_clock::time_point monotonic_now) {
+ mock_time_ = true;
+ monotonic_now_ = monotonic_now;
+ }
+
+ // Clears any mock time for the current thread.
+ void UnMockTime() { mock_time_ = false; }
+
+ ::aos::monotonic_clock::time_point monotonic_now() const override {
+ if (mock_time_) {
+ return monotonic_now_;
+ }
+ return ::aos::monotonic_clock::now();
+ }
+
// This class has to be a singleton so that everybody can get access to the
// same instance to read out the messages etc.
static TestLogImplementation *GetInstance() {
@@ -80,10 +96,20 @@
bool print_as_messages_come_in_ = false;
FILE *output_file_ = stdout;
::aos::Mutex messages_mutex_;
+
+ // Thread local storage for mock time. This is thread local because if
+ // someone spawns a thread and goes to town in parallel with a simulated event
+ // loop, we want to just print the actual monotonic clock out.
+ static thread_local bool mock_time_;
+ static thread_local ::aos::monotonic_clock::time_point monotonic_now_;
};
+thread_local bool TestLogImplementation::mock_time_ = false;
+thread_local ::aos::monotonic_clock::time_point
+ TestLogImplementation::monotonic_now_ = ::aos::monotonic_clock::min_time;
+
class MyTestEventListener : public ::testing::EmptyTestEventListener {
- virtual void OnTestStart(const ::testing::TestInfo &/*test_info*/) {
+ virtual void OnTestStart(const ::testing::TestInfo & /*test_info*/) {
TestLogImplementation::GetInstance()->ClearMessages();
}
virtual void OnTestEnd(const ::testing::TestInfo &test_info) {
@@ -141,5 +167,12 @@
TestLogImplementation::GetInstance()->PrintMessagesAsTheyComeIn();
}
+void MockTime(::aos::monotonic_clock::time_point monotonic_now) {
+ TestLogImplementation::GetInstance()->MockTime(monotonic_now);
+}
+void UnMockTime() {
+ TestLogImplementation::GetInstance()->UnMockTime();
+}
+
} // namespace testing
} // namespace aos
diff --git a/aos/testing/test_logging.h b/aos/testing/test_logging.h
index a4d835a..e7059d1 100644
--- a/aos/testing/test_logging.h
+++ b/aos/testing/test_logging.h
@@ -1,6 +1,8 @@
#ifndef AOS_TESTING_TEST_LOGGING_H_
#define AOS_TESTING_TEST_LOGGING_H_
+#include "aos/time/time.h"
+
namespace aos {
namespace testing {
@@ -21,6 +23,13 @@
// we want to use graphing tools to verify what's happening.
void ForcePrintLogsDuringTests();
+// Sets the current mock logging time to monotonic_now. This only applies to
+// the current thread.
+void MockTime(::aos::monotonic_clock::time_point monotonic_now);
+// Clears the mock logging time for the current thread and goes back to using
+// monotonic_clock::now().
+void UnMockTime();
+
} // namespace testing
} // namespace aos