SMP heisenbug (weird cpu exceptions when logging is removed, possibly related to networking)
Posted: Thu Jul 24, 2025 4:44 pm
Hello, I added SMP support a while ago, but now that I started to use threads I'm discovering weird issues. Recently I tried to move net packet processing outside virtio interrupt handler, but then sometimes some random exceptions occur. This is the networking code:
This tiggers on virtio interrupt:
This is the function it calls:
So sometimes when I run 100 tcp sockets with 10k req each, some exceptions occur. They do not occur when I call eth_recv() from inside interrupt handler. I suspect it might be something related to threads. If I alter process_net_packet
Everything mostly works (sometimes there is exception right at the boot, but if that doesn't happen it works for all my tests). This is my threads code:
and this is thread_switch
While debugging issues I also noticed inside eth_recv() (that is entry to NS), when sending something I have a line
Basically if I hexdump intf, it has correct pointer to send function, but in asm when jmp rax gets called, rax is set to something like 15 exabytes (if important, it always the same value, but it doesnt show up anywhere in code). So something alters state of register (since memory is still holding correct value).
I have been going at this for past 7 days (even found out this type of bugs which disappear when added LOG are called haisenbugs), help would be appreciated
Code: Select all
buffer_q_complete g_net_buffer_queue = {};
spinlock_t __virtio_net_lock;
void initialize_net_buffer() { ... }
void initialize_processing_thread() { ... }
void process_net_packet()
{
net_buf *net_buffer = (net_buf *)liballoc_malloc(sizeof(net_buf));
tthread *cur = NULL;
uint32_t cpu_id;
while (1) {
cpu_id = lapic_get_id();
cur = tthread_cpu[cpu_id];
spinlock_acquire(&g_net_buffer_queue.buffer_queue_start_lock);
if (atomic_load(&g_net_buffer_queue.size) == 0) {
spinlock_release(&g_net_buffer_queue.buffer_queue_start_lock);
tscheduler_yield(cur);
continue;
}
if (g_net_buffer_queue.buffer_queue_bool[g_net_buffer_queue.buffer_start] == 0) {
spinlock_release(&g_net_buffer_queue.buffer_queue_start_lock);
tscheduler_yield(cur);
continue;
}
int start = g_net_buffer_queue.buffer_start;
g_net_buffer_queue.buffer_start = (g_net_buffer_queue.buffer_start + 1) % BUFFER_QUEUE_SIZE;
net_buffer->start = g_net_buffer_queue.buffer_queue[start].data;
net_buffer->end = g_net_buffer_queue.buffer_queue[start].data
+ g_net_buffer_queue.buffer_queue[start].data_size;
spinlock_release(&g_net_buffer_queue.buffer_queue_start_lock);
spinlock_acquire(&__virtio_net_lock);
eth_recv(g_virtio_intf, net_buffer);
spinlock_release(&__virtio_net_lock);
spinlock_acquire(&g_net_buffer_queue.buffer_queue_start_lock);
atomic_fetch_sub(&g_net_buffer_queue.size, 1);
g_net_buffer_queue.buffer_queue_bool[start] = 0;
spinlock_release(&g_net_buffer_queue.buffer_queue_start_lock);
tscheduler_yield(cur);
}
}
Code: Select all
static uint64_t __virtio_net_interrupts_served_per_cpu[128];
static uint64_t __virtio_net_currently_serving_interrupt[128];
static uint32_t __virtio_net_last_cpu = -1;
registers *interrupt_virtio_net_handler(registers *r)
{
uint32_t cpu_id = lapic_get_id();
uint32_t next_cpu = (__virtio_net_last_cpu + 1) % g_acpi_cpu_count;
// only try to get the lock if current cpu is next cpu or if next cpu is busy processing other
// interrupts
if (cpu_id == next_cpu || __virtio_net_currently_serving_interrupt[next_cpu]) {
spinlock_acquire(&g_virtio_lock);
__virtio_net_last_cpu = cpu_id;
__virtio_net_interrupts_served_per_cpu[cpu_id]++;
__virtio_net_currently_serving_interrupt[cpu_id] = 1;
LOG(LOG_TYPE_NET, "virtio_net: net interrupt");
virtio_net_receive();
__virtio_net_currently_serving_interrupt[cpu_id] = 0;
}
__acknowledge_interrupt();
return r;
}
Code: Select all
void virtio_net_receive()
{
uint8_t isr = pmio_read_8(__virtio_net_dev.io_base + 0x13);
// LOG(LOG_TYPE_NET, "isr %d", isr);
virtio_queue *vq = &__virtio_net_dev.queues[0];
vq->used->flags = 1;
if (vq->last_used_index == vq->used->index) {
spinlock_release(&g_virtio_lock);
return;
}
...
uint8_t *buffer = (uint8_t *)(vq->buffers[buffer_index].address + sizeof(net_header));
uint32_t cpu_id = lapic_get_id();
LOG(LOG_TYPE_NET, "virtio_net: received package, size %d on core %d",
vq->used->rings[index].length - sizeof(net_header), cpu_id);
__net_bufs[cpu_id].start = buffer;
__net_bufs[cpu_id].end = buffer + vq->used->rings[index].length - sizeof(net_header);
// if the buffer is full it won't be processed
if (atomic_load(&g_net_buffer_queue.size) == BUFFER_QUEUE_SIZE) {
spinlock_release(&g_virtio_lock);
return;
}
int end = g_net_buffer_queue.buffer_end;
g_net_buffer_queue.buffer_end = (g_net_buffer_queue.buffer_end + 1) % BUFFER_QUEUE_SIZE;
memcpy(g_net_buffer_queue.buffer_queue[end].data, buffer,
vq->used->rings[index].length - sizeof(net_header));
g_net_buffer_queue.buffer_queue[end].data_size
= vq->used->rings[index].length - sizeof(net_header);
g_net_buffer_queue.buffer_queue_bool[end] = 1;
atomic_fetch_add(&g_net_buffer_queue.size, 1);
spinlock_release(&g_virtio_lock);
}
uint64_t virtio_net_send(void *package, uint64_t package_size) // since whole NS has global lock this is fine without locks
{
...
__virtio_send_buffer(&__virtio_net_dev, 1, __send_bi, 2);
return package_size;
}
Code: Select all
if (atomic_load(&g_net_buffer_queue.size) == 0) {
spinlock_release(&g_net_buffer_queue.buffer_queue_start_lock);
tscheduler_yield(cur);
wait(1 ms);
continue;
}
if (g_net_buffer_queue.buffer_queue_bool[g_net_buffer_queue.buffer_start] == 0) {
spinlock_release(&g_net_buffer_queue.buffer_queue_start_lock);
tscheduler_yield(cur);
wait(1 ms);
continue;
}
Code: Select all
typedef struct tthread
{
uint64_t tid;
uint32_t cpu_id;
tthread_state state;
void *stack;
} tthread;
typedef struct tt_swtch_stack
{
uint64_t RBP;
uint64_t RBX;
uint64_t R12;
uint64_t R13;
uint64_t R14;
uint64_t R15;
uint64_t RBP2;
uint64_t ret;
} __attribute__((packed)) tt_swtch_stack;
#define MAX_TSCHEDULER_QUEUE_SIZE 128
#define THREAD_STACK_SIZE 131072
typedef struct tscheduler_queue
{
int front;
int rear;
int size;
tthread *tthreads[MAX_TSCHEDULER_QUEUE_SIZE];
} tscheduler_queue;
extern tthread *tthread_cpu[128];
static uint64_t s_ttid = 0;
static spinlock_t tthread_lock;
spinlock_t tscheduler_lock;
static tscheduler_queue tq = {};
tthread *tthread_cpu[MAX_TSCHEDULER_QUEUE_SIZE] = {};
tthread *tscheduler_threads[4];
static void __tscheduler_init()
{
spinlock_init(&tscheduler_lock);
tq.front = 0;
tq.rear = -1;
tq.size = 0;
}
static int __tq_is_empty()
static int __tq_is_full(void)
static void __tq_enqueue(tthread *thread)
static tthread *__tq_dequeue()
void infi() { while (1) { } }
void initialize_tthreads()
{
for (int cpu_id = 0; cpu_id < 4; cpu_id++) {
tscheduler_threads[cpu_id] = liballoc_aligned_alloc(16, THREAD_STACK_SIZE);
tscheduler_threads[cpu_id]->stack = (void *)((uint64_t)tscheduler_threads[cpu_id]
+ THREAD_STACK_SIZE - sizeof(tt_swtch_stack));
tt_swtch_stack *stack = tscheduler_threads[cpu_id]->stack;
stack->RBP = (uint64_t)&stack->RBP2;
stack->ret = (uint64_t)infi;
}
spinlock_init(&tthread_lock);
__tscheduler_init();
}
tthread *create_tthread(void (*func)(void))
{
tthread *new = liballoc_aligned_alloc(64, THREAD_STACK_SIZE);
if (!new) {
return NULL;
}
spinlock_acquire(&tthread_lock);
new->tid = s_ttid++;
spinlock_release(&tthread_lock);
new->cpu_id = 0;
new->state = TTHREAD_READY;
new->stack = (void *)((uint64_t)new + THREAD_STACK_SIZE - sizeof(tt_swtch_stack));
tt_swtch_stack *stack = new->stack;
stack->RBP = (uint64_t)&stack->RBP2;
stack->ret = (uint64_t)func;
return new;
}
void tscheduler_add_thread(tthread *thread)
{
spinlock_acquire(&tscheduler_lock);
__tq_enqueue(thread);
spinlock_release(&tscheduler_lock);
}
void tscheduler_yield(tthread *old)
{
spinlock_acquire(&tscheduler_lock);
if (__tq_is_empty()) {
spinlock_release(&tscheduler_lock);
if (old->state == TTHREAD_TERMINATED) {
liballoc_aligned_free(old);
}
return;
}
tthread *new = __tq_dequeue();
if (old->state == TTHREAD_RUNNING) {
old->state = TTHREAD_READY;
__tq_enqueue(old);
}
if (!new) {
spinlock_release(&tscheduler_lock);
if (old->state == TTHREAD_TERMINATED) {
liballoc_aligned_free(old);
}
return;
}
new->cpu_id = old->cpu_id;
new->state = TTHREAD_RUNNING;
tthread_cpu[new->cpu_id] = new;
void *old_stack = &old->stack;
if (old->state == TTHREAD_TERMINATED) {
liballoc_aligned_free(old);
}
tt_switch_stack(old_stack, &new->stack, &tscheduler_lock);
}
void tscheduler_enter()
{
while (1) {
spinlock_acquire(&tscheduler_lock);
if (!__tq_is_empty()) {
tthread *thread = __tq_dequeue();
thread->cpu_id = lapic_get_id();
thread->state = TTHREAD_RUNNING;
tthread_cpu[thread->cpu_id] = thread;
uint64_t dummy_stack_ptr;
tt_switch_stack(&dummy_stack_ptr, &thread->stack, &tscheduler_lock);
} else {
spinlock_release(&tscheduler_lock);
}
}
}
Code: Select all
global tt_switch_stack
tt_switch_stack:
cli
push rbp
mov rbp, rsp
push r15
push r14
push r13
push r12
push rbx
push rbp
mov [rdi], rsp
mov rsp, [rsi]
pop rbp
pop rbx
pop r12
pop r13
pop r14
pop r15
mfence ; Full memory barrier (__sync_synchronize)
mov dword [rdx], 0
leave
sti
ret
Code: Select all
intf->send(intf, next_addr, ET_IPV4, pkt);
I have been going at this for past 7 days (even found out this type of bugs which disappear when added LOG are called haisenbugs), help would be appreciated