Log boot và earlycon¶

Khi board không boot được, việc đầu tiên là xác định quá trình boot dừng ở giai đoạn nào, và log trên serial console là nguồn thông tin chính. Trang này trình bày theo thứ tự: log của từng giai đoạn boot, console sớm để kernel in log trước khi driver UART probe, mức log và bộ đệm log của kernel, theo dõi initcall, giữ log qua lần reboot bằng pstore, và bảng đối chiếu triệu chứng.

Trang này nói về việc dùng các công cụ log có sẵn trên board. Kết nối serial console với máy host xem trang Serial console. Debug code kernel bằng JTAG hoặc KGDB thuộc tab Linux Kernel.

Log theo giai đoạn boot¶

Mỗi giai đoạn boot để lại một dấu hiệu đặc trưng trên console. Dòng log cuối cùng nhìn thấy cho biết giai đoạn nào đã chạy xong và giai đoạn nào bị dừng:

Giai đoạn	Dấu hiệu trên console	Không thấy dấu hiệu thì kiểm tra
Boot ROM	Thường không in gì	Boot mode, header và vị trí của stage 1 trên boot media
Stage 1 (FSBL, SPL)	Log của FSBL hoặc banner của SPL, nếu được bật	Khởi tạo clock, DDR, pin mux của UART
U-Boot	Banner `U-Boot <phiên bản>`, sau đó là dấu nhắc hoặc đếm ngược `bootdelay`	Stage 1 không nạp được U-Boot, DDR không ổn định
Chuyển sang kernel	`Starting kernel ...`, do U-Boot in ngay trước khi nhảy vào kernel [7]	Image, DTB hoặc địa chỉ nạp sai
Kernel sớm	Trên ARM 32-bit, dòng đầu tiên là `Booting Linux on physical CPU ...` [6]	Không có console sớm, xem mục Console sớm
Console chính	Dòng có dạng `console [ttyPS0] enabled`	Driver UART chưa build sẵn trong kernel, `console=` sai tên thiết bị
Mount rootfs	`Waiting for root device ...` khi có `rootwait` [5]	Driver của thiết bị lưu trữ, `root=`
Init	`Run /sbin/init as init process` [4]	Rootfs thiếu init, sai kiến trúc của binary

Bảng triệu chứng chi tiết hơn cho phần bootloader nằm ở mục Debug quá trình boot của trang Bootloader.

Console sớm¶

Driver UART của kernel chỉ probe sau khi đã qua phần lớn quá trình khởi tạo. Nếu kernel lỗi trước thời điểm đó, log được ghi vào bộ đệm nhưng không in ra đâu cả, và trên console chỉ thấy Starting kernel ... rồi dừng. Console sớm giải quyết vấn đề này: một driver tối giản ghi thẳng vào thanh ghi UART theo kiểu polling, hoạt động ngay từ đầu quá trình boot.

earlycon¶

earlycon là cơ chế console sớm chung, dùng được trên các kiến trúc có Device Tree hoặc ACPI. Có hai cách khai báo:

earlycon không có tham số: kernel chọn UART theo thuộc tính stdout-path trong node chosen của Device Tree, hoặc theo bảng ACPI SPCR nếu nền tảng hỗ trợ [2].
earlycon=<driver>,<địa chỉ>[,tùy chọn]: chỉ định trực tiếp driver và địa chỉ thanh ghi. Với UART của Zynq (Cadence), driver là cdns và tùy chọn duy nhất là baudrate; nếu không ghi baudrate thì UART phải đã được bootloader cấu hình sẵn [2].

Ví dụ trên Zynq-7000, UART1 có địa chỉ 0xe0001000 [8]:

console=ttyPS0,115200 earlycon=cdns,0xe0001000,115200

Kernel cần bật CONFIG_SERIAL_EARLYCON, và driver UART phải khai báo hỗ trợ earlycon. Driver xilinx_uartps của Zynq khai báo earlycon cdns cho các compatible xlnx,xuartps, cdns,uart-r1p8 và cdns,uart-r1p12 [9].

earlyprintk¶

earlyprintk là cơ chế cũ hơn, phụ thuộc kiến trúc. Trên x86, tham số này có dạng như earlyprintk=serial,ttyS0,115200 [2]. Trên ARM 32-bit, CONFIG_EARLY_PRINTK phụ thuộc CONFIG_DEBUG_LL, cơ chế debug mức thấp dùng một UART được chọn cố định khi build kernel [11]. Kernel bật tùy chọn này chỉ in được log sớm trên đúng nền tảng đã chọn. Với các board có Device Tree, earlycon là lựa chọn nên dùng.

Chuyển từ console sớm sang console chính¶

Console sớm (bootconsole) bị hủy đăng ký ngay khi console chính được đăng ký. Kernel in dòng console [...] enabled ra mọi console trước khi hủy bootconsole, để báo rằng có thể đã có log chỉ in ra bootconsole [10]. Nếu lỗi xảy ra đúng trong khoảng giữa lúc bootconsole bị hủy và lúc console chính hoạt động, tham số keep_bootcon giữ lại bootconsole để tiếp tục thấy log [2].

Mức log và bộ đệm log¶

Mỗi thông điệp của kernel có một mức log từ 0 đến 7. Thông điệp có mức nhỏ hơn mức log của console (console loglevel) mới được in ra console [2][3]:

Mức	Tên	Ý nghĩa
0	`KERN_EMERG`	Hệ thống không dùng được
1	`KERN_ALERT`	Cần xử lý ngay
2	`KERN_CRIT`	Tình trạng nghiêm trọng
3	`KERN_ERR`	Lỗi
4	`KERN_WARNING`	Cảnh báo
5	`KERN_NOTICE`	Bình thường nhưng đáng chú ý
6	`KERN_INFO`	Thông tin
7	`KERN_DEBUG`	Thông tin debug

Mọi thông điệp đều được ghi vào bộ đệm vòng (ring buffer) của printk, bất kể có in ra console hay không. Vì vậy, nếu boot tới được shell, dmesg vẫn đọc được các thông điệp không hiện trên console.

Các tham số và thao tác liên quan:

Tham số hoặc lệnh	Tác dụng
`loglevel=<n>`	Đặt console loglevel lúc boot [2]
`quiet`	Tắt phần lớn log trên console [2]. Nên bỏ khi đang debug boot
`ignore_loglevel`	In mọi thông điệp ra console, bất kể mức log; đổi được lúc chạy qua `/sys/module/printk/parameters/ignore_loglevel` [2]
`printk.time=1`	Thêm timestamp vào đầu mỗi dòng log [2]
`log_buf_len=<n>`	Kích thước ring buffer, phải là lũy thừa của 2 [2]. Tăng khi log boot dài bị mất phần đầu
`cat /proc/sys/kernel/printk`	Hiện bốn giá trị: mức log hiện tại, mặc định, tối thiểu và mặc định lúc boot của console [3]
`dmesg -n 5`	Đặt console loglevel lúc chạy, ở ví dụ này chỉ in thông điệp từ `KERN_WARNING` trở lên [3]

Theo dõi initcall¶

Phần lớn quá trình khởi tạo kernel, gồm việc đăng ký và probe các driver build sẵn, chạy dưới dạng các hàm initcall. Tham số initcall_debug in một dòng trước và sau mỗi initcall [2]. Dòng sau có dạng initcall <hàm> returned <mã> after <n> usecs [4], nên tham số này dùng được cho hai việc:

Tìm chỗ treo. Dòng calling <hàm> cuối cùng mà không có dòng returned tương ứng chỉ ra initcall đang treo.
Tìm initcall chậm. Thời gian ở dòng returned cho biết initcall nào chiếm nhiều thời gian boot.

Các dòng này được in với mức KERN_DEBUG [4], nên muốn thấy trên console thì phải dùng kèm ignore_loglevel hoặc loglevel=8:

console=ttyPS0,115200 earlycon initcall_debug ignore_loglevel

Khi boot đã tới shell, có thể lọc từ dmesg, ví dụ dmesg | grep "initcall .* returned", rồi sắp xếp theo thời gian. Driver không probe được vì thiếu tài nguyên phụ thuộc thì không treo mà bị hoãn probe; trường hợp này kiểm tra bằng file devices_deferred, xem trang Porting Linux lên board tùy biến.

Giữ log qua lần reboot¶

Khi kernel panic rồi watchdog reset board, hoặc board tự reboot ngoài hiện trường, log trong ring buffer bị mất. pstore là cơ chế lưu log kernel vào một vùng lưu trữ còn giữ được nội dung sau reboot. ramoops là backend của pstore dùng một vùng RAM dành riêng; nội dung vùng RAM này còn sau warm reset, nhưng mất khi board mất nguồn.

Trên board có Device Tree, vùng RAM cho ramoops được khai báo trong reserved-memory [1]:

reserved-memory {
    #address-cells = <1>;
    #size-cells = <1>;
    ranges;

    ramoops@1ff00000 {
        compatible = "ramoops";
        reg = <0x1ff00000 0x100000>;    /* 1 MB cuối của 512 MB DDR */
        record-size = <0x4000>;
        console-size = <0x4000>;
    };
};

Ví dụ trong tài liệu kernel dùng #address-cells = <2> cho nền tảng 64-bit [1]; ví dụ trên dùng một cell cho Zynq-7000 32-bit, với địa chỉ giả định là 1 MB cuối của DDR. Kernel cần bật CONFIG_PSTORE và CONFIG_PSTORE_RAM.

Sau khi board reboot, log của lần boot trước nằm trong filesystem pstore, dưới dạng các file dmesg-ramoops-N [1]:

mount -t pstore pstore /sys/fs/pstore   # systemd tự mount sẵn điểm này
ls /sys/fs/pstore

Với systemd, /sys/fs/pstore được mount sẵn lúc khởi động [12]. Xóa một file trong pstore là xóa bản ghi tương ứng khỏi RAM [1]. Cơ chế này bổ sung cho kdump: pstore chỉ giữ log nhưng gọn và không cần kernel thứ hai, xem trang Kernel crash dump (kdump).

Đối chiếu triệu chứng¶

Triệu chứng	Hướng xử lý
Dừng ở `Starting kernel ...`	Thêm `earlycon`. Nếu vẫn không có log, kiểm tra địa chỉ nạp kernel và DTB, DTB có đúng board, kernel có đúng kiến trúc
Có log earlycon, dừng giữa chừng không có panic	Thêm `initcall_debug ignore_loglevel` để tìm initcall treo
Có log earlycon nhưng mất log sau dòng `console [...] enabled`	Sai `console=`, sai alias `serial` trong Device Tree, hoặc clock của UART sai; thử `keep_bootcon`
`Waiting for root device ...` mãi không tiếp tục	Driver của controller SD, eMMC hoặc của filesystem chưa build sẵn trong kernel; `root=` trỏ sai phân vùng
`VFS: Unable to mount root fs on ...` [5]	Sai `root=` hoặc `rootfstype=`, thiếu driver filesystem
`No working init found` [4]	Rootfs không có `/sbin/init` hoặc binary init build sai kiến trúc; thử `init=/bin/sh`
Board tự reboot, không kịp đọc log	Bật pstore và ramoops, đọc log của lần boot trước sau khi reboot

Liên quan¶

Serial console: nối UART, phần mềm terminal trên host, console=, getty.
Porting Linux lên board tùy biến: các mốc kiểm tra khi port board.
Bootloader trong hệ nhúng Linux: chuỗi boot nhiều stage và lỗi ở giai đoạn bootloader.
Linux Kernel Boot Process (Linux Kernel): các bước kernel thực hiện từ entry point tới init.
Kernel Command Line (Linux Kernel): danh sách tham số thường dùng.
Dynamic Debug (Linux Kernel): bật pr_debug của driver lúc boot.

Tài liệu tham khảo¶

[1] - Ramoops oops/panic logger - docs.kernel.org

[2] - The kernel's command-line parameters - docs.kernel.org, các tham số earlycon, earlyprintk, keep_bootcon, loglevel, quiet, ignore_loglevel, printk.time, log_buf_len, initcall_debug

[3] - Message logging with printk - docs.kernel.org

[4] - init/main.c - mainline kernel, thông điệp của initcall và init

[5] - init/do_mounts.c - mainline kernel, thông điệp khi mount rootfs

[6] - arch/arm/kernel/setup.c - mainline kernel

[7] - boot/bootm.c - mainline U-Boot

[8] - zynq-7000.dtsi - mainline kernel

[9] - xilinx_uartps.c - mainline kernel

[10] - kernel/printk/printk.c - mainline kernel, hàm register_console

[11] - arch/arm/Kconfig.debug - mainline kernel, DEBUG_LL và EARLY_PRINTK

[12] - src/shared/mount-setup.c - systemd, danh sách filesystem API được mount lúc khởi động