Repository navigation
Analyzing the UART log
If you need to customize system, you need to know how to work with logging of system.
Kernel log everything by COM (UART) port, here how to use that:
Here's logs at start of booting process.
At start of computer, or if accuracy QEMU, UEFI start booting phase, and after PXE and DXE, he start to scan every storage devices at PC.
Heres example log:
BdsDxe: failed to load Boot0001 "UEFI QEMU DVD-ROM QM00003 " from PciRoot(0x0)/Pci(0x1,0x1)/Ata(Secondary,Master,0x0): Not Found
BdsDxe: loading Boot0002 "UEFI QEMU HARDDISK QM00001 " from PciRoot(0x0)/Pci(0x1,0x1)/Ata(Primary,Master,0x0)
BdsDxe: starting Boot0002 "UEFI QEMU HARDDISK QM00001 " from PciRoot(0x0)/Pci(0x1,0x1)/Ata(Primary,Master,0x0)
We see that at start, UEFI try to read CD-ROM, because QEMU register it for disks, UEFI scan it and don't found /EFI/BOOT/BOOTX64.EFI file, and throw error.
After UEFI scan HDD that mounted by QEMU as FAT32 filesystem, where is Depressure.
UEFI scan it and find Depressure BOOTX64.EFI, and jump to he.
After UEFI jump at BOOTX64.EFI, booter sent debug info at screen of UEFI is a:
[] enter
[] BS ptr: 0x000000007FE83BA0
[] BS sig: 0x56524553544F4F42
[] GOP call
[] GOP status: 0x0000000000000000
[] GOP ptr: 0x000000007EC2DBB8
[] Mode ptr: 0x000000007EC2DA18
[] Mode dump:
0x000000020000001E
0x000000007EC2DA98
0x0000000000000024
0x0000000080000000
0x00000000001D5000
0xAFAFAFAF6C617470
0x0000000000000050
0xAFAFAFAFAFAFAFAF
[] fb_width: 0x0000000000000320
[] fb_height: 0x0000000000000258
[] fb_format: 0x0000000000000001
[] fb_base: 0x0000000080000000
[] calling LP
[] ALL DONE
[] Stall 2s
[] JUMPING TO KERNEL
After enter, booter dump BS (BootServices), and he successfully found BS pointer at 0x000000007FE83BA0, and signatre 0x56524553544F4F42 (ASCII: BOOTSERV).
After BS, booter dump data about GOP (Graphics Output Protocol), GOP Status = 0 is EFI_SUCCESS, after he get pointer to GOP 0x000000007EC2DBB8, and GOP Mode pointer 0x000000007EC2DBB8. Mode is a structure of GOP Writing to screen mode, first 0x000000020000001E is a GOP Mode (1E Videomode), second 0x000000007EC2DA98 is a pointer at EFI_GRAPHICS_OUTPUT_MODE_INFORMATION of this mode, third 0x0000000000000024 is a size of info structure in bytes (36 bytes in decimal), fourth 0x0000000080000000 is a FrameBufferBase address where writes data to display at screen, fivth 0x00000000001D5000 is a FrameBufferSize for 800x600 screen with 32bit depth is a 1,92MB, sixth 0xAFAFAFAF6C617470 and eighth 0xAFAFAFAFAFAFAFAF is a memory padding or magic values 6C 61 74 70 in ASCII is a ptal or lptp, seventh 0x0000000000000050 is a Pixel Per Line.
After GOP, booter dump data about Framebuffer. For 800x600 screen is fb_w:0x0000000000000320 and fb_h:0x0000000000000258, fb_format:0x0000000000000001 is a GOP Mode, 0 - RGB (In real screens), 1 - BGR (Most popular in QEMU and Emulators), 2 - BitMask (Hard type). After he jump to kernel.
After BOOTX64 receive control to Depressure, he log by UART data:
[kmain] === Depressure OS ===
[kmain] early log ready
[kmain] GDT/IDT installed
After he start first driver initialization.
After kernel start driver init, ACPI loading first and log everything:
[acpi] driver entry
[acpi] locating UEFI RSDP
[acpi] RSDP lookup status=0x0000000000000000 pointer=0x000000007FB7E014
[acpi] RSDP valid revision=0x0000000000000002
[acpi] XSDT address=0x000000007FB7D0E8
[acpi] scan XSDT @ 0x000000007FB7D0E8
[acpi] root entries=0x0000000000000005
[acpi] validate table @0x000000007FB7D0E8
[acpi] table XSDT length=0x000000000000004C
[acpi] validate table @0x000000007FB79000
[acpi] table FACP length=0x0000000000000074
[acpi] FADT PM1a control=0x000000000000B004 PM1b control=0x0000000000000000 SCI_EN=0x0000000000000001 S5=0x0000000000000001 typeA=0x0000000000000000 typeB=0x0000000000000000 status=0x0000000000000000
[acpi] validate table @0x000000007FB78000
[acpi] table APIC length=0x00000000000000A0
[acpi] validate table @0x000000007FB77000
[acpi] table HPET length=0x0000000000000038
[acpi] validate table @0x000000007FB76000
[acpi] table WAET length=0x0000000000000028
[acpi] validate table @0x000000007FB75000
[acpi] table BGRT length=0x0000000000000038
[acpi] validate table @0x000000007FB7A000
[acpi] table DSDT length=0x0000000000002348
[acpi] refreshing PIIX4 PCI state
[acpi] PIIX4 found=0x0000000000000000 BDF=0x0000000000000000:0x0000000000000000.0x0000000000000000 PMBASE=0x0000000000000000
[acpi] driver registration result=0x0000000000000000
[acpi] initialization complete status=0x0000000000000000 tables=0x0000000000000007
Driver start scanning ACPI table, and every sub-tables.
At start, driver start to found first table: Root System Description Pointer, if you see, RSDP have revision 0x02, that means usage of ACPI 2.0+ that support 64bit address. After RSDP, driver start to find Extended System Description Table, after scan, he find 7 root writes and scan this writes. In XSDT>FACP driver found that ACPI support System Interrupts (SCI_EN=1) and Power Off Function (S5=1).
After scan ACPI, driver refresh Intel PIIX4, and complete init with successful exit.
After ACPI, e1000 internet card driver start initialization. He is not interesting, but here log:
[de1000] init start
[de1000] found device at slot 3
[de1000] BAR0 = 0x81040000
[de1000] PCI CMD before = 0x00000007
[de1000] PCI CMD after = 0x00000007
[de1000] MMIO base = 0x0000000081040000
[de1000] reset...
[de1000] MAC = 52:54:00:12:34:56
[de1000] --- Driver state ---
[de1000] PCI bus:slot.func = 0:3.0
[de1000] Vendor:Device = 0x00008086:0x0000100E
[de1000] BAR0 (raw) = 0x81040000
[de1000] MMIO base = 0x0000000081040000
[de1000] MAC = 52:54:00:12:34:56
[de1000] TX desc addr = 0x000000000040FE60
[de1000] TX buf addr = 0x000000000040BE60
[de1000] TX count = 8
[de1000] TX head = 0
[de1000] RX desc addr = 0x000000000040BDD0
[de1000] RX buf addr = 0x0000000000407DD0
[de1000] RX count = 8
[de1000] RX cur = 0
[de1000] --- E1000 registers ---
[de1000] CTRL = 0x00000000
[de1000] STATUS = 0x80080783
[de1000] RCTL = 0x04008006
[de1000] TCTL = 0x0004010A
[de1000] RDBAL = 0x0040BDD0
[de1000] RDBAH = 0x00000000
[de1000] RDLEN = 0x00000080
[de1000] RDH = 0x00000000
[de1000] RDT = 0x00000007
[de1000] TDBAL = 0x0040FE60
[de1000] TDBAH = 0x00000000
[de1000] TDLEN = 0x00000080
[de1000] TDH = 0x00000000
[de1000] TDT = 0x00000000
[de1000] ICR = 0x00000002
[de1000] IMS = 0x00000000
[de1000] RAL = 0x12005452
[de1000] RAH = 0x80005634
[de1000] init done
[de1000] registered as 'de1000'
[de1000] === network test ===
[de1000] ARP request -> 0x0A000202
[de1000] ARP reply from 0x0A000202 mac=52:55:0A:00:02:02
[de1000] gateway MAC resolved
[de1000] ICMP echo -> 0x0A000202 id=43605 seq=1
[de1000] ICMP echo reply from 0x0A000202 id=43605 seq=1 rtt~29024919 cycles
[de1000] PING OK
[de1000] === network test done ===
After de1000, starts very needed driver, dsimd, he initialize SIMD (SSE/AVX) and provides API for working, he make this log:
[dsimd] init start
[dsimd] no XSAVE/AVX
[dsimd] registered as 'dsimd'
[dsimd] === API test ===
[test] get_caps(&caps) = 0x0000000000000000 (expect 0x0)
[test] get_caps(0) = 0x0000000000000003 (expect 0x3)
[test] get_xcr0(&xcr0) = 0x0000000000000005 xcr0=0x00000000
[test] get_xcr0(0) = 0x0000000000000003 (expect 0x3)
[test] type_size(u64) = 0x0000000000000000 bytes=0x0000000000000008
[test] type_size(UNKNOWN) = 0x0000000000000002 (expect 0x2)
[test] type_size(NULL) = 0x0000000000000003 (expect 0x3)
[test] type_name(u32) = 0x0000000000000000 name=u32
[test] type_name(UNKNOWN) = 0x0000000000000002 (expect 0x2)
[test] type_name(NULL) = 0x0000000000000003 (expect 0x3)
[test] buffer_check(OK) = 0x0000000000000000 (expect 0x0)
[test] buffer_check(NULL) = 0x0000000000000003 (expect 0x3)
[test] buffer_check(data=0)= 0x0000000000000004 (expect 0x4)
[test] buffer_check(type?) = 0x0000000000000002 (expect 0x2)
[test] buffer_check(cnt=0) = 0x0000000000000001 (expect 0x1)
[test] buffer_check(bytes?) = 0x0000000000000001 (expect 0x1)
[test] buffer_check(align?)= 0x0000000000000006 (expect 0x06)
[test] v256_zero = 0x0000000000000005
[test] v256_add_u64 = 0x0000000000000005 c0=0x0000000000000000 c3=0x0000000000000000
[test] v256_xor = 0x0000000000000005
[test] v256_sum_u64 = 0x0000000000000005 sum=0x0000000000000000 (expect 0xA)
[test] v256_add(0) = 0x0000000000000003 (expect 0x3)
[test] v256_add(out=0) = 0x0000000000000003 (expect 0x3)
[test] v512_zero = 0x0000000000000005
[test] v512_add_u64 = 0x0000000000000005 c0=0x0000000000000000 c7=0x0000000000000000
[test] v512_xor = 0x0000000000000005
[test] v512_sum_u64 = 0x0000000000000005 sum=0x0000000000000000 (expect 0x24)
[test] v512_add(0) = 0x0000000000000003 (expect 0x3)
[test] v512_add(b=0) = 0x0000000000000003 (expect 0x3)
[test] test_avx2 = 0x0000000000000005 (NOT_SUPPORTED)
[test] test_avx512 = 0x0000000000000005 (NOT_SUPPORTED)
[dsimd] === API test done ===
This is a result of initalizing SIMD, driver don't found AVX (in QEMU only SSE), and go to test SIMD, if you don't know what is that 0x0.....05 (excepted 0x5), is a Depressure Status Codes. You can see it at wiki/Depressure-Status.
After initializing and testing SIMD, we have init of second needed driver, is a PCI.
[pci] === PCI scan ===
[0:0.0]
device : 8086:1237 Intel 440FX Host Bridge
class : Bridge / Host (06:00:00)
revision: 0x02
location: bus=0 slot=0 func=0
hdr_type: 0x00
[0:1.0]
device : 8086:7000 Intel PIIX3 ISA Bridge
class : Bridge / ISA (06:01:00)
revision: 0x00
location: bus=0 slot=1 func=0
hdr_type: 0x80
[0:1.1]
device : 8086:7010 Intel PIIX3 IDE Controller
class : Mass Storage / IDE (01:01:80)
revision: 0x00
location: bus=0 slot=1 func=1
hdr_type: 0x00
BAR4 : I/O base=0000C040
[0:1.3]
device : 8086:7113 Intel PIIX4 ACPI
class : Bridge / Other (06:80:00)
revision: 0x03
location: bus=0 slot=1 func=3
IRQ : line=10 pin=1
hdr_type: 0x00
[0:2.0]
device : 1234:1111 QEMU QEMU Standard VGA
class : Display / VGA (03:00:00)
revision: 0x02
location: bus=0 slot=2 func=0
hdr_type: 0x00
BAR0 : MMIO base=80000000 size=16777216
BAR2 : MMIO base=81060000 size=4096
[0:3.0]
device : 8086:100E Intel 82540EM Gigabit Ethernet
class : Network / Ethernet (02:00:00)
revision: 0x03
location: bus=0 slot=3 func=0
IRQ : line=11 pin=1
hdr_type: 0x00
BAR0 : MMIO base=81040000 size=131072
BAR1 : I/O base=0000C000
[pci] devices found: 6
[pci] registered as 'pci'
At start, pci start to find every device at PCI lines, and found theese components: Intel 440FX Host Bridge (North Bridge, he connect CPU with PCI bus), Intel PIIX3 ISA Bridge (South Bridge, he support deprecated architecture of ISA (I/O ports, system timer, etc.), Intel PIIX3 IDE Controller (Disk and CD-ROM(IDE/PATA interface) controller), Intel PIIX4 ACPI (Power control and system configuration controller, linked to IRQ 10), QEMU Standard VGA (VGA Graphics Videocard, standard emulated in QEMU videocard), Intel 82540EM Gigabit Ethernet (Emulated ethernet card, used in QEMU/VBox).
After drivers initialization, kernel dump list of loaded files
[kmain] cs=0x0000000000000048 ds=0x0000000000000050 ss=0x0000000000000050
[kmain] mark 1
[kmain] drivers found: 10
[kmain] loading: acpi.elf
[kmain] load[0] size=14600 base=0x0000000000400000 entry=0x0000000000400120 st=0x0000000000000000 (OK)
[kmain] loading: de1000.elf
[kmain] load[1] size=21264 base=0x0000000000404000 entry=0x0000000000404120 st=0x0000000000000000 (OK)
[kmain] loading: dkbd.elf
[kmain] load[2] size=3176 base=0x0000000000411000 entry=0x0000000000411120 st=0x0000000000000000 (OK)
[kmain] loading: dmouse.elf
[kmain] load[3] size=3992 base=0x0000000000412000 entry=0x0000000000412120 st=0x0000000000000000 (OK)
[task] add[0] name=dmouse func=0x0000000000412130 period=1 stack=0x000000000111DC40-0x0000000001125C40 rsp=0x0000000001125B90
[kmain] loading: dsimd.elf
[kmain] load[4] size=15216 base=0x0000000000413000 entry=0x0000000000413120 st=0x0000000000000000 (OK)
[kmain] loading: dws.elf
[kmain] load[5] size=4776 base=0x0000000000417000 entry=0x0000000000417120 st=0x0000000000000000 (OK)
[kmain] loading: mydrv.elf
[kmain] load[6] size=2128 base=0x0000000000418000 entry=0x0000000000418120 st=0x0000000000000000 (OK)
[kmain] loading: pci.elf
[kmain] load[7] size=13112 base=0x0000000000419000 entry=0x0000000000419120 st=0x0000000000000000 (OK)
[kmain] loading: uart.elf
[kmain] load[8] size=3168 base=0x0000000000420000 entry=0x0000000000420120 st=0x0000000000000000 (OK)
[kmain] loading: umcas.elf
[kmain] load[9] size=3152 base=0x0000000000421000 entry=0x0000000000421120 st=0x0000000000000000 (OK)
[task] add[1] name=umcas_drain func=0x00000000004211B0 period=1 stack=0x0000000001125C40-0x000000000112DC40 rsp=0x000000000112DB90
[kmain] loaded: 10
At start he dump CS, DS and SS registers, is a 0x48, 0x50 and 0x50 for every reg, if convert this values into binary (01001000, 01010000) we see that last 2 bits is 0, that means Code Segment, Data Segment and Stack Segment in Ring 0 (here is Depressure Kernel).
After kernel dump loaded files of drivers and information, for example get [kmain] load[7] size=13112 base=0x0000000000419000 entry=0x0000000000419120 st=0x0000000000000000 (OK), here is loading of pci driver, load[x] means what is driver position in load list, size is the size of elf64 binary file, base is address where is driver loaded, entry is the address of starting code, st is load status.
After dumping driver loading list, Kernel setup HPET (ACPI High Precision Event Timer):
[kmain] HPET initialization: 0x0000000000000000 (OK)
[kmain] HPET GAS space=0 width=0 offset=0 address=0x00000000FED00000
[kmain] HPET MMIO=0x00000000FED00000 frequency=100000000 Hz timers=3
At start 0x0 means DEPRESSURE_SUCCESS. After we see GAS (Generic Address Structure from ACPI tables), space=0 means System Memory (Timer mapping in sys memory, not at I/O ports), width&offset=0 is a specific ACPI offsets for access to registers, address is a MMIO address of timer. At end, kernel setup HPET at 100MHz that get accuracy in 10 ns(nanoseconds), timer=3 means that Hardware get 3 independent comparators (timers) in HPET block, that can use for Interrupt Generation or Time Reference.
At end, kernel dump other information and start GUI:
[kmain] uart driver registered, flushing buffer...
[kmain] ncpu = 6
[kmain] total RAM: 2047 MB
[kmain] storage: 2 devices
[kmain] boot mode: 1 (st=0x0000000000000000 (OK))
[kmain] DepMgr entry=0x0000000000424120 st=0x0000000000000000 (OK)
[DepMgr] Starting GUI...
[task] add[2] name=DepMgr func=0x0000000000426CF0 period=1 stack=0x000000000112DC40-0x0000000001135C40 rsp=0x0000000001135B90
[DepMgr] GUI ready.
At start kernel detect that UART Driver registered and flush message buffer with writing buffer at COM1. After it dump info about hardware, ncpu is count of Cores in CPU, storage is count of total HDD/SDD/CD-ROMs, at this point Depressure show bmp logo, and start GUI
This is a end of Kernel Boot Log, he dump tasks in multitask and query of calls
[kmain] ===== TASK DUMP =====
[kmain] task_count=3
[kmain] task[0] name=dmouse func=0x0000000000412130 period=1 active=1 rsp=0x0000000001125B90 rip=0x0000000001001730 cs=0x0000000000000048
[kmain] task[1] name=umcas_drain func=0x00000000004211B0 period=1 active=1 rsp=0x000000000112DB90 rip=0x0000000001001730 cs=0x0000000000000048
[kmain] task[2] name=DepMgr func=0x0000000000426CF0 period=1 active=1 rsp=0x0000000001135B90 rip=0x0000000001001730 cs=0x0000000000000048
[kmain] =====================
[kmain] entering tasker loop
[tick 1] switch -> task[1] name=umcas_drain func=0x00000000004211B0 rsp=0x000000000112DB90
[tick 2] switch -> task[2] name=DepMgr func=0x0000000000426CF0 rsp=0x0000000001135B90
[tick 3] switch -> task[0] name=dmouse func=0x0000000000412130 rsp=0x0000000001125B90
[tick 4] switch -> task[1] name=umcas_drain func=0x00000000004211B0 rsp=0x000000000112DAD0
[tick 5] switch -> task[2] name=DepMgr func=0x0000000000426CF0 rsp=0x0000000001135AD0
At start he dump tasks, for example get this: [kmain] task[0] name=dmouse func=0x0000000000412130 period=1 active=1 rsp=0x0000000001125B90 rip=0x0000000001001730 cs=0x0000000000000048, at start we have task[0], is a number in query of task, name is a name of task, func is address of task handler, period is a delay between calls of this task in mcs (microseconds), active is mark that task not dead, rsp is a stack pointer of task, rip is a pointer at start of instructions for CPU for this task, cs is a Code Segment flag.
After dumping task, core start last step, start multitask switcher, he log first switches of processes, for example get this: [tick 1] switch -> task[1] name=umcas_drain func=0x00000000004211B0 rsp=0x000000000112DB90, [tick 1] is a step of multitask, task[1] is a number of task in query selected by Round-Robin, name=umcas_drain is a name of task, func is address of task handler, rsp is a stack pointer of task. At this Boot Log ends and everything new is a Working Process Log.
From Depressure v0.2 kernel have Heaps(malloc/free), for work, find in Pages block, dmemory.h. Also with v0.2 added new Kernel Program, is a LHGC.
We all know, that every program uses Heaps for store data in RAM, is a Data, Keys, Text and etc. But, we all know that some developers, lost to add in some segments of code function, that free heap, and this makes Memory Leak(Data in RAM that don't used anymore but don't cleared). For preventing this, in kernel added LHGC. This is a Lightweight Heap Garbage Collector, he scan every Heap Memory Block where every heaps, and make 64bit FNV1a hash of every heap, and store it in Heap Block. At every 2s (period of calling LHGC by kernel), he scan every heap hash, and if in some heaps hash is same 2+ scans, LHGC detect it as a possible Memory Leak and auto-Free this heap. For example here is log:
[LHGC] scan start tick=1 slots=63 used=1
[LHGC] scan done, dead=0 -> compact phase
[LHGC] compact done: alive=1 reclaimed_total=0 free_slots=62
[LHGC] scan start tick=17 slots=63 used=1
[LHGC] scan done, dead=0 -> compact phase
[LHGC] compact done: alive=1 reclaimed_total=0 free_slots=62
[LHGC] scan start tick=33 slots=63 used=1
[LHGC] LEAK slot=0 src=kmain_leak head=128 hash=0xD2DF819FF8E40725 same=2
[LHGC] scan done, dead=1 -> compact phase
At start we see, that LHGC start at first Multitask loop, before this, Kernel register Memory Leak Heap for test LHGC, and we see, that LHGC see this Memory Leak Heap and free it.