[PAL/vm-common] The Bottomhalves thread sometimes goes into the BLOCKED state

[dimakuv]

Description of the problem

The Bottomhalves helper thread is periodically invoked in response to IRQ (interrupt requests) from the host devices: virtio-fs (for file system events/responses), virtio-vsock (for networking events/responses, in particular incoming packets), virtio-console (for input/output events/responses, in particular incoming characters).

This thread should never put itself in the THREAD_BLOCKED state -- there are no events it is blocked on.

However, this thread is seen in the BLOCKED state, though very-very rarely, when I put an assert like this:

diff --git a/pal/src/host/vm-common/kernel_sched.c b/pal/src/host/vm-common/kernel_sched.c
@@ -104,12 +107,48 @@ static struct thread* find_next_thread(struct thread* curr_thread) {
     if (!next_thread && get_per_cpu_data()->cpu_id == 0) {
         /* CPU0 must periodically handle incoming events (network packets, stdin) */
         assert(get_per_cpu_data()->bottomhalves_thread);
+        assert(get_per_cpu_data()->bottomhalves_thread->state != THREAD_BLOCKED);
         next_thread = get_per_cpu_data()->bottomhalves_thread;
     }

I tried to catch and analyze it, but this happened only a couple times in my several days of debugging. So I won't investigate this bug further now.

Steps to reproduce

Instead of the assert that doesn't give any useful info, we can also print a backtrace like this:

diff --git a/pal/src/host/vm-common/kernel_sched.c b/pal/src/host/vm-common/kernel_sched.c
@@ -104,12 +107,48 @@ static struct thread* find_next_thread(struct thread* curr_thread) {
     if (!next_thread && get_per_cpu_data()->cpu_id == 0) {
         /* CPU0 must periodically handle incoming events (network packets, stdin) */
         assert(get_per_cpu_data()->bottomhalves_thread);
+        if (get_per_cpu_data()->bottomhalves_thread->state == THREAD_BLOCKED) {
+            uint64_t value;
+            __asm__ volatile("mov %%rbp, %0" : "=r"(value) : );
+
+            uint64_t prev_rbp = *((uint64_t*)value + 0);
+            log_error("       0x%lx 0x%lx 0x%lx 0x%lx",
+                      *((uint64_t*)prev_rbp + 0), *((uint64_t*)prev_rbp + 1),
+                      *((uint64_t*)prev_rbp + 2), *((uint64_t*)prev_rbp + 3));
+
+            prev_rbp = *((uint64_t*)prev_rbp + 0);
+            log_error("       0x%lx 0x%lx 0x%lx 0x%lx",
+                      *((uint64_t*)prev_rbp + 0), *((uint64_t*)prev_rbp + 1),
+                      *((uint64_t*)prev_rbp + 2), *((uint64_t*)prev_rbp + 3));
+
+            prev_rbp = *((uint64_t*)prev_rbp + 0);
+            log_error("       0x%lx 0x%lx 0x%lx 0x%lx",
+                      *((uint64_t*)prev_rbp + 0), *((uint64_t*)prev_rbp + 1),
+                      *((uint64_t*)prev_rbp + 2), *((uint64_t*)prev_rbp + 3));
+
+            prev_rbp = *((uint64_t*)prev_rbp + 0);
+            log_error("       0x%lx 0x%lx 0x%lx 0x%lx",
+                      *((uint64_t*)prev_rbp + 0), *((uint64_t*)prev_rbp + 1),
+                      *((uint64_t*)prev_rbp + 2), *((uint64_t*)prev_rbp + 3));
+
+            prev_rbp = *((uint64_t*)prev_rbp + 0);
+            log_error("       0x%lx 0x%lx 0x%lx 0x%lx",
+                      *((uint64_t*)prev_rbp + 0), *((uint64_t*)prev_rbp + 1),
+                      *((uint64_t*)prev_rbp + 2), *((uint64_t*)prev_rbp + 3));
+
+            while (true) {}  // this is to be able to invoke GDB on the hanged Gramine-TDX
+        }
         next_thread = get_per_cpu_data()->bottomhalves_thread;
     }

[dimakuv]

Update some six months later: this issue is not seen anymore. I think I'll close it.