Octocontrabass wrote:According to your QEMU log, the NVMe controller is processing your command successfully, returning the namespace list, and raising an interrupt.
Are interrupts enabled for the code that checks if the interrupt has arrived? If so, the interrupt may arrive after deciding to use HLT but before actually using HLT.
Have you tried instruction-level debugging to see what the CPU is doing when it hangs?
I just did that, adding a cli and a sti in the code to try to force interrupts to occur when I want them to. This is what happens (in code) now:
Code: Select all
// At function entry
unsafe {
asm!("cli", options(nomem, nostack));
}
// When we're about to wait for a response
let mut i: Interrupt;
unsafe {
asm!("sti", options(nomem, nostack));
asm!("hlt", options(nomem, nostack));
}
// Now we're waiting...
loop {
if !INTRS.is_empty() {
i = INTRS.pop().unwrap();
if i.0 == self.id {
break;
} else {
INTRS.push(i);
unsafe {
asm!("pause", options(nomem, nostack));
}
}
} else {
unsafe {
asm!("pause", options(nomem, nostack));
}
continue;
}
}
let mut entries: MiniVec<queues::CompletionQueueEntry> = MiniVec::new();
From what GDB is telling me (with the /s parameter to disassemble), this is the instruction stream (with GDB's stuff in it too), and nothing appears tobe amiss:
Code: Select all
728 let mut i: Interrupt;
729 unsafe {
730 asm!("sti", options(nomem, nostack));
0x00000000003228dc <+2172>: sti
731 asm!("hlt", options(nomem, nostack));
0x00000000003228dd <+2173>: hlt # things get stuck here
732 }
733 loop {
=> 0x00000000003228de <+2174>: jmp 0x3228e0 <<libk::nvme::NvmeController as libk::disk::Disk>::process_command+2176>
734 if !INTRS.is_empty() {
0x00000000003228e0 <+2176>: mov 0x1282c9(%rip),%rdi # 0x44abb0
0x00000000003228e7 <+2183>: callq 0x316750 <crossbeam_queue::seg_queue::SegQueue<T>::is_empty>
0x00000000003228ec <+2188>: mov %al,0x93(%rsp)
0x00000000003228f3 <+2195>: mov 0x93(%rsp),%al
0x00000000003228fa <+2202>: xor $0xff,%al
0x00000000003228fc <+2204>: test $0x1,%al
0x00000000003228fe <+2206>: jne 0x322902 <<libk::nvme::NvmeController as libk::disk::Disk>::process_command+2210>
0x0000000000322900 <+2208>: jmp 0x322918 <<libk::nvme::NvmeController as libk::disk::Disk>::process_command+2232>
735 i = INTRS.pop().unwrap();
0x0000000000322902 <+2210>: lea 0x340(%rsp),%rdi
0x000000000032290a <+2218>: mov 0x12829f(%rip),%rsi # 0x44abb0
0x0000000000322911 <+2225>: callq 0x315620 <crossbeam_queue::seg_queue::SegQueue<T>::pop>
0x0000000000322916 <+2230>: jmp 0x32291f <<libk::nvme::NvmeController as libk::disk::Disk>::process_command+2239>
742 }
743 }
744 } else {
745 unsafe {
746 asm!("pause", options(nomem, nostack));
0x0000000000322918 <+2232>: pause
0x000000000032291a <+2234>: jmpq 0x3229d6 <<libk::nvme::NvmeController as libk::disk::Disk>::process_command+2422>
735 i = INTRS.pop().unwrap();
0x000000000032291f <+2239>: lea 0x117962(%rip),%rsi # 0x43a288
0x0000000000322926 <+2246>: lea 0x340(%rsp),%rdi
0x000000000032292e <+2254>: callq 0x255690 <core::option::Option<T>::unwrap>
0x0000000000322933 <+2259>: mov %rcx,0x78(%rsp)
0x0000000000322938 <+2264>: mov %rdx,0x80(%rsp)
0x0000000000322940 <+2272>: mov %rax,0x88(%rsp)
0x0000000000322948 <+2280>: mov 0x88(%rsp),%rax
0x0000000000322950 <+2288>: mov 0x80(%rsp),%rcx
0x0000000000322958 <+2296>: mov 0x100(%rsp),%rsi
0x0000000000322960 <+2304>: mov 0x78(%rsp),%rdx
0x0000000000322965 <+2309>: mov %rax,0x4f0(%rsp)
0x000000000032296d <+2317>: mov %rcx,0x4f8(%rsp)
0x0000000000322975 <+2325>: mov %rdx,0x500(%rsp)
736 if i.0 == self.id {
0x000000000032297d <+2333>: mov 0x108(%rsi),%rdx
0x0000000000322984 <+2340>: mov 0x110(%rsi),%rsi
0x000000000032298b <+2347>: xor %rsi,%rcx
0x000000000032298e <+2350>: xor %rdx,%rax
0x0000000000322991 <+2353>: or %rcx,%rax
0x0000000000322994 <+2356>: jne 0x3229a7 <<libk::nvme::NvmeController as libk::disk::Disk>::process_command+2375>
0x0000000000322996 <+2358>: jmp 0x322998 <<libk::nvme::NvmeController as libk::disk::Disk>::process_command+2360>
747 }
748 continue;
749 }
750 }
751 let mut entries: MiniVec<queues::CompletionQueueEntry> = MiniVec::new();
0x0000000000322998 <+2360>: callq 0x2b3c50 <minivec::MiniVec<T>::new>
0x000000000032299d <+2365>: mov %rax,0x360(%rsp)
0x00000000003229a5 <+2373>: jmp 0x3229db <<libk::nvme::NvmeController as libk::disk::Disk>::process_command+2427>
0x00000000003229a7 <+2375>: mov 0x78(%rsp),%rcx
0x00000000003229ac <+2380>: mov 0x80(%rsp),%rdx
0x00000000003229b4 <+2388>: mov 0x88(%rsp),%rsi
739 INTRS.push(i);
0x00000000003229bc <+2396>: mov 0x1281ed(%rip),%rax # 0x44abb0
0x00000000003229c3 <+2403>: mov 0x1281e6(%rip),%rdi # 0x44abb0
0x00000000003229ca <+2410>: callq 0x315e60 <crossbeam_queue::seg_queue::SegQueue<T>::push>
740 unsafe {
741 asm!("pause", options(nomem, nostack));
0x00000000003229cf <+2415>: pause
733 loop {
0x00000000003229d1 <+2417>: jmpq 0x3228e0 <<libk::nvme::NvmeController as libk::disk::Disk>::process_command+2176>
So I'm really, really confused. I'm not sure what's wrong -- this assembly dump looks perfectly fine to me. (Also, the bug appears to be random: sometimes the bug happens on the first command, other times the bug happens on the second, and other times the interrupt fires but the loop is never terminated).
Update: I've updated it to use a while loop (kinda pointless since I can just use a pure loop construct) but even that didn't help. I'd love for this driver to be completely interrupt driven, but I don't really know how to do that, so I'm stuck with this hack of sorts. I don't know if my driver implementation is just wrong or what at this point. My current command processing code for one command is this:
Code: Select all
impl Disk for NvmeController {
type CommandRequest = Request;
type Response = Response;
type Error = queues::Status;
fn process_command(
&mut self,
req: Self::CommandRequest,
) -> Result<Self::Response, Self::Error> {
debug!("Processing command {:?}", req);
debug!("Waiting for controller to be ready...");
loop {
if self.read_csts().get_bit(0) {
break;
}
}
debug!("Writing request");
self.sqs[req.qid].queue_command(req.entry);
if req.qid == 0 {
debug!("Queue is admin queue, writing admin queue doorbell");
self.write_adm_sub_tail_queue_doorbell(self.sqs[req.qid].get_queue_tail());
} else {
debug!("Writing to queue {} doorbell", req.qid);
self.write_sub_tail_doorbell(req.qid, self.sqs[req.qid].get_queue_tail());
}
debug!("Waiting for response");
while INTRS.is_empty() {
unsafe {
asm!("hlt", options(nomem, nostack));
}
}
let _ = INTRS.pop().unwrap();
let mut entries: MiniVec<queues::CompletionQueueEntry> = MiniVec::new();
self.cqs[req.qid].read_new_entries(&mut entries);
if req.qid == 0 {
debug!("Writing to admin completion queue doorbell");
self.write_adm_comp_head_queue_doorbell(self.cqs[req.qid].get_queue_head());
} else {
debug!("Writing completion queue doorbell for queue {}", req.qid);
self.write_comp_head_doorbell(req.qid, self.cqs[req.qid].get_queue_head());
}
if entries.len() > 1 {
warn!(
"Retrieved {} responses; returning only first",
entries.len()
);
entries.truncate(1);
}
let entry = entries[0];
if entry.status.sc != 0x00 {
Err(entry.status)
} else {
Ok(Response {
qid: req.qid,
entry,
})
}
}
}