glommio
glommio copied to clipboard
Published
20 hours ago •
DataDog
DataDog
timer::timer_impl::test::basic_timer_works hang in an EC2 instance
The test is consistently hanging in my EC2 VM while the same test consistently pass in a local VM. I have tried 3 different kernel versions and it is hanging all the same in the EC2 VM.
Maybe I have made a silly mistake in my EC2 VM setup, but I could not figure it out. Any ideas?
Here is a snippet of the hanging environment
$cat /etc/os-release
NAME="Amazon Linux"
VERSION="2"
ID="amzn"
ID_LIKE="centos rhel fedora"
VERSION_ID="2"
PRETTY_NAME="Amazon Linux 2"
ANSI_COLOR="0;33"
CPE_NAME="cpe:2.3:o:amazon:amazon_linux:2"
HOME_URL="https://amazonlinux.com/"
$uname -r
5.15.33
$ls /boot/vmlinuz-*
-rwxr-xr-x 1 root root 9.0M Mar 2 19:18 /boot/vmlinuz-5.10.102-99.473.amzn2.x86_64
-rwxr-xr-x 1 root root 9.0M Mar 29 23:19 /boot/vmlinuz-5.10.106-102.504.amzn2.x86_64
-rw-r--r-- 1 root root 9.2M Apr 12 22:03 /boot/vmlinuz-5.15.33
-rw-r--r-- 1 root root 9.2M Apr 12 21:57 /boot/vmlinuz-5.15.33.old
This is the command I used to run the test
$cargo +stable test timer_impl::test::basic_timer_works -- --test-threads 1 --nocapture
Compiling glommio v0.7.0 (/home/ec2-user/github/glommio/glommio)
Finished test [unoptimized + debuginfo] target(s) in 47.13s
Running unittests (/home/ec2-user/github/glommio/target/debug/deps/glommio-560519b5ddc0765e)
running 1 test
test timer::timer_impl::test::basic_timer_works ...
I wrote a C program to simulate what the test does, but the C program is not hanging. See the following for the C program:
#include <sys/eventfd.h>
#include <pthread.h>
#include <stdarg.h>
#include <unistd.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <pthread.h>
#include <liburing.h>
#include <fcntl.h>
#include <poll.h>
#define URING_SIZE 8
struct io_uring main_ring;
struct io_uring latency_ring;
void error_exit(const char *fmt, ...) {
va_list args;
va_start(args, fmt);
vprintf(fmt, args);
va_end(args);
exit(EXIT_FAILURE);
}
void link_ring_and_sleep() {
unsigned poll_mask = POLLERR | POLLHUP | POLLNVAL | POLLIN | POLLPRI;
struct io_uring_sqe *sqe;
sqe = io_uring_get_sqe(&main_ring);
if (!sqe) {
error_exit("Could not get SQE.\n");
}
io_uring_prep_poll_add(sqe, latency_ring.ring_fd, poll_mask);
int ret = io_uring_submit(&main_ring);
if (ret < 0) {
error_exit("Could not submit SQE: %s\n", strerror(-ret));
}
printf("Start waiting.\n"); struct io_uring_cqe *cqe = NULL;
ret = io_uring_wait_cqe(&main_ring, &cqe);
if (ret < 0) {
error_exit("Error waiting for completion: %s\n", strerror(-ret));
}
if (cqe->res < 0) {
error_exit("Error in PollAdd operation: %s\n", strerror(-cqe->res));
}
printf("Result of the operation: %d\n", cqe->res);
io_uring_cqe_seen(&main_ring, cqe);
}
void add_timeout_to_latency_ring(
struct __kernel_timespec *timeout_duration) {
struct io_uring_sqe *sqe;
sqe = io_uring_get_sqe(&latency_ring);
if (!sqe) {
error_exit("Could not get SQE from latency ring when adding timeout.\n");
}
io_uring_prep_timeout(sqe, timeout_duration, 1, 0);
int ret = io_uring_submit(&latency_ring);
if (ret < 0) {
error_exit("Could not submit timeout to latency ring: %s\n", strerror(-ret));
}
}
void setup_io_urings() {
int ret = io_uring_queue_init(URING_SIZE, &main_ring, 0);
if (ret) {
error_exit("Could not setup main io_uring: %s\n", strerror(-ret));
}
ret = io_uring_queue_init(URING_SIZE, &latency_ring, 0);
if (ret) {
error_exit("Could not setup latency io_uring: %s\n", strerror(-ret));
}
}
void cleanup_io_urings() {
io_uring_queue_exit(&main_ring);
io_uring_queue_exit(&latency_ring);
}
void *executor_thread(void *data) {
struct __kernel_timespec timeout_duration = {
.tv_sec = 1,
.tv_nsec = 0,
};
setup_io_urings();
add_timeout_to_latency_ring(&timeout_duration);
link_ring_and_sleep();
cleanup_io_urings();
return NULL;
}
int main() {
pthread_t t;
pthread_create(&t, NULL, executor_thread, NULL);
pthread_join(t, NULL);
return EXIT_SUCCESS;
}
It's concerning that such a simple test fails. On the other hand, it's great that it is a simple test that fails =p
However your C test doesn't seem fully equivalent to the rust test: the rust test sleeps for 100ms, while your C test sleeps for 1s.
This is relevant, because if we're racing with the wakeups, maybe the test fails with small sleeps but succeed with long sleeps (although 100ms is pretty long, but who knows).
I'd suggest starting by making sure the rust test always fails - regardless of the sleep amount.
From there, my suggestion would be to add some prints to the reactor to make sure that we are:
- submitting the timer event
- receiving the cqes (note that there is a test in the beginning of the cqe processing function where we discard anything with user_data == 0... )
I have tried different sleeping times (10ms, 100ms, 1s, 10s) in the Rust test. All consistently hanging.
I also added printing logs, and it seems the timer even are submitted:
cargo +stable test timer_impl::test::basic_timer_works -- --test-threads 1 --nocapture
Finished test [unoptimized + debuginfo] target(s) in 0.09s
Running unittests (target/debug/deps/glommio-edbb63ec2fcf9390)
running 1 test
test timer::timer_impl::test::basic_timer_works ... 6: io_uring_submit
4: io_uring_submit
6: io_uring_submit
<ThreadId(1)> Timer registered.
6: io_uring_submit
4: io_uring_submit
<ThreadId(1)> Going to sleep for 9.999857859s
6: io_uring_submit
<ThreadId(1)> Going to sleep 1
4: io_uring_submit
<ThreadId(1)> Wait inner.
4: io_uring_wait_cqes enter: 1
The prints are added in sys/uring.rs:
diff --git a/glommio/src/sys/uring.rs b/glommio/src/sys/uring.rs
index 0ac954b..a1ffc2a 100644
--- a/glommio/src/sys/uring.rs
+++ b/glommio/src/sys/uring.rs
@@ -1104,6 +1104,7 @@ impl SleepableRing {
.or_else(Reactor::intr_ok)?
!= 1
{
+ println!("<{:?}> Failed to submit SQE that link rings.", std::thread::current().id());
// We failed to submit the `SQE` that links the rings. Just can't sleep.
// Waiting here is unsafe because we could end up waiting much longer than
// needed.
@@ -1124,6 +1125,7 @@ impl SleepableRing {
// Can't link rings because we ran out of `CQE`s. Just can't sleep.
// Submit what we have, once we're out of here we'll consume them
// and at some point will be able to sleep again.
+ println!("<{:?}> Cannot link rings.", std::thread::current().id());
self.submit_sqes()
.or_else(Reactor::busy_ok)
.or_else(Reactor::again_ok)
@@ -1873,6 +1875,8 @@ impl Reactor {
if let Some(dur) = user_timer {
self.latency_preemption_timeout_src
.set(Some(lat_ring.prepare_latency_preemption_timer(dur)));
+ println!("<{:?}> Going to sleep for {:?}",
+ std::thread::current().id(), dur);
assert!(flush_rings!(lat_ring)? > 0);
}
// From this moment on the remote executors are aware that we are sleeping
@@ -1887,8 +1891,12 @@ impl Reactor {
let events = process_remote_channels() + self.flush_syscall_thread();
if events == 0 {
if self.eventfd_src.is_installed().unwrap() {
+ let now = std::time::Instant::now();
+ println!("<{:?}> Going to sleep {}",
+ std::thread::current().id(), self.id());
self.link_rings_and_sleep(&mut main_ring)
.expect("some error");
+ println!("<{:?}> Back from sleep {}, elapsed: {:?}", std::thread::current().id(), self.id(), now.elapsed());
// May have new cancellations related to the link ring fd.
flush_cancellations!(into &mut 0; lat_ring, poll_ring, main_ring);
flush_rings!(lat_ring, poll_ring, main_ring)?;
and into the liburing c code:
diff --git a/src/queue.c b/src/queue.c
index ce5d237..caf5379 100644
--- a/src/queue.c
+++ b/src/queue.c
@@ -8,6 +8,7 @@
#include <errno.h>
#include <string.h>
#include <stdbool.h>
+#include <stdio.h>
#include "liburing/compat.h"
#include "liburing/io_uring.h"
@@ -284,6 +285,7 @@ int io_uring_wait_cqes(struct io_uring *ring, struct io_uring_cqe **cqe_ptr,
{
unsigned to_submit = 0;
+ printf("%d: io_uring_wait_cqes enter: %u\n", ring->ring_fd, wait_nr);
if (ts) {
struct io_uring_sqe *sqe;
int ret;
@@ -304,12 +306,16 @@ int io_uring_wait_cqes(struct io_uring *ring, struct io_uring_cqe **cqe_ptr,
if (!sqe)
return -EAGAIN;
}
+ printf("%d: io_uring_prep_timeout\n", ring->ring_fd);
io_uring_prep_timeout(sqe, ts, wait_nr, 0);
sqe->user_data = LIBURING_UDATA_TIMEOUT;
to_submit = __io_uring_flush_sq(ring);
}
- return __io_uring_get_cqe(ring, cqe_ptr, to_submit, wait_nr, sigmask);
+ int r = __io_uring_get_cqe(ring, cqe_ptr, to_submit, wait_nr, sigmask);
+ printf("%d: io_uring_wait_cqes exit: %u\n", ring->ring_fd, wait_nr);
+ return r;
+ //return __io_uring_get_cqe(ring, cqe_ptr, to_submit, wait_nr, sigmask);
}
/*
@@ -361,6 +367,7 @@ static int __io_uring_submit_and_wait(struct io_uring *ring, unsigned wait_nr)
*/
int io_uring_submit(struct io_uring *ring)
{
+ printf("%d: io_uring_submit\n", ring->ring_fd);
return __io_uring_submit_and_wait(ring, 0);
}
I added log into io_uring_prep_timeout into liburing:
diff --git a/src/include/liburing.h b/src/include/liburing.h
index 5b96e02..7b05d6d 100644
--- a/src/include/liburing.h
+++ b/src/include/liburing.h
@@ -12,6 +12,7 @@
#include <errno.h>
#include <signal.h>
#include <stdbool.h>
+#include <stdio.h>
#include <inttypes.h>
#include <time.h>
#include <linux/swab.h>
@@ -345,6 +346,7 @@ static inline void io_uring_prep_timeout(struct io_uring_sqe *sqe,
struct __kernel_timespec *ts,
unsigned count, unsigned flags)
{
+ printf("io_uring_prep_timeout: ts(%llu, %llu)\n", ts->tv_sec, ts->tv_nsec);
io_uring_prep_rw(IORING_OP_TIMEOUT, sqe, -1, ts, 1, count);
sqe->timeout_flags = flags;
}
Re-runing the test, I see logs like this:
io_uring_prep_timeout: ts(9223372036854775807, 999999999)
I suspect we are accessing dangling pointer. Probably from here. Aren't we using a pointer of a local variable there?
Too bad that the asan build failed with tokio errors, so I cannot ran the test with AddressSanitizer enabled.
error: /home/ec2-user/github/glommio/target/debug/deps/libtokio_macros-3d0388ab8367cab7.so: undefined symbol: __asan_option_detect_stack_use_after_return
--> /home/ec2-user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.17.0/src/lib.rs:493:13
|
493 | pub use tokio_macros::select_priv_declare_output_enum;
| ^^^^^^^^^^^^
error: /home/ec2-user/github/glommio/target/debug/deps/libtokio_macros-3d0388ab8367cab7.so: undefined symbol: __asan_option_detect_stack_use_after_return
--> /home/ec2-user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.17.0/src/lib.rs:499:13
|
499 | pub use tokio_macros::select_priv_clean_pattern;
| ^^^^^^^^^^^^
...
Got the asan build working, but it is not catching the bug. Turned out I need --target x86_64-unknown-linux-gnu to enable the asan build to work:
export RUSTFLAGS=-Zsanitizer=address RUSTDOCFLAGS=-Zsanitizer=address
cargo +nightly test -Zbuild-std --target x86_64-unknown-linux-gnu timer_impl::test::basic_timer_works -- --test-threads 1 --nocapture
Somehow the test is still hanging and asan didn't catch anything.
Tried msan and caught an use-of-uninitialized-value error, but without details.
$export RUSTFLAGS=-Zsanitizer=memory
$cargo +nightly test -Zbuild-std --target x86_64-unknown-linux-gnu timer_impl::test::basic_timer_works -- --test-threads 1 --nocapture
...
==7279==WARNING: MemorySanitizer: use-of-uninitialized-value
#0 0x5618c15c87ef (/home/ec2-user/github/glommio/target/x86_64-unknown-linux-gnu/debug/deps/glommio-848a82b5e4bf009f+0x29c87ef) (BuildId: 62a45221ca5b64a09e7a72f57896620db80e9d4c)
#1 0x5618c0e75b55 (/home/ec2-user/github/glommio/target/x86_64-unknown-linux-gnu/debug/deps/glommio-848a82b5e4bf009f+0x2275b55) (BuildId: 62a45221ca5b64a09e7a72f57896620db80e9d4c)
#2 0x5618c11fe928 (/home/ec2-user/github/glommio/target/x86_64-unknown-linux-gnu/debug/deps/glommio-848a82b5e4bf009f+0x25fe928) (BuildId: 62a45221ca5b64a09e7a72f57896620db80e9d4c)
#3 0x5618c35a4e98 (/home/ec2-user/github/glommio/target/x86_64-unknown-linux-gnu/debug/deps/glommio-848a82b5e4bf009f+0x49a4e98) (BuildId: 62a45221ca5b64a09e7a72f57896620db80e9d4c)
#4 0x5618c3895a00 (/home/ec2-user/github/glommio/target/x86_64-unknown-linux-gnu/debug/deps/glommio-848a82b5e4bf009f+0x4c95a00) (BuildId: 62a45221ca5b64a09e7a72f57896620db80e9d4c)
#5 0x5618c40e2cba (/home/ec2-user/github/glommio/target/x86_64-unknown-linux-gnu/debug/deps/glommio-848a82b5e4bf009f+0x54e2cba) (BuildId: 62a45221ca5b64a09e7a72f57896620db80e9d4c)
#6 0x5618bef9ccce (/home/ec2-user/github/glommio/target/x86_64-unknown-linux-gnu/debug/deps/glommio-848a82b5e4bf009f+0x39ccce) (BuildId: 62a45221ca5b64a09e7a72f57896620db80e9d4c)
#7 0x5618bef369c4 (/home/ec2-user/github/glommio/target/x86_64-unknown-linux-gnu/debug/deps/glommio-848a82b5e4bf009f+0x3369c4) (BuildId: 62a45221ca5b64a09e7a72f57896620db80e9d4c)
#8 0x5618bfa38670 (/home/ec2-user/github/glommio/target/x86_64-unknown-linux-gnu/debug/deps/glommio-848a82b5e4bf009f+0xe38670) (BuildId: 62a45221ca5b64a09e7a72f57896620db80e9d4c)
#9 0x5618bfcfe4ef (/home/ec2-user/github/glommio/target/x86_64-unknown-linux-gnu/debug/deps/glommio-848a82b5e4bf009f+0x10fe4ef) (BuildId: 62a45221ca5b64a09e7a72f57896620db80e9d4c)
#10 0x5618c14f776a (/home/ec2-user/github/glommio/target/x86_64-unknown-linux-gnu/debug/deps/glommio-848a82b5e4bf009f+0x28f776a) (BuildId: 62a45221ca5b64a09e7a72f57896620db80e9d4c)
#11 0x5618bf915bf3 (/home/ec2-user/github/glommio/target/x86_64-unknown-linux-gnu/debug/deps/glommio-848a82b5e4bf009f+0xd15bf3) (BuildId: 62a45221ca5b64a09e7a72f57896620db80e9d4c)
which may mean we accessed a valid object, in a valid region, but with the wrong contents (wrong index in a buffer, etc)