-
-
Notifications
You must be signed in to change notification settings - Fork 846
inconsistent logging results when using atomics #160
nihalpasham
started this conversation in
General
-
This seems like an odd issue.
I'm using the log crate to abstract over the (UART-based) logging implementation. log uses atomics under the hood to initialize the global logger. In this case, I'm using set_logger_racy
pub unsafe fn set_logger_racy(logger: &'static dyn Log) -> Result<(), SetLoggerError> { match STATE.load(Ordering::SeqCst) { UNINITIALIZED => { LOGGER = logger; STATE.store(INITIALIZED, Ordering::SeqCst); Ok(()) } INITIALIZING => { // This is just plain UB, since we were racing another initialization function unreachable!("set_logger_racy must not be used with other initialization functions") } _ => Err(SetLoggerError(())), } }
set_logger_racy uses an atomic load + store, like in the case panic_wait. I presume they are lowered to regular load/store operations on aarch64. However, initializing the global logger yields inconsistent results.
exceptionhandling andmmu + cachingare enabled in all cases.- Here's a link to the full implementation.
Case 1:
- with the global logger enabled, adding the following piece of code.
let _fat_cache = match ctrlr.populate_fat_cache(&volume) { Ok(val) => { info!("fat cache populated ...") } Err(e) => { panic!("error populating fat_cache, {:?}", e) } };
In theory, this snippet simply caches the fat table and should have no bearing on our global logger but nonetheless, adding this, results in the system-hanging without any exception. What's weird is the call to initialize the global logger is supposed to happen after printing a few more logs. In other words, none of the info logs from kernel_main get printed. It looks like the system simply hangs right after kernel_init.
--- COM3 is connected. Press Ctrl+] to quit --- [ 1.796213] EMMC: reset card. [ 1.796240] control1: 16143 [ 1.798915] Divisor = 63, Freq Set = 396825 [ 2.206299] CSD Contents : 00 40 0e 00 32 5b 59 00 00ed c8 7f 80 0a 40 40 [ 2.210115] cemmc_structure=1, spec_vers=0, taac=0x0E, nsac=0x00, tran_speed=0x32,ccc=0x05B5, read_bl_len=0x09, read_bl_partial=0b, write_blk_misalign=0b,read_blk_misalign=0b, dsr_imp=0b, sector_size =0x7F, erase_blk_en=1b [ 2.229749] CSD 2.0: ver2_c_size = 0xEFFC, card capacity: 31914459136 bytes or 31.91GiB [ 2.237654] wp_grp_size=0x0000000b, wp_grp_enable=0b, default_ecc=00b, r2w_factor=010b, write_bl_len=0x09, write_bl_partial=0b, file_format_grp=0, copy=1b, perm_write_protect=0b, tmp_write_protect=0b, file_format=0b ecc=00b [ 2.257375] control1: 271 [ 2.259895] Divisor = 1, Freq Set = 25000000 [ 2.266381] EMMC: Bus width set to 4 [ 2.267542] EMMC: SD Card Type 2 HC, 30436Mb, mfr_id: 3, 'SD:ACLCD', r8.0, mfr_date: 1/2017, serial: 0xbbce119c, RCA: 0xaaaa [ 2.278659] EMMC2 driver initialized... hangs.....
Case 2:
- with the global logger enabled but without the above snippet of code, it works as expected. As you can see from the output logs, we print
[INFO]logs.
boards\bootloaders\rpi4 on main [!?] is 📦 v0.1.0 via 🦀 v1.61.0-nightly ❯ terminal-s.exe --- COM3 is connected. Press Ctrl+] to quit --- [ 1.796262] EMMC: reset card. [ 1.796289] control1: 16143 [ 1.798965] Divisor = 63, Freq Set = 396825 [ 2.206343] CSD Contents : 00 40 0e 00 32 5b 59 00 00ed c8 7f 80 0a 40 40 [ 2.210159] cemmc_structure=1, spec_vers=0, taac=0x0E, nsac=0x00, tran_speed=0x32,ccc=0x05B5, read_bl_len=0x09, read_bl_partial=0b, write_blk_misalign=0b,read_blk_misalign=0b, dsr_imp=0b, sector_size =0x7F, erase_blk_en=1b [ 2.229792] CSD 2.0: ver2_c_size = 0xEFFC, card capacity: 31914459136 bytes or 31.91GiB [ 2.237698] wp_grp_size=0x0000000b, wp_grp_enable=0b, default_ecc=00b, r2w_factor=010b, write_bl_len=0x09, write_bl_partial=0b, file_format_grp=0, copy=1b, perm_write_protect=0b, tmp_write_protect=0b, file_format=0b ecc=00b [ 2.257419] control1: 271 [ 2.259938] Divisor = 1, Freq Set = 25000000 [ 2.266424] EMMC: Bus width set to 4 [ 2.267586] EMMC: SD Card Type 2 HC, 30436Mb, mfr_id: 3, 'SD:ACLCD', r8.0, mfr_date: 1/2017, serial: 0xbbce119c, RCA: 0xaaaa [ 2.278703] EMMC2 driver initialized... [ 2.282526] rpi4 version 0.1.0 [ 2.285479] Booting on: Raspberry Pi 4 [ 2.289128] MMU online. Special regions: [ 2.292950] 0x00080000 - 0x000acfff | 180 KiB | C RO PX | Kernel code and RO data [ 2.301117] 0xfe000000 - 0xff84ffff | 24 MiB | Dev RW PXN | Device MMIO [ 2.308241] Current privilege level: EL1 [ 2.312063] Exception handling state: [ 2.315625] Debug: Masked [ 2.318752] SError: Masked [ 2.321880] IRQ: Masked [ 2.325007] FIQ: Masked [ 2.328135] Architectural timer resolution: 18 ns [ 2.332739] Drivers loaded: [ 2.335432] 1. BCM GPIO [ 2.338299] 2. BCM PL011 UART [ 2.341687] Chars written: 1702 [ 2.344730] [INFO] create new emmc-fat controller... [ 2.350462] - rustBoot::fs::controller @ line:202 [ 2.360068] Listing root directory: [ 2.361587] - Found: SIGNED~1.ITB [ 2.365795] loading fit-image... [ 34.285615] loaded fit: 62202019 bytes, starting at addr: 0x4200000 [ 34.288911] authenticating fit-image... [ 34.293908] [INFO] computing "kernel" hash [ 34.298641] - rustBoot::dt::fit @ line:289 [ 35.404489] [INFO] computed "kernel" hash: 97dcbff24ad0a60514e31a7a6b34a765681fea81f8dd11e4644f3ec81e1044fb [ 35.412127] - rustBoot::dt::fit @ line:294 [ 35.416913] [INFO] kernel integrity consistent with supplied itb... [ 35.424724] - rustBoot::dt::fit @ line:308 [ 35.429526] [INFO] computing "fdt" hash [ 35.434107] - rustBoot::dt::fit @ line:289 [ 35.439856] [INFO] computed "fdt" hash: 3572783be74511b710ed7fca9b3131e97fd8073c620a94269a4e4ce79d331540 [ 35.449136] - rustBoot::dt::fit @ line:294 [ 35.453920] [INFO] fdt integrity consistent with supplied itb... [ 35.461472] - rustBoot::dt::fit @ line:308 [ 35.466274] [INFO] computing "ramdisk" hash [ 35.471202] - rustBoot::dt::fit @ line:289 [ 36.713353] [INFO] computed "ramdisk" hash: f1290587e2155e3a5c2c870fa1d6e3e2252fb0dddf74992113d2ed86bc67f37c [ 36.721078] - rustBoot::dt::fit @ line:294 [ 36.725862] [INFO] ramdisk integrity consistent with supplied itb... [ 36.733762] - rustBoot::dt::fit @ line:308 [ 36.738568] [INFO] computing "rbconfig" hash [ 36.743579] - rustBoot::dt::fit @ line:289 [ 36.748367] [INFO] computed "rbconfig" hash: b16d058c4f09abdb8da98561f3a15d06ff271c38a4655c2be11dec23567fd519 [ 36.759042] - rustBoot::dt::fit @ line:294 [ 36.763825] [INFO] rbconfig integrity consistent with supplied itb... [ 36.771813] - rustBoot::dt::fit @ line:308 ######## ecdsa signature checks out, image is authentic ######## [ 36.808898] relocating kernel to addr: 0x2200000 [ 36.832642] relocating initrd to addr: 0x200000 [ 36.834200] load rbconfig... [ 36.837013] patching dtb... [ 36.840865] relocating dtb to addr: 0x4000000 first 4 entries of FAT_CACHE, [[0, 0, 0, 0], [0, 0, 0, 0],[0, 0, 0, 0],[0, 0, 0, 0]]
Case 3:
- with the global logger disabled, everything works as expected. You can see that the time taken to load the fit-image is much faster (down from 30 seconds to 3 seconds).
boards\bootloaders\rpi4 on main [!?] is 📦 v0.1.0 via 🦀 v1.61.0-nightly ❯ terminal-s.exe --- COM3 is connected. Press Ctrl+] to quit --- [ 1.771731] EMMC: reset card. [ 1.771759] control1: 16143 [ 1.774434] Divisor = 63, Freq Set = 396825 [ 2.181818] CSD Contents : 00 40 0e 00 32 5b 59 00 00ed c8 7f 80 0a 40 40 [ 2.185634] cemmc_structure=1, spec_vers=0, taac=0x0E, nsac=0x00, tran_speed=0x32,ccc=0x05B5, read_bl_len=0x09, read_bl_partial=0b, write_blk_misalign=0b,read_blk_misalign=0b, dsr_imp=0b, sector_size =0x7F, erase_blk_en=1b [ 2.205267] CSD 2.0: ver2_c_size = 0xEFFC, card capacity: 31914459136 bytes or 31.91GiB [ 2.213172] wp_grp_size=0x0000000b, wp_grp_enable=0b, default_ecc=00b, r2w_factor=010b, write_bl_len=0x09, write_bl_partial=0b, file_format_grp=0, copy=1b, perm_write_protect=0b, tmp_write_protect=0b, file_format=0b ecc=00b [ 2.232893] control1: 271 [ 2.235413] Divisor = 1, Freq Set = 25000000 [ 2.241898] EMMC: Bus width set to 4 [ 2.243060] EMMC: SD Card Type 2 HC, 30436Mb, mfr_id: 3, 'SD:ACLCD', r8.0, mfr_date: 1/2017, serial: 0xbbce119c, RCA: 0xaaaa [ 2.254177] EMMC2 driver initialized... [ 2.258000] rpi4 version 0.1.0 [ 2.260954] Booting on: Raspberry Pi 4 [ 2.264602] MMU online. Special regions: [ 2.268425] 0x00080000 - 0x000abfff | 176 KiB | C RO PX | Kernel code and RO data [ 2.276591] 0xfe000000 - 0xff84ffff | 24 MiB | Dev RW PXN | Device MMIO [ 2.283715] Current privilege level: EL1 [ 2.287537] Exception handling state: [ 2.291099] Debug: Masked [ 2.294227] SError: Masked [ 2.297354] IRQ: Masked [ 2.300482] FIQ: Masked [ 2.303609] Architectural timer resolution: 18 ns [ 2.308214] Drivers loaded: [ 2.310907] 1. BCM GPIO [ 2.313774] 2. BCM PL011 UART [ 2.317162] Chars written: 1702 [ 2.465278] fat cache populated ... [ 2.465793] Listing root directory: [ 2.470188] - Found: SIGNED~1.ITB [ 2.474394] loading fit-image... [ 5.893780] loaded fit: 62202019 bytes, starting at addr: 0x4200000 [ 5.897076] authenticating fit-image... ######## ecdsa signature checks out, image is authentic ######## [ 7.400849] relocating kernel to addr: 0x2200000 [ 7.424647] relocating initrd to addr: 0x200000 [ 7.426205] load rbconfig... [ 7.429017] patching dtb... [ 7.432870] relocating dtb to addr: 0x4000000 first 4 entries of FAT_CACHE, [[248, 255, 255, 15], [255, 255, 255, 255], [255, 255, 255, 15], [255, 255, 255, 15]]
Any idea why this could be happening? Am I missing something specific to the rpi4?
Beta Was this translation helpful? Give feedback.
All reactions
Replies: 1 comment 10 replies
-
I don’t know your EMMC driver, and it is also not part of the tutorials here.
To me, this looks more like something races between your emmc driver init and this fat_cache snippet than with the logging. If you have caching enabled anyways then there should be no issue with the atomics.
Beta Was this translation helpful? Give feedback.
All reactions
10 replies
-
I don’t know if it has to do with the problem, but your current layout.ld is erroneous.
code_end_exclusive is aligned 4KiB (PAGE_SIZE), and then there’s a gap and then data starts 64KiB aligned.
Beta Was this translation helpful? Give feedback.
All reactions
-
I guess it was worth a try - used a 64KiB page-size to ensure there are no gaps between __code_end_exclusive and start of .data section.
still get the same result.
/* SPDX-License-Identifier: MIT OR Apache-2.0 * * Copyright (c) 2018-2021 Andre Richter <andre.o.richter@gmail.com> */ PAGE_SIZE = 64K; PAGE_MASK = PAGE_SIZE - 1; __rpi_phys_dram_start_addr = 0; /* The physical address at which the the kernel binary will be loaded by the Raspberry's firmware */ __rpi_phys_binary_load_addr = 0x80000; ENTRY(__rpi_phys_binary_load_addr) /* Flags: * 4 == R * 5 == RX * 6 == RW * * Segments are marked PT_LOAD below so that the ELF file provides virtual and physical addresses. * It doesn't mean all of them need actually be loaded. */ PHDRS { segment_boot_core_stack PT_LOAD FLAGS(6); segment_code PT_LOAD FLAGS(5); segment_data PT_LOAD FLAGS(6); } SECTIONS { . = __rpi_phys_dram_start_addr; /*********************************************************************************************** * Boot Core Stack ***********************************************************************************************/ .boot_core_stack (NOLOAD) : { /* ^ */ /* | stack */ . += __rpi_phys_binary_load_addr; /* | growth */ /* | direction */ __boot_core_stack_end_exclusive = .; /* | */ } :segment_boot_core_stack ASSERT((. & PAGE_MASK) == 0, "End of boot core stack is not page aligned") /*********************************************************************************************** * Code + RO Data + Global Offset Table ***********************************************************************************************/ __code_start = .; .text : { KEEP(*(.text._start)) *(.text._start_arguments) /* Constants (or statics in Rust speak) read by _start(). */ *(.text._start_rust) /* The Rust entry point */ *(.text*) /* Everything else, add all other input .text sections (i.e. from other input object files) to our main binary. */ } :segment_code .rodata : ALIGN(8) { *(.rodata*) } :segment_code .got : ALIGN(8) { *(.got) } :segment_code . = ALIGN(PAGE_SIZE); __code_end_exclusive = .; /*********************************************************************************************** * Data + BSS ***********************************************************************************************/ .data : { *(.data*) } :segment_data /* align .data to a 64KiB boundary. */ /* As we enable the MMU and set the paging granularity to 64KiB. */ /* So, the end of `code + ro` section and start of data section needs to be 64KiB aligned.*/ /* Section is zeroed in pairs of u64. Align start and end to 16 bytes */ .bss (NOLOAD): ALIGN(16) { __bss_start = .; *(.bss*); . = ALIGN(16); __bss_end_exclusive = .; } :segment_data /* not a section that's loaded into memory, we just need to allocate as many zeroed bytes.*/ }
grepped the symbol table for __code_end_exclusive, it looks right.
npashi@DESKTOP-M9O6B7J:/mnt/c/Users/Nil/devspace/rust/projects/rustBoot/boards/bootloaders/rpi4$ readelf -s ../../target/aarch64-unknown-none-softfloat/release/kernel | grep __code* 1581: 0000000000080000 0 NOTYPE GLOBAL DEFAULT 1 __code_start 1582: 00000000000b0000 0 NOTYPE GLOBAL DEFAULT 3 __code_end_exclusive
and assembly for the .data section
Disassembly of section .data: 00000000000b0000 <log::LOGGER.1>: b0000: 000a7350 00000000 Ps...... 00000000000b0008 <rustBoot_hal::rpi::rpi4::bsp::global::GPIO>: b0008: fe200000 00000000 .. ..... 00000000000b0010 <rustBoot_hal::rpi::rpi4::bsp::global::PL011_UART>: b0010: fe201000 000000000000000000000000 .. ............. ... 00000000000b0028 <rustBoot_hal::rpi::rpi4::bsp::drivers::emmc::EMMC_CARD>: ... b0068: 000abc37 0000000000000001000000007............... ...
Beta Was this translation helpful? Give feedback.
All reactions
-
What happens if you define your own static atomic and cmp_exchange it during boot?
Beta Was this translation helpful? Give feedback.
All reactions
-
You need to get an idea where you are actually hanging.
If you can’t get hold of a hw debugger, try something like implementing IRQ support, and periodically interrupt yourself and print ELR_EL1 to understand where the CPU was.
You could set the timer compare value register and then kick off counting with timer IRQ enabled (see time.rs in the tutorials). In the ISR, reset the timer again to get infinite periodic IRQs.
Beta Was this translation helpful? Give feedback.
All reactions
-
Yep, that's the only option I have left. I'll circle back when I'm in possession of hw debugger. Hopefully soon.
Beta Was this translation helpful? Give feedback.
All reactions
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment