Logger: Pipe the monotonic_remote_transmit_time through event loop
Populate the field in all the network bridges and pipe it through
all the required spots in the event loop. Update all the tests to match
the update.
As part of this, we realized that our modeling of network delay was
wrong. Wakeups don't always take 50 uS if something else triggers the
wakeup and the message is ready in shared memory. This wasn't being
handled properly.
Change-Id: Idf94c5c6d7c87f4d65868c71b1cceedca7bf3853
Signed-off-by: James Kuszmaul <james.kuszmaul@bluerivertech.com>
diff --git a/aos/ipc_lib/lockless_queue.cc b/aos/ipc_lib/lockless_queue.cc
index 9d14d8f..57a2e9e 100644
--- a/aos/ipc_lib/lockless_queue.cc
+++ b/aos/ipc_lib/lockless_queue.cc
@@ -953,6 +953,7 @@
const char *data, size_t length,
monotonic_clock::time_point monotonic_remote_time,
realtime_clock::time_point realtime_remote_time,
+ monotonic_clock::time_point monotonic_remote_transmit_time,
uint32_t remote_queue_index, const UUID &source_boot_uuid,
monotonic_clock::time_point *monotonic_sent_time,
realtime_clock::time_point *realtime_sent_time, uint32_t *queue_index) {
@@ -962,13 +963,15 @@
// adhere to this convention and place it at the end.
memcpy((reinterpret_cast<char *>(Data()) + size() - length), data, length);
return Send(length, monotonic_remote_time, realtime_remote_time,
- remote_queue_index, source_boot_uuid, monotonic_sent_time,
- realtime_sent_time, queue_index);
+ monotonic_remote_transmit_time, remote_queue_index,
+ source_boot_uuid, monotonic_sent_time, realtime_sent_time,
+ queue_index);
}
LocklessQueueSender::Result LocklessQueueSender::Send(
size_t length, monotonic_clock::time_point monotonic_remote_time,
realtime_clock::time_point realtime_remote_time,
+ monotonic_clock::time_point monotonic_remote_transmit_time,
uint32_t remote_queue_index, const UUID &source_boot_uuid,
monotonic_clock::time_point *monotonic_sent_time,
realtime_clock::time_point *realtime_sent_time, uint32_t *queue_index) {
@@ -997,6 +1000,8 @@
message->header.source_boot_uuid = source_boot_uuid;
message->header.monotonic_remote_time = monotonic_remote_time;
message->header.realtime_remote_time = realtime_remote_time;
+ message->header.monotonic_remote_transmit_time =
+ monotonic_remote_transmit_time;
Index to_replace = Index::Invalid();
while (true) {
@@ -1298,6 +1303,7 @@
monotonic_clock::time_point *monotonic_sent_time,
realtime_clock::time_point *realtime_sent_time,
monotonic_clock::time_point *monotonic_remote_time,
+ monotonic_clock::time_point *monotonic_remote_transmit_time,
realtime_clock::time_point *realtime_remote_time,
uint32_t *remote_queue_index, UUID *source_boot_uuid, size_t *length,
char *data,
@@ -1379,6 +1385,8 @@
context.monotonic_event_time = m->header.monotonic_sent_time;
context.realtime_event_time = m->header.realtime_sent_time;
context.monotonic_remote_time = m->header.monotonic_remote_time;
+ context.monotonic_remote_transmit_time =
+ m->header.monotonic_remote_transmit_time;
context.realtime_remote_time = m->header.realtime_remote_time;
context.queue_index = queue_index.index();
if (m->header.remote_queue_index == 0xffffffffu) {
@@ -1443,6 +1451,7 @@
*realtime_sent_time = context.realtime_event_time;
*remote_queue_index = context.remote_queue_index;
*monotonic_remote_time = context.monotonic_remote_time;
+ *monotonic_remote_transmit_time = context.monotonic_remote_transmit_time;
*realtime_remote_time = context.realtime_remote_time;
*source_boot_uuid = context.source_boot_uuid;
*length = context.size;
@@ -1597,6 +1606,12 @@
<< m->header.monotonic_remote_time << " 0x" << std::hex
<< m->header.monotonic_remote_time.time_since_epoch().count()
<< std::dec << ::std::endl;
+ ::std::cout
+ << " monotonic_clock::time_point "
+ "monotonic_remote_transmit_time = "
+ << m->header.monotonic_remote_transmit_time << " 0x" << std::hex
+ << m->header.monotonic_remote_transmit_time.time_since_epoch().count()
+ << std::dec << ::std::endl;
::std::cout << " realtime_clock::time_point realtime_remote_time = "
<< m->header.realtime_remote_time << " 0x" << std::hex
<< m->header.realtime_remote_time.time_since_epoch().count()
diff --git a/aos/ipc_lib/lockless_queue.h b/aos/ipc_lib/lockless_queue.h
index 4f867b9..462b2b6 100644
--- a/aos/ipc_lib/lockless_queue.h
+++ b/aos/ipc_lib/lockless_queue.h
@@ -91,6 +91,7 @@
// passed through.
monotonic_clock::time_point monotonic_remote_time;
realtime_clock::time_point realtime_remote_time;
+ monotonic_clock::time_point monotonic_remote_transmit_time;
// Queue index from the remote node.
uint32_t remote_queue_index;
@@ -326,6 +327,7 @@
LocklessQueueSender::Result Send(
size_t length, monotonic_clock::time_point monotonic_remote_time,
realtime_clock::time_point realtime_remote_time,
+ monotonic_clock::time_point monotonic_remote_transmit_time,
uint32_t remote_queue_index, const UUID &source_boot_uuid,
monotonic_clock::time_point *monotonic_sent_time = nullptr,
realtime_clock::time_point *realtime_sent_time = nullptr,
@@ -336,6 +338,7 @@
const char *data, size_t length,
monotonic_clock::time_point monotonic_remote_time,
realtime_clock::time_point realtime_remote_time,
+ monotonic_clock::time_point monotonic_remote_transmit_time,
uint32_t remote_queue_index, const UUID &source_boot_uuid,
monotonic_clock::time_point *monotonic_sent_time = nullptr,
realtime_clock::time_point *realtime_sent_time = nullptr,
@@ -442,6 +445,7 @@
uint32_t queue_index, monotonic_clock::time_point *monotonic_sent_time,
realtime_clock::time_point *realtime_sent_time,
monotonic_clock::time_point *monotonic_remote_time,
+ monotonic_clock::time_point *monotonic_remote_transmit_time,
realtime_clock::time_point *realtime_remote_time,
uint32_t *remote_queue_index, UUID *source_boot_uuid, size_t *length,
char *data,
diff --git a/aos/ipc_lib/lockless_queue_death_test.cc b/aos/ipc_lib/lockless_queue_death_test.cc
index ccf95f7..bc5ebb7 100644
--- a/aos/ipc_lib/lockless_queue_death_test.cc
+++ b/aos/ipc_lib/lockless_queue_death_test.cc
@@ -79,10 +79,11 @@
for (int i = 0; i < 5; ++i) {
char data[100];
size_t s = snprintf(data, sizeof(data), "foobar%d", i + 1);
- ASSERT_EQ(sender.Send(data, s + 1, monotonic_clock::min_time,
- realtime_clock::min_time, 0xffffffffl,
- UUID::Zero(), nullptr, nullptr, nullptr),
- LocklessQueueSender::Result::GOOD);
+ ASSERT_EQ(
+ sender.Send(data, s + 1, monotonic_clock::min_time,
+ realtime_clock::min_time, monotonic_clock::min_time,
+ 0xffffffffl, UUID::Zero(), nullptr, nullptr, nullptr),
+ LocklessQueueSender::Result::GOOD);
// Pin a message, so when we keep writing we will exercise the pinning
// logic.
if (i == 1) {
@@ -156,10 +157,11 @@
// Send a message to make sure that the queue still works.
char data[100];
size_t s = snprintf(data, sizeof(data), "foobar%d", 971);
- ASSERT_EQ(sender.Send(data, s + 1, monotonic_clock::min_time,
- realtime_clock::min_time, 0xffffffffl,
- UUID::Zero(), nullptr, nullptr, nullptr),
- LocklessQueueSender::Result::GOOD);
+ ASSERT_EQ(
+ sender.Send(data, s + 1, monotonic_clock::min_time,
+ realtime_clock::min_time, monotonic_clock::min_time,
+ 0xffffffffl, UUID::Zero(), nullptr, nullptr, nullptr),
+ LocklessQueueSender::Result::GOOD);
}
// Now loop through the queue and make sure the number in the snprintf
@@ -175,17 +177,18 @@
monotonic_clock::time_point monotonic_sent_time;
realtime_clock::time_point realtime_sent_time;
monotonic_clock::time_point monotonic_remote_time;
+ monotonic_clock::time_point monotonic_remote_transmit_time;
realtime_clock::time_point realtime_remote_time;
uint32_t remote_queue_index;
UUID source_boot_uuid;
char read_data[1024];
size_t length;
- LocklessQueueReader::Result read_result =
- reader.Read(i, &monotonic_sent_time, &realtime_sent_time,
- &monotonic_remote_time, &realtime_remote_time,
- &remote_queue_index, &source_boot_uuid, &length,
- &(read_data[0]), std::ref(should_read));
+ LocklessQueueReader::Result read_result = reader.Read(
+ i, &monotonic_sent_time, &realtime_sent_time,
+ &monotonic_remote_time, &monotonic_remote_transmit_time,
+ &realtime_remote_time, &remote_queue_index, &source_boot_uuid,
+ &length, &(read_data[0]), std::ref(should_read));
if (read_result != LocklessQueueReader::Result::GOOD) {
if (read_result == LocklessQueueReader::Result::TOO_OLD) {
diff --git a/aos/ipc_lib/lockless_queue_test.cc b/aos/ipc_lib/lockless_queue_test.cc
index bfd9916..a2c0992 100644
--- a/aos/ipc_lib/lockless_queue_test.cc
+++ b/aos/ipc_lib/lockless_queue_test.cc
@@ -251,8 +251,8 @@
char data[100];
size_t s = snprintf(data, sizeof(data), "foobar%d", i);
ASSERT_EQ(sender.Send(data, s, monotonic_clock::min_time,
- realtime_clock::min_time, 0xffffffffu, UUID::Zero(),
- nullptr, nullptr, nullptr),
+ realtime_clock::min_time, monotonic_clock::min_time,
+ 0xffffffffu, UUID::Zero(), nullptr, nullptr, nullptr),
LocklessQueueSender::Result::GOOD);
// Confirm that the queue index still makes sense. This is easier since the
@@ -263,6 +263,7 @@
monotonic_clock::time_point monotonic_sent_time;
realtime_clock::time_point realtime_sent_time;
monotonic_clock::time_point monotonic_remote_time;
+ monotonic_clock::time_point monotonic_remote_transmit_time;
realtime_clock::time_point realtime_remote_time;
uint32_t remote_queue_index;
UUID source_boot_uuid;
@@ -277,8 +278,9 @@
}
LocklessQueueReader::Result read_result = reader.Read(
index.index(), &monotonic_sent_time, &realtime_sent_time,
- &monotonic_remote_time, &realtime_remote_time, &remote_queue_index,
- &source_boot_uuid, &length, &(read_data[0]), std::ref(should_read));
+ &monotonic_remote_time, &monotonic_remote_transmit_time,
+ &realtime_remote_time, &remote_queue_index, &source_boot_uuid, &length,
+ &(read_data[0]), std::ref(should_read));
// This should either return GOOD, or TOO_OLD if it is before the start of
// the queue.
@@ -450,6 +452,7 @@
monotonic_clock::time_point monotonic_sent_time;
realtime_clock::time_point realtime_sent_time;
monotonic_clock::time_point monotonic_remote_time;
+ monotonic_clock::time_point monotonic_remote_transmit_time;
realtime_clock::time_point realtime_remote_time;
uint32_t remote_queue_index;
UUID source_boot_uuid;
@@ -458,8 +461,9 @@
LocklessQueueReader::Result read_result = reader.Read(
i, &monotonic_sent_time, &realtime_sent_time, &monotonic_remote_time,
- &realtime_remote_time, &remote_queue_index, &source_boot_uuid, &length,
- &(read_data[0]), should_read_callback);
+ &monotonic_remote_transmit_time, &realtime_remote_time,
+ &remote_queue_index, &source_boot_uuid, &length, &(read_data[0]),
+ should_read_callback);
if (read_result != LocklessQueueReader::Result::GOOD) {
if (read_result == LocklessQueueReader::Result::TOO_OLD) {
@@ -526,10 +530,11 @@
for (int i = 0; i < 5; ++i) {
char data[100];
size_t s = snprintf(data, sizeof(data), "foobar%d", i + 1);
- ASSERT_EQ(sender.Send(data, s + 1, monotonic_clock::min_time,
- realtime_clock::min_time, 0xffffffffl,
- UUID::Zero(), nullptr, nullptr, nullptr),
- LocklessQueueSender::Result::GOOD);
+ ASSERT_EQ(
+ sender.Send(data, s + 1, monotonic_clock::min_time,
+ realtime_clock::min_time, monotonic_clock::min_time,
+ 0xffffffffl, UUID::Zero(), nullptr, nullptr, nullptr),
+ LocklessQueueSender::Result::GOOD);
}
},
[config, &tid](void *raw_memory) {
@@ -549,10 +554,11 @@
{
char data[100];
size_t s = snprintf(data, sizeof(data), "foobar%d", i + 1);
- ASSERT_EQ(sender.Send(data, s + 1, monotonic_clock::min_time,
- realtime_clock::min_time, 0xffffffffl,
- UUID::Zero(), nullptr, nullptr, nullptr),
- LocklessQueueSender::Result::GOOD);
+ ASSERT_EQ(
+ sender.Send(data, s + 1, monotonic_clock::min_time,
+ realtime_clock::min_time, monotonic_clock::min_time,
+ 0xffffffffl, UUID::Zero(), nullptr, nullptr, nullptr),
+ LocklessQueueSender::Result::GOOD);
}
// Now, make sure we can send 1 message and receive it to confirm we
diff --git a/aos/ipc_lib/memory_mapped_queue.cc b/aos/ipc_lib/memory_mapped_queue.cc
index fc486d4..dc457fe 100644
--- a/aos/ipc_lib/memory_mapped_queue.cc
+++ b/aos/ipc_lib/memory_mapped_queue.cc
@@ -16,7 +16,7 @@
std::string ShmPath(std::string_view shm_base, const Channel *channel) {
CHECK(channel->has_type());
- return ShmFolder(shm_base, channel) + channel->type()->str() + ".v6";
+ return ShmFolder(shm_base, channel) + channel->type()->str() + ".v7";
}
void PageFaultDataWrite(char *data, size_t size, const long page_size) {
diff --git a/aos/ipc_lib/queue_racer.cc b/aos/ipc_lib/queue_racer.cc
index aa73f2b..2797c24 100644
--- a/aos/ipc_lib/queue_racer.cc
+++ b/aos/ipc_lib/queue_racer.cc
@@ -197,7 +197,8 @@
++started_writes_;
auto result =
sender.Send(sizeof(ThreadPlusCount), aos::monotonic_clock::min_time,
- aos::realtime_clock::min_time, 0xffffffff,
+ aos::realtime_clock::min_time,
+ aos::monotonic_clock::min_time, 0xffffffff,
UUID::FromSpan(absl::Span<const uint8_t>(
reinterpret_cast<const uint8_t *>(&tpc),
sizeof(ThreadPlusCount))),
@@ -309,6 +310,7 @@
monotonic_clock::time_point monotonic_sent_time;
realtime_clock::time_point realtime_sent_time;
monotonic_clock::time_point monotonic_remote_time;
+ monotonic_clock::time_point monotonic_remote_transmit_time;
realtime_clock::time_point realtime_remote_time;
UUID source_boot_uuid;
uint32_t remote_queue_index;
@@ -321,14 +323,16 @@
0xffffffffu, LocklessQueueSize(queue_.memory())));
LocklessQueueReader::Result read_result =
set_should_read
- ? reader.Read(wrapped_i, &monotonic_sent_time, &realtime_sent_time,
- &monotonic_remote_time, &realtime_remote_time,
- &remote_queue_index, &source_boot_uuid, &length,
- &(read_data[0]), std::ref(should_read))
+ ? reader.Read(
+ wrapped_i, &monotonic_sent_time, &realtime_sent_time,
+ &monotonic_remote_time, &monotonic_remote_transmit_time,
+ &realtime_remote_time, &remote_queue_index, &source_boot_uuid,
+ &length, &(read_data[0]), std::ref(should_read))
: reader.Read(wrapped_i, &monotonic_sent_time, &realtime_sent_time,
- &monotonic_remote_time, &realtime_remote_time,
- &remote_queue_index, &source_boot_uuid, &length,
- &(read_data[0]), nop);
+ &monotonic_remote_time,
+ &monotonic_remote_transmit_time,
+ &realtime_remote_time, &remote_queue_index,
+ &source_boot_uuid, &length, &(read_data[0]), nop);
// The code in lockless_queue.cc reads everything but data, checks that the
// header hasn't changed, then reads the data. So, if we succeed and both