Kernel Debug Log
Debug logs:
What follows is more-or-less stream of conciousness notes written while I was debugging my kernel code. I've found that writing my thought process down makes it easier to logically work through a problem. Additionally it's nice to document how I've solved problems.
The problem statement:
I'm currently trying to implement recursive page tables in my x86_64 kernel project. I've just gotten the map() function for the page mapper to stop faulting when mapping a test page, now we're trying to make use of the newly mapped page:
pub fn init(_multiboot_addr: usize) {
let mut frame_allocator = FrameAllocator::new(PhysicalAddress::new(10_000 * PAGE_SIZE));
let mut page_mapper = PageMapper::init_kernel_table();
let test_frame = Frame {
frame_number: 0x55_55_BB_00_BB_BB_BB_BB / PAGE_SIZE,
};
let test_page = Page::from_virtual_address(VirtualAddress::new(0x0000_1FFF_0000_0000));
page_mapper.map(test_page, test_frame, &mut frame_allocator);
log!("Success!");
let test_value: &mut u64 = unsafe {
&mut *(test_page.virtual_address().0 as *mut u64)
};
log!("test_value before: {test_value}"); // <--- PROBLEMS BEGIN HERE
*test_value = 100;
log!("test_value after: {test_value}");
log!("unmapping page");
page_mapper.unmap(test_page, test_frame, &mut frame_allocator);
}
When we try to access our new page we get the following error:
[kernel] Hello world! :)
[kernel] Multiboot flags 4026597203
[kernel::memory::frame_alloc] start: 0x2710000
[kernel::memory::page_mapper] writing pml4 entry
[kernel::memory::page_mapper] new recursive page: ff7fbfc3f000
[kernel::memory::frame_alloc] allocating frame: 2710000
[kernel::memory::page_mapper] table vaddr: ffffff7fbfc3f000
[kernel::memory::page_mapper] writing pdpt entry
[kernel::memory::page_mapper] new recursive page: ff7f87ffc000
[kernel::memory::frame_alloc] allocating frame: 2711000
[kernel::memory::page_mapper] table vaddr: ffffff7f87ffc000
[kernel::memory::page_mapper] writing pd entry
[kernel::memory::page_mapper] new recursive page: ff0fff800000
[kernel::memory::frame_alloc] allocating frame: 2712000
[kernel::memory::page_mapper] table vaddr: ffffff0fff800000
[kernel::memory::page_mapper] writing pt entry
[kernel::memory] Success!
[kernel::memory] test_value before: check_exception old: 0xffffffff new 0xe
0: v=0e e=0009 i=0 cpl=0 IP=0008:ffffffff801023c7 pc=ffffffff801023c7 SP=0010:ffffffff8010be00 CR2=00001fff00000000
RAX=0000000000000000 RBX=ffffffff8010c120 RCX=ffffffff8010c180 RDX=00000000000000e9
.
.
.
v=0e is vector 14, which according to the AMD64 system programming manual is a page fault exception. The error code e=0009 has bits zero and three set which are page-protection violation and reserved field violation respectively. We can also note that control register 2 (CR2) contains the virtual address for test_page.
So the first guess is that we're not setting one of the table entries correctly when we map. We do have page size extensions turned on (it's used to map our kernel pages in kernel/arch/amd64/start.S). However the page mapper only supports 4KiB pages for now and we should be able to use both 2MiB and 4KiB pages, as long as the page size bits are setup correctly. We'll also want to make sure we set the User/Supervisor bit correctly (since that's the other error incidated in the fault).
Running qemu with -s -S will add a gdb stub and pause before starting. Which gives me time to open gdb and run target remote localhost:1234 so we can get a debugging session going. Stepping through to just after map() returns, we can use the qemu monitoring (ctrl-alt-2 in the qemu window) to get tlb information:
We can also check general memory information:
The error output also dumps control registers.
CR0=80010011 CR2=00001fff00000000 CR3=0000000000106000 CR4=000000b0
CR4 contains 0x000000b0. 0xb0 sets bits 4, 5, and 7 for page size extension, physical address extension, and page global enable respectively.
We can also add some debug code to dump the state of relevant tables after we call map():
[kernel::memory::page_mapper] pml4
[kernel::memory::page_mapper] entry 0: 107023
[kernel::memory::page_mapper] entry 63: 2710063
[kernel::memory::page_mapper] entry 510: 106063
[kernel::memory::page_mapper] entry 511: 108023
[kernel::memory::page_mapper] pdpt
[kernel::memory::page_mapper] entry 508: 2711063
[kernel::memory::page_mapper] pd
[kernel::memory::page_mapper] entry 0: 2712063
[kernel::memory::page_mapper] pt
[kernel::memory::page_mapper] entry 0: 5555bb00bbbbb003
Looking at the physical address, a few things might be wrong here:
First: it's got more that 52 bits of data (because we have PSE and PAE set as noted before), so it's not really pointing where we think it is.
Second: that's probably way larger than the amount of 'physical' memory qemu uses by default which is 128 MiB. Ooops.
Let's change that to a more reasonable value: 0x4e20000 that fixes both problems.
Re-running shows we can access our newly mapped page, but also gives an error during unmap():
[kernel] Hello world! :)
[kernel] Multiboot flags 4026597203
[kernel::memory::frame_alloc] start: 0x2710000
[kernel::memory::page_mapper] writing pml4 entry
[kernel::memory::page_mapper] new recursive page: ff7fbfc3f000
[kernel::memory::frame_alloc] allocating frame: 2710000
[kernel::memory::page_mapper] table vaddr: ffffff7fbfc3f000
[kernel::memory::page_mapper] writing pdpt entry
[kernel::memory::page_mapper] new recursive page: ff7f87ffc000
[kernel::memory::frame_alloc] allocating frame: 2711000
[kernel::memory::page_mapper] table vaddr: ffffff7f87ffc000
[kernel::memory::page_mapper] writing pd entry
[kernel::memory::page_mapper] new recursive page: ff0fff800000
[kernel::memory::frame_alloc] allocating frame: 2712000
[kernel::memory::page_mapper] table vaddr: ffffff0fff800000
[kernel::memory::page_mapper] writing pt entry
[kernel::memory::page_mapper] pml4
[kernel::memory::page_mapper] entry 0: 107023
[kernel::memory::page_mapper] entry 63: 2710063
[kernel::memory::page_mapper] entry 510: 106063
[kernel::memory::page_mapper] entry 511: 108023
[kernel::memory::page_mapper] pdpt
[kernel::memory::page_mapper] entry 508: 2711063
[kernel::memory::page_mapper] pd
[kernel::memory::page_mapper] entry 0: 2712063
[kernel::memory::page_mapper] pt
[kernel::memory::page_mapper] entry 0: 4e20003
[kernel::memory] Success!
[kernel::memory] test_value before: 0
[kernel::memory] test_value after: 100
[kernel::memory] unmapping page
[kernel::memory::page_mapper] new recursive page: ff7fbfc3f000
[kernel::memory::page_mapper] table vaddr: ffffff7fbfc3f000
[kernel::memory::page_mapper] new recursive page: ff7f87ffc000
[kernel::memory::page_mapper] table vaddr: ffffff7f87ffc000
[kernel::memory::page_mapper] new recursive page: ff0fff800000
[kernel::memory::page_mapper] table vaddr: ffffff0fff800000
[kernel::unwind] PANIC file='memory/page_mapper.rs',
line=134 :: assertion failed: frame == pt_entry.frame()
but that's a problem for another debug log!