style: improve user-facing kernel messages #1974
Open
+343
−376
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
n0toose
force-pushed
the
improve-kernel-messages
branch
from
fefcf37 to
a165dcb
Compare
|
I went a bit overboard with this 2.5 hour effort, but this fixes a massive pet peeve I've had for a while. Given my lack of familiarity with some components, some mistakes may be present. (I also deliberately didn't go as far enough as to try to make things like punctuation/capitalization consistent :D) |
![github-actions[bot]](https://avatars.githubusercontent.com/in/15368?s=60&v=4){kind=small}
There was a problem hiding this comment.
Benchmark Results
| Benchmark | Current: 57d104e | Previous: 565ef14 | Performance Ratio |
|---|---|---|---|
| startup_benchmark Build Time | 107.60 s |
113.59 s |
0.95 |
| startup_benchmark File Size | 0.91 MB |
0.91 MB |
1.00 |
| Startup Time - 1 core | 0.90 s (±0.02 s) |
0.90 s (±0.03 s) |
1.01 |
| Startup Time - 2 cores | 0.92 s (±0.02 s) |
0.90 s (±0.02 s) |
1.03 |
| Startup Time - 4 cores | 0.93 s (±0.03 s) |
0.91 s (±0.02 s) |
1.02 |
| multithreaded_benchmark Build Time | 111.28 s |
113.29 s |
0.98 |
| multithreaded_benchmark File Size | 1.01 MB |
1.01 MB |
1.00 |
| Multithreaded Pi Efficiency - 2 Threads | 2.65 % (±12.71 %) |
4.07 % (±19.55 %) |
0.65 |
| Multithreaded Pi Efficiency - 4 Threads | 1.47 % (±7.08 %) |
1.94 % (±9.32 %) |
0.76 |
| Multithreaded Pi Efficiency - 8 Threads | 0.88 % (±4.21 %) |
1.13 % (±5.41 %) |
0.78 |
| micro_benchmarks Build Time | 104.89 s |
116.23 s |
0.90 |
| micro_benchmarks File Size | 1.01 MB |
1.01 MB |
1.00 |
| Scheduling time - 1 thread | 2.49 ticks (±11.94 ticks) |
2.76 ticks (±13.23 ticks) |
0.90 |
| Scheduling time - 2 threads | 1.54 ticks (±7.39 ticks) |
1.64 ticks (±7.88 ticks) |
0.94 |
| Micro - Time for syscall (getpid) | 0.10 ticks (±0.50 ticks) |
0.16 ticks (±0.77 ticks) |
0.65 |
| Memcpy speed - (built_in) block size 4096 | 1838.24 MByte/s (±8823.53 MByte/s) |
1474.06 MByte/s (±7075.47 MByte/s) |
1.25 |
| Memcpy speed - (built_in) block size 1048576 | 786.27 MByte/s (±3774.10 MByte/s) |
723.43 MByte/s (±3472.47 MByte/s) |
1.09 |
| Memcpy speed - (built_in) block size 16777216 | 230.27 MByte/s (±1105.28 MByte/s) |
221.43 MByte/s (±1062.86 MByte/s) |
1.04 |
| Memset speed - (built_in) block size 4096 | 1558.44 MByte/s (±7480.52 MByte/s) |
1578.95 MByte/s (±7578.95 MByte/s) |
0.99 |
| Memset speed - (built_in) block size 1048576 | 998.23 MByte/s (±4791.50 MByte/s) |
974.85 MByte/s (±4679.27 MByte/s) |
1.02 |
| Memset speed - (built_in) block size 16777216 | 978.24 MByte/s (±4695.55 MByte/s) |
971.72 MByte/s (±4664.27 MByte/s) |
1.01 |
| Memcpy speed - (rust) block size 4096 | 1212.12 MByte/s (±5818.18 MByte/s) |
1200.00 MByte/s (±5760.00 MByte/s) |
1.01 |
| Memcpy speed - (rust) block size 1048576 | 781.48 MByte/s (±3751.10 MByte/s) |
751.22 MByte/s (±3605.84 MByte/s) |
1.04 |
| Memcpy speed - (rust) block size 16777216 | 230.01 MByte/s (±1104.06 MByte/s) |
212.39 MByte/s (±1019.46 MByte/s) |
1.08 |
| Memset speed - (rust) block size 4096 | 1967.21 MByte/s (±9442.62 MByte/s) |
1578.95 MByte/s (±7578.95 MByte/s) |
1.25 |
| Memset speed - (rust) block size 1048576 | 1002.56 MByte/s (±4812.27 MByte/s) |
994.58 MByte/s (±4773.98 MByte/s) |
1.01 |
| Memset speed - (rust) block size 16777216 | 954.01 MByte/s (±4579.22 MByte/s) |
863.20 MByte/s (±4143.37 MByte/s) |
1.11 |
| alloc_benchmarks Build Time | 103.65 s |
103.60 s |
1.00 |
| alloc_benchmarks File Size | 0.97 MB |
0.97 MB |
1.00 |
| Allocations - Allocation success | 2.00 % (±13.86 %) |
2.00 % (±13.86 %) |
1 |
| Allocations - Deallocation success | 1.40 % (±9.68 %) |
1.40 % (±9.67 %) |
1.00 |
| Allocations - Pre-fail Allocations | 2.00 % (±13.86 %) |
2.00 % (±13.86 %) |
1 |
| Allocations - Average Allocation time | 228.02 Ticks (±1580.07 Ticks) |
282.08 Ticks (±1954.68 Ticks) |
0.81 |
| Allocations - Average Allocation time (no fail) | 228.02 Ticks (±1580.07 Ticks) |
282.08 Ticks (±1954.68 Ticks) |
0.81 |
| Allocations - Average Deallocation time | 13.44 Ticks (±93.11 Ticks) |
14.38 Ticks (±99.64 Ticks) |
0.93 |
| mutex_benchmark Build Time | 104.26 s |
103.90 s |
1.00 |
| mutex_benchmark File Size | 1.02 MB |
1.02 MB |
1.00 |
| Mutex Stress Test Average Time per Iteration - 1 Threads | 0.26 ns (±1.80 ns) |
0.26 ns (±1.80 ns) |
1 |
| Mutex Stress Test Average Time per Iteration - 2 Threads | 0.30 ns (±2.08 ns) |
0.30 ns (±2.08 ns) |
1 |
This comment was automatically generated by workflow using github-action-benchmark.
n0toose
force-pushed
the
improve-kernel-messages
branch
from
521890b to
2b10b81
Compare
- Move subjects to beginning of each message - Unify certain messages across architecture-specific implementations - State the component/task at the beginning of most messages (before verbs) to make log scrolling and pinpointing failures easier - Grammar-related improvements - Increase consistency of used wording - In some cases, display relevant variables - Replace debug! with error! before errors are returned. - Replace some debug! instances with trace! - Decrease the length of some sentences - Make messages of standard actions (e.g. driver init) consistent (mostly.) - Correct mentions of RTL8139 in the driver's messages - Add more variables inside of placeholders This change is not intended to be perfect and does not improve ALL messages, with many changes being highly subjective. It has a primary focus on debugging information and drivers. The primary motivation for this change is mostly the high amount of time spent trying to understand sequences of actions (and e.g. where specifically the booting of a kernel may break), while also assisting those that do not have a full picture of the kernel's source code. Some messages were not modified to include the name of the component, as it may be self-evident depending on the context and the debugging activity (see: src/drivers/gem.rs) and increase the mental noise, rather than decrease it.
n0toose
force-pushed
the
improve-kernel-messages
branch
from
2b10b81 to
57d104e
Compare
jounathaen
approved these changes
Oct 13, 2025
This was referenced Oct 17, 2025
Merged
|
@mkroening Would you like me to rebase this PR (and break out the commits)? |
|
What do you mean by breaking out the commits? You can rebase if you like, but I still need to write down my opinion about this before this is ready to merge. :D |
mkroening
requested changes
Oct 23, 2025
There was a problem hiding this comment.
Thanks for taking the time and opening this PR!
I like many of the changes and think they are good improvements. 👍
One thing I am not yet so sure about is manually moving the subjects to the front of the message and separating them by colons:
- I think it's difficult to reach and maintain consistency. Still, this would be a change for the better if we like it.
- In some cases, it sounds awkward. Having a subject in the sentence often really helps me.
CompareWaking up core 0...withCPU 0: Waking up core.... - We already have a system for printing module names:
feature = "log-target".
So for providing context at the start of the message, I think it would make sense to improve log-target instead.
Currently, the output looks like this:
[ ][0][INFO hermit] BSS starts at 0x1835980
[ ][0][INFO hermit] tls_info = Some(
TlsInfo {
start: 0x180c080,
filesz: 0x20,
memsz: 0x70,
align: 0x8,
},
)
[ ][0][INFO hermit::mm] Total memory size: 997 MiB
[ ][0][INFO hermit::mm] Kernel region: 0x1600000..0x1a00000
[ ][0][INFO hermit::mm] Minimum memory size: 31 MiB
[ ][0][INFO hermit::mm] Heap: size 866 MB, start address 0x400000000000
[ ][0][INFO hermit::mm] Heap is located at 0x400000000000..0x400036200000 (0 Bytes unmapped)
[ ][0][INFO hermit::mm] Physical memory free list:
0x1c02000.. 0x1e00000 (len = 0x1fe000, pages = 510)
0x37e00000.. 0x3ffe0000 (len = 0x81e0000, pages = 33248)
[ ][0][INFO hermit::mm] Virtual memory free list:
0x400036200000.. 0x800000000000 (len = 0x3fffc9e00000, pages = 17179647488)
[ ][0][INFO hermit::env] bootargs = hermit-loader-x86_64
[ 0.190108][0][INFO hermit::arch::x86_64::kernel::processor]
[ 0.193856][0][INFO hermit::arch::x86_64::kernel::processor] ========================== CPU INFORMATION ===========================
[ 0.197378][0][INFO hermit::arch::x86_64::kernel::processor] Model: Intel Core Processor (Skylake)
[ 0.197823][0][INFO hermit::arch::x86_64::kernel::processor] Frequency: 997 MHz (from Measurement)
[ 0.198368][0][INFO hermit::arch::x86_64::kernel::processor] SpeedStep Technology: Not Available
[ 0.198805][0][INFO hermit::arch::x86_64::kernel::processor] Features: MMX SSE SSE2 SSE3 SSSE3 SSE4.1 SSE4.2 AVX AESNI RDRAND FMA MOVBE MCE FXSR XSAVE RDTSCP CLFLUSH X2APIC HYPERVISOR AVX2 BMI1 BMI2 FSGSBASE RDSEED
[ 0.200700][0][INFO hermit::arch::x86_64::kernel::processor] Physical Address Width: 40 bits
[ 0.201111][0][INFO hermit::arch::x86_64::kernel::processor] Linear Address Width: 48 bits
[ 0.201458][0][INFO hermit::arch::x86_64::kernel::processor] Supports 1GiB Pages: No
[ 0.201779][0][INFO hermit::arch::x86_64::kernel::processor] ======================================================================
[ 0.202233][0][INFO hermit::arch::x86_64::kernel::processor]
[ 0.215960][0][INFO hermit::arch::x86_64::kernel::systemtime] Hermit booted on 2025-10-23 15:29:14.78551 +00:00:00
[ 0.225239][0][INFO hermit::arch::x86_64::kernel::acpi] Found an ACPI revision 0 table at 0xF52E0 with OEM ID "BOCHS "
[ 0.238941][0][INFO hermit::arch::x86_64::kernel::pci] Initialized PCI
[ 0.271566][0][INFO hermit::arch::x86_64::kernel::apic] IOAPIC v32 has 24 entries
[ 0.277677][0][INFO hermit::arch::x86_64::kernel::apic]
[ 0.278015][0][INFO hermit::arch::x86_64::kernel::apic] ===================== MULTIPROCESSOR INFORMATION =====================
[ 0.278438][0][INFO hermit::arch::x86_64::kernel::apic] APIC in use: x2APIC
[ 0.278769][0][INFO hermit::arch::x86_64::kernel::apic] Initialized CPUs: 1
[ 0.279057][0][INFO hermit::arch::x86_64::kernel::apic] ======================================================================
[ 0.279464][0][INFO hermit::arch::x86_64::kernel::apic]
[ 0.279680][0][INFO hermit] Compiled with PCI support
[ 0.279889][0][INFO hermit] Compiled with ACPI support
[ 0.280117][0][INFO hermit::drivers::pci]
[ 0.280317][0][INFO hermit::drivers::pci] ======================== PCI BUS INFORMATION =========================
[ 0.281094][0][INFO hermit::drivers::pci] 00:00 Unknown Class [0600]: Unknown Vendor Unknown Device [8086:1237]
[ 0.282117][0][INFO hermit::drivers::pci] 00:01 Unknown Class [0601]: Unknown Vendor Unknown Device [8086:7000]
[ 0.282453][0][INFO hermit::drivers::pci] 00:02 Unknown Class [0300]: Unknown Vendor Unknown Device [1234:1111], BAR0 Memory32 { address: 0xFD000000, size: 0x1000000, prefetchable: true }, BAR2 Memory32 { address: 0xFEBF0000, size: 0x1000, prefetchable: false }
[ 0.283786][0][INFO hermit::drivers::pci] 00:03 Unknown Class [0200]: Unknown Vendor Unknown Device [8086:100E], IRQ 11, BAR0 Memory32 { address: 0xFEBC0000, size: 0x20000, prefetchable: false }, BAR1 IO { port: 0xC000 }
[ 0.284736][0][INFO hermit::drivers::pci] ======================================================================
[ 0.285137][0][INFO hermit::drivers::pci]
[ 0.295606][0][INFO hermit] Hermit is running on common system!
[ 0.332993][0][INFO hermit] Jumping into application
Having the full path printed looks very busy to me, but if we only printed the last module of the path, it looks much better to me:
[ ][0][INFO hermit] BSS starts at 0x1837c80
[ ][0][INFO hermit] tls_info = Some(
TlsInfo {
start: 0x180e1f0,
filesz: 0x20,
memsz: 0x70,
align: 0x8,
},
)
[ ][0][INFO mm] Total memory size: 997 MiB
[ ][0][INFO mm] Kernel region: 0x1600000..0x1a00000
[ ][0][INFO mm] Minimum memory size: 31 MiB
[ ][0][INFO mm] Heap: size 866 MB, start address 0x400000000000
[ ][0][INFO mm] Heap is located at 0x400000000000..0x400036200000 (0 Bytes unmapped)
[ ][0][INFO mm] Physical memory free list:
0x1c02000.. 0x1e00000 (len = 0x1fe000, pages = 510)
0x37e00000.. 0x3ffe0000 (len = 0x81e0000, pages = 33248)
[ ][0][INFO mm] Virtual memory free list:
0x400036200000.. 0x800000000000 (len = 0x3fffc9e00000, pages = 17179647488)
[ ][0][INFO env] bootargs = hermit-loader-x86_64
[ 0.185185][0][INFO processor]
[ 0.189411][0][INFO processor] ========================== CPU INFORMATION ===========================
[ 0.192922][0][INFO processor] Model: Intel Core Processor (Skylake)
[ 0.193409][0][INFO processor] Frequency: 996 MHz (from Measurement)
[ 0.194006][0][INFO processor] SpeedStep Technology: Not Available
[ 0.194400][0][INFO processor] Features: MMX SSE SSE2 SSE3 SSSE3 SSE4.1 SSE4.2 AVX AESNI RDRAND FMA MOVBE MCE FXSR XSAVE RDTSCP CLFLUSH X2APIC HYPERVISOR AVX2 BMI1 BMI2 FSGSBASE RDSEED
[ 0.196144][0][INFO processor] Physical Address Width: 40 bits
[ 0.196483][0][INFO processor] Linear Address Width: 48 bits
[ 0.196797][0][INFO processor] Supports 1GiB Pages: No
[ 0.197080][0][INFO processor] ======================================================================
[ 0.197519][0][INFO processor]
[ 0.210918][0][INFO systemtime] Hermit booted on 2025-10-23 15:30:44.790533 +00:00:00
[ 0.219745][0][INFO acpi] Found an ACPI revision 0 table at 0xF52E0 with OEM ID "BOCHS "
[ 0.233964][0][INFO pci] Initialized PCI
[ 0.266142][0][INFO apic] IOAPIC v32 has 24 entries
[ 0.272461][0][INFO apic]
[ 0.272742][0][INFO apic] ===================== MULTIPROCESSOR INFORMATION =====================
[ 0.273156][0][INFO apic] APIC in use: x2APIC
[ 0.273440][0][INFO apic] Initialized CPUs: 1
[ 0.273701][0][INFO apic] ======================================================================
[ 0.274085][0][INFO apic]
[ 0.274261][0][INFO hermit] Compiled with PCI support
[ 0.274531][0][INFO hermit] Compiled with ACPI support
[ 0.274793][0][INFO pci]
[ 0.274966][0][INFO pci] ======================== PCI BUS INFORMATION =========================
[ 0.275752][0][INFO pci] 00:00 Unknown Class [0600]: Unknown Vendor Unknown Device [8086:1237]
[ 0.276751][0][INFO pci] 00:01 Unknown Class [0601]: Unknown Vendor Unknown Device [8086:7000]
[ 0.277085][0][INFO pci] 00:02 Unknown Class [0300]: Unknown Vendor Unknown Device [1234:1111], BAR0 Memory32 { address: 0xFD000000, size: 0x1000000, prefetchable: true }, BAR2 Memory32 { address: 0xFEBF0000, size: 0x1000, prefetchable: false }
[ 0.278531][0][INFO pci] 00:03 Unknown Class [0200]: Unknown Vendor Unknown Device [8086:100E], IRQ 11, BAR0 Memory32 { address: 0xFEBC0000, size: 0x20000, prefetchable: false }, BAR1 IO { port: 0xC000 }
[ 0.279462][0][INFO pci] ======================================================================
[ 0.279867][0][INFO pci]
[ 0.290144][0][INFO hermit] Hermit is running on common system!
[ 0.295311][0][INFO foo] foo
[ 0.332794][0][INFO hermit] Jumping into application
I like most of the other changes, though. Should I already pull out the non-subject moving changes that look good to me until we have reached consensus here, or what would you prefer? :)
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
3 participants
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
This change is not intended to be perfect and does not improve ALL messages, with many changes being highly subjective.
It has a primary focus on debugging information and drivers. The primary motivation for this change is mostly the high amount of time spent trying to understand sequences of actions (and e.g. where specifically the booting of a kernel may break), while also assisting those that do not have a full picture of the kernel's source code.
Some messages were not modified to include the name of the component, as it may be self-evident depending on the context and the debugging activity (see: src/drivers/gem.rs) and increase the mental noise, rather than decrease it.