QEMU Module Debug Printing
Module debug printing allows verbose logging for a QEMU virtual peripheral, such as a SPI controller.
This will allow you to see register reads/writes (if the module supports it), and any time a debug print statement is used in a module.
Module Debug Printing by Using the Command Line
QEMU provides a way to print debugging output by passing in the -d command-line parameter.
This output typically informs the user of things such as guest errors, unimplemented features in a module, and what a module is currently doing.
However, you could also use -d to see information on lower level things, such as CPU and MMU activity.
Passing in the Command-Line Argument
-d can take in 1 or more arguments separated by a comma (with no space between arguments), or help and trace:help to show a full list of what can be printed using -d.
See the QEMU Options and Commands page for syntax.
Example Output
For this example we'll be passing in
-d trace:m25p80_command_decoded
to see what commands our SPI flash receives.
The output shown below is ZCU102 Linux boot with the added -d trace:m25p80_command_decoded command-line parameter:
201160@1598298783.243037:m25p80_command_decoded [0x55555ada87d0] new command:0x9f 201160@1598298783.254801:m25p80_command_decoded [0x55555ada87d0] new command:0x5a 201160@1598298783.261425:m25p80_command_decoded [0x55555ada87d0] new command:0x6 201160@1598298783.262073:m25p80_command_decoded [0x55555ada87d0] new command:0x1 201160@1598298783.263738:m25p80_command_decoded [0x55555ada87d0] new command:0x5 201160@1598298783.269035:m25p80_command_decoded [0x55555ada87d0] new command:0x6 201160@1598298783.269038:m25p80_command_decoded [0x55555ada9d10] new command:0x6 201160@1598298783.269714:m25p80_command_decoded [0x55555ada87d0] new command:0xb7 201160@1598298783.269717:m25p80_command_decoded [0x55555ada9d10] new command:0xb7 201160@1598298783.270148:m25p80_command_decoded [0x55555ada9d10] new command:0x4 201160@1598298783.271772:m25p80_command_decoded [0x55555ada87d0] new command:0x6 201160@1598298783.271775:m25p80_command_decoded [0x55555ada9d10] new command:0x6 201160@1598298783.272155:m25p80_command_decoded [0x55555ada87d0] new command:0x1 201160@1598298783.272157:m25p80_command_decoded [0x55555ada9d10] new command:0x1 201160@1598298783.272779:m25p80_command_decoded [0x55555ada87d0] new command:0x5 201160@1598298783.272781:m25p80_command_decoded [0x55555ada9d10] new command:0x5 201160@1598298783.273502:m25p80_command_decoded [0x55555ada87d0] new command:0x70 201160@1598298783.273504:m25p80_command_decoded [0x55555ada9d10] new command:0x70 201160@1598298783.274585:m25p80_command_decoded [0x55555ada87d0] new command:0x6 201160@1598298783.274588:m25p80_command_decoded [0x55555ada9d10] new command:0x6 201160@1598298783.275370:m25p80_command_decoded [0x55555ada87d0] new command:0xb7 201160@1598298783.275373:m25p80_command_decoded [0x55555ada9d10] new command:0xb7 201160@1598298783.275769:m25p80_command_decoded [0x55555ada87d0] new command:0x4 201160@1598298783.275771:m25p80_command_decoded [0x55555ada9d10] new command:0x4 [ 16.903020] m25p80 spi0.0: n25q512a (131072 Kbytes) [ 16.911027] 3 fixed-partitions partitions found on MTD device spi0.0 [ 16.911781] Creating 3 MTD partitions on "spi0.0":
Note that in this case some commands are repeated, because the flash is in a dual parallel configuration (as shown by the different addresses QEMU prints in the m25p80_command_decoded lines).
Module Debug Printing by Modifying Source Code
Some modules have extra debug printing that can be enabled by modifying the source code of the module.
These print statements usually show register accesses and what the module is currently doing.
Additional print statements could also be added by the user, if desired.
Finding the Module
When using a device tree, there are many ways to ways to find the module files that you want to add debug printing to. This section will cover two of them.
Using info qtree
In the QEMU monitor, info qtree will show you the device tree model that QEMU is using.
A short snippet is shown below.
(qemu) info qtree
# ...
dev: cdns.spi-r1p6, id "ps7-spi@0xFF050000"
gpio-out "" 4
gpio-out "sysbus-irq" 1
num-busses = 1 (0x1)
num-ss-bits = 4 (0x4)
num-txrx-bytes = 1 (0x1)
mmio ffffffffffffffff/0000000000000800
bus: spi0
type SSI
dev: sst25wf080, id "spi1_flash3@0"
gpio-in "ssi-gpio-cs" 1
nonvolatile-cfg = 36863 (0x8fff)
spansion-cr1nv = 0 (0x0)
spansion-cr2nv = 8 (0x8)
spansion-cr3nv = 2 (0x2)
spansion-cr4nv = 16 (0x10)
len-nv-cfg-large-stage = 0 (0x0)
drive = ""
dev: sst25wf080, id "spi1_flash2@0"
gpio-in "ssi-gpio-cs" 1
nonvolatile-cfg = 36863 (0x8fff)
spansion-cr1nv = 0 (0x0)
spansion-cr2nv = 8 (0x8)
spansion-cr3nv = 2 (0x2)
spansion-cr4nv = 16 (0x10)
len-nv-cfg-large-stage = 0 (0x0)
drive = ""
dev: sst25wf080, id "spi1_flash1@0"
gpio-in "ssi-gpio-cs" 1
nonvolatile-cfg = 36863 (0x8fff)
spansion-cr1nv = 0 (0x0)
spansion-cr2nv = 8 (0x8)
spansion-cr3nv = 2 (0x2)
spansion-cr4nv = 16 (0x10)
len-nv-cfg-large-stage = 0 (0x0)
drive = ""
dev: sst25wf080, id "spi1_flash0@0"
gpio-in "ssi-gpio-cs" 1
nonvolatile-cfg = 36863 (0x8fff)
spansion-cr1nv = 0 (0x0)
spansion-cr2nv = 8 (0x8)
spansion-cr3nv = 2 (0x2)
spansion-cr4nv = 16 (0x10)
len-nv-cfg-large-stage = 0 (0x0)
drive = ""
# ...
dev: xlnx.zynqmp-csu-core, id "csu_core"
gpio-out "sysbus-irq" 1
version-platform = 3 (0x3)
version-ps-version = 3 (0x3)
idcode = 73400467 (0x4600093)
mmio ffffffffffffffff/0000000000005038
# ...
On more complex systems, such as the Zynq UltraScale+ MPSoC or Versal Adaptive SoC, the output of info qtree can be very long.
For finding the module, the only part we care about is the line that says dev:.
The value to the right of dev:, e.g. xlnx.zynqmp-csu-core, is the object model name that QEMU uses.
We can use grep to find what file the object model name was defined in, which will most likely be the module file.
komlodi@machine:/scratch/proj/qemu/build$ grep -rin xlnx.zynqmp-csu-core --exclude-dir=build .. ../hw/misc/csu_core.c:42:#define TYPE_XLNX_CSU_CORE "xlnx.zynqmp-csu-core"
In this case, the Zynq UltraScale+ MPSoC CSU core source file is in hw/misc/csu_core.c.
We can verify this by looking at the top of the file and seeing a reference to debug printing for the CSU core.
#ifndef XLNX_CSU_CORE_ERR_DEBUG #define XLNX_CSU_CORE_ERR_DEBUG 0 #endif
Now let's look for the SPI controller, cdns.spi-r1p6.
komlodi@machine:/scratch/proj/qemu/build$ grep -rin cdns.spi-r1p6 --exclude-dir=build ..
../hw/core/fdt_generic_devices_cadence.c:50: { .name = "cdns.spi-r1p6", .parent = "xlnx.ps7-spi" },
In fdt_generic_devices_cadence.c there is a reference to debug printing, but it isn't for a SPI controller.
#ifndef FDT_GENERIC_UTIL_ERR_DEBUG #define FDT_GENERIC_UTIL_ERR_DEBUG 0 #endif
If we look deeper, we see a reference to a parent QEMU object model.
static const TypeInfo fdt_qom_aliases[] = {
{ .name = "xlnx.ps7-ethernet", .parent = "cadence_gem" },
{ .name = "cdns,gem", .parent = "cadence_gem" },
{ .name = "cdns,zynq-gem", .parent = "cadence_gem" },
{ .name = "cdns,zynqmp-gem", .parent = "cadence_gem" },
{ .name = "xlnx.ps7-ttc", .parent = "cadence_ttc" },
{ .name = "cdns.ttc", .parent = "cadence_ttc" },
{ .name = "cdns.uart", .parent = "cadence_uart" },
{ .name = "xlnx.ps7-uart", .parent = "cadence_uart" },
{ .name = "cdns.spi-r1p6", .parent = "xlnx.ps7-spi" }, // <--
{ .name = "xlnx.xuartps", .parent = "cadence_uart" },
};
This module name should be the one that contains the debug printing macro we want.
komlodi@machine:/scratch/proj/qemu/build$ grep -rin xlnx.ps7-spi --exclude-dir=build ..
../hw/core/fdt_generic_devices_cadence.c:50: { .name = "cdns.spi-r1p6", .parent = "xlnx.ps7-spi" },
../hw/arm/xilinx_zynq.c:124: dev = qdev_create(NULL, is_qspi ? "xlnx.ps7-qspi" : "xlnx.ps7-spi");
../include/hw/ssi/xilinx_spips.h:144:#define TYPE_XILINX_SPIPS "xlnx.ps7-spi"
We found #define TYPE_XILINX_SPIPS "xlnx.ps7-spi", but it's in a .h file.
We can assume that include/hw/ssi/xilinx_spips.h will be used in a .c file named hw/ssi/xilinx_spips.c, but that can be verified with grep.
komlodi@machine:/scratch/proj/qemu/build$ grep -rn xilinx_spips.h --exclude-dir=build .. ../hw/ssi/xilinx_spips.c:33:#include "hw/ssi/xilinx_spips.h" Binary file ../.git/index matches ../MAINTAINERS:795:F: include/hw/ssi/xilinx_spips.h ../include/hw/arm/xlnx-zynqmp.h:27:#include "hw/ssi/xilinx_spips.h"
Verify that it has the debug printing macro we're looking for.
komlodi@machine:/scratch/proj/qemu/build$ vim ../hw/ssi/xilinx_spips.c
// ...
#ifndef XILINX_SPIPS_ERR_DEBUG
#define XILINX_SPIPS_ERR_DEBUG 0
#endif
#define DB_PRINT_L(level, ...) do { \
if (XILINX_SPIPS_ERR_DEBUG > (level)) { \
fprintf(stderr, ": %s: ", __func__); \
fprintf(stderr, ## __VA_ARGS__); \
} \
} while (0)
Using the DTS or DTB Files
Using the DTS or DTB files to find the module file is similar to using info qtree.
If using a DTB file, you first need to un-flatten it.
komlodi@machine:/path/to/xilinx-zcu102-2020.2/pre-built/linux/images$ dtc -I dtb -O dts system.dtb -o system.dts komlodi@machine:/path/to/xilinx-zcu102-2020.2/pre-built/linux/images$ vim system.dts
In the DTS file, find the peripheral that you want to enable debug printing for.
For this example, we'll add debug printing to the ZynpMP's UART.
By looking at the register layout of the Zynq UltraScale+ MPSoC, we know UART0 is at address 0xFF000000. We can use that to identify the node in the DTS file.
serial@ff000000 {
u-boot,dm-pre-reloc;
compatible = "cdns,uart-r1p12", "xlnx,xuartps";
status = "okay";
interrupt-parent = <0x4>;
interrupts = <0x0 0x15 0x4>;
reg = <0x0 0xff000000 0x0 0x1000>;
clock-names = "uart_clk", "pclk";
power-domains = <0xc 0x21>;
clocks = <0x3 0x38 0x3 0x1f>;
pinctrl-names = "default";
pinctrl-0 = <0x1d>;
cts-override;
device_type = "serial";
port-number = <0x0>;
};
The line we care about is compatible = "cdns,uart-r1p12", "xlnx,xuartps";.
QEMU will go left-to-right and look for modules that are compatible with those strings.
Usually you can grep the compatible string and find the module file that way.
komlodi@machine:/scratch/proj/qemu/build$ grep -rin cdns,uart .. komlodi@machine:/scratch/proj/qemu/build$
However, that didn't work, so we need to look for something more generic.
komlodi@machine:/scratch/proj/qemu/build$ find .. -name "*uart*" ../hw/riscv/sifive_uart.c ../hw/char/lm32_juart.c ../hw/char/cmsdk-apb-uart.c ../hw/char/omap_uart.c ../hw/char/grlib_apbuart.c ../hw/char/xilinx_iomod_uart.c ../hw/char/exynos4210_uart.c ../hw/char/milkymist-uart.c ../hw/char/nrf51_uart.c ../hw/char/mcf_uart.c ../hw/char/xilinx_uartlite.c ../hw/char/lm32_uart.c ../hw/char/cadence_uart.c ../hw/char/digic-uart.c
hw/char/cadence_uart.c looks like the most likely file, verify it has a debug macro.
komlodi@machine:/scratch/proj/qemu/build$ vim ../hw/char/cadence_uart.c
// ...
#ifdef CADENCE_UART_ERR_DEBUG
#define DB_PRINT(...) do { \
fprintf(stderr, ": %s: ", __func__); \
fprintf(stderr, ## __VA_ARGS__); \
} while (0)
#else
#define DB_PRINT(...)
#endif
This confirms hw/char/cadence_uart.c is the file we're looking for.
If we did not find it, we would search for the next string in the compatible string list and repeat the same steps above.
Enabling Debug Printing
Modules have different ways to enable debug printing, but the underlying concepts are the same.
Changing the Debug Print Level
With modules that have a debug macro similar to
komlodi@machine:/scratch/proj/qemu/build$ vim ../hw/ssi/xilinx_spips.c
// ...
#ifndef XILINX_SPIPS_ERR_DEBUG
#define XILINX_SPIPS_ERR_DEBUG 0
#endif
#define DB_PRINT_L(level, ...) do { \
if (XILINX_SPIPS_ERR_DEBUG > (level)) { \
fprintf(stderr, ": %s: ", __func__); \
fprintf(stderr, ## __VA_ARGS__); \
} \
} while (0)
The DB_PRINT_L definition says that it will print if the level is above a threshold.
Therefore, to make it print, make XILINX_SPIPS_ERR_DEBUG greater than zero and rebuild QEMU. A higher debug level means more verbose printing.
An example QSPI debug output during ZCU102 Linux boot is shown below:
# ... : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: f404 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 1f501 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: fd00 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 1f501 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: fd00 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: c403 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: f404 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 1f501 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: fd00 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 6f502 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: c403 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: f404 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 1f501 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: fd00 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 6f502 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: c403 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: f404 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 1f501 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: fd00 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: c403 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: f404 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 1f501 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: fd00 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: c403 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: f404 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 : xlnx_zynqmp_qspips_flush_fifo_g: Dummy GQSPI Delay Command Entry, Do nothing: xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 1f501 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: fd00 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: c403 : xlnx_zynqmp_qspips_flush_fifo_g: GQSPI command: 0 [ 16.844785] m25p80 spi0.0: n25q512a (131072 Kbytes) [ 16.852754] 3 fixed-partitions partitions found on MTD device spi0.0 [ 16.854076] Creating 3 MTD partitions on "spi0.0": [ 16.856450] 0x000000000000-0x000001e00000 : "boot" [ 16.882958] 0x000001e00000-0x000001e40000 : "bootenv" [ 16.896354] 0x000001e40000-0x000004240000 : "kernel"
Adding a Debug Definition
With modules that don't mention print levels, such as
#ifdef CADENCE_UART_ERR_DEBUG
#define DB_PRINT(...) do { \
fprintf(stderr, ": %s: ", __func__); \
fprintf(stderr, ## __VA_ARGS__); \
} while (0)
#else
#define DB_PRINT(...)
#endif
Add a definition for CADENCE_UART_ERR_DEBUG and debug printing will be enabled.
Caveats
In some situations, modules are accessed very frequently.
This means that enabling debug printing for that module will cause a lot of text to be printed.
For example, if enabling debug printing for hw/char/cadence_uart.c on a ZCU102 default PetaLinux image, we will see all of stdout and stderr redirected to the UART.
# ... p: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:00000072 r: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:0000006f o: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:00000063 c: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:00000065 e: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:00000073 s: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:00000073 s: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:00000069 i: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:0000006e n: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:00000067 g: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:00000020 : uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:00000046 F: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:00000044 D: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:00000054 T: uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:0000000d : uart_read: offset:0 data:00000010 : uart_read: offset:2c data:0000000a : uart_write: offset:30 data:0000000a # ...
© Copyright 2019 - 2022 Xilinx Inc. Privacy Policy