diff --git a/doc/tutorials/debug.rst b/doc/tutorials/debug.rst new file mode 100644 index 000000000..8ddabf981 --- /dev/null +++ b/doc/tutorials/debug.rst @@ -0,0 +1,257 @@ +.. _acrn-debug: + +ACRN Debugging Tools +#################### + +This document describes how to use ACRN tools to collect log +and trace data for debugging. + +ACRN Console Command +******************** + +The ACRN console provides shell commands for a user to check system states +and environment settings. See the :ref:`acrnshell` documentation for a +full list of commands, or see a summary of available commands by using +the ``help`` command within the ACRN shell. + + +An example +********** + +As an example, we'll show how to obtain the interrupts of a pass-through USB device. + +First, we can get the USB controller BDF number (0:15.0) through the +following command in the SOS console:: + + lspci | grep "USB controller" + + +.. figure:: images/debug_image19.png + :align: center + + USB controller BDF information + +Second, we use the ``pt`` command in the ACRN console, and use this BDF number +to find the interrupt vector (VEC) "0x31". + +.. figure:: images/debug_image20.png + :align: center + + USB controller interrupt information + +Finally we use the ``int`` command in the ACRN console, and use this +interrupt vector to find the interrupt number (909) on CPU3. + +.. figure:: images/debug_image21.png + :align: center + + USB controller interrupt number information + +ACRN Log +******** + +ACRN log provides console log and mem log for a user to analyze. +We can use console log to debug directly, while mem log is a userland tool +used to capture a ACRN hypervisor log. + +Turn on the logging info +======================== + +ACRN enables a console log by default. + +To enable and start the mem log:: + + $ systemctl enable acrnlog + $ systemctl start acrnlog + + +Set and grab log +================ + +We have 1-6 log levels for console log and mem log. The following +functions print different levels of console log and mem log:: + + pr_dbg("debug...level %d", LOG_DEBUG); //level 6 + pr_info("info...level %d", LOG_INFO); //level 5 + pr_warn("warn...level %d", LOG_WARNING); //level 4 + pr_err("err...level %d", LOG_ERROR); //level 3 + pr_acrnlog("acrnlog...level %d", LOG_ACRN); //level 2 + pr_fatal("fatal...level %d", LOG_FATAL); //level 1 + +If the built-in logging doesn't provide enough information, you can add +additional logging in functions you want to debug, using the functions +noted above. For example, add the following code into function +``shell_cmd_help`` in the source file +``acrn-hypervisor/hypervisor/debug/shell.c``: + +.. figure:: images/debug_image22.png + :align: center + + shell_cmd_help added information + +We set console log level to 5, and mem log level to 2 through the +command:: + + loglevel 5 2 + +Then we input "help" into the ACRN console, and find the log as follows. + +.. figure:: images/debug_image23.png + :align: center + + console log information + +Then we use the command, on the ACRN console:: + + sos_console + +to switch to the SOS console the use the commands:: + + systemctl enable acrnlog + reboot + +to enable the mem log and reboot the SOS. + +Next we set the console and mem log levels with:: + + loglevel 5 2 + +and run the command:: + + help + +Finally we get into the SOS and use the command:: + + cat /tmp/acrnlog/acrnlog_cur.0 + +on the console, and we'll see the following log: + +.. figure:: images/debug_image24.png + :align: center + + mem log information + + +ACRN Trace +********** + +ACRN trace is a tool running on the Service OS (SOS) to capture trace +data. We can use the existing trace information to analyze, and we can +add self-defined tracing to analyze code which we care about. + +Using Existing trace event id to analyze trace +============================================== + +As an example, we can use the existing vm_exit trace to analyze the +reason and times of each vm_exit after we have done some operations. + +1. Run the following SOS console command to collect + trace data:: + + # acrntrace -c + +2. Check current directory, and confirm the directory contains four + trace files:: + + # ls + 0 1 2 3 + +3. Use the command to get a summary of vmexit:: + + # acrnalyze.py -i /home/trace/acrntrace/20190219-001529/1 -o vmexit --vm_exit + + .. note:: The acrnalyze.py script is in the + ``acrn-hypervisor/tools/acrntrace/scripts`` folder. The location + of the trace files produced by ``acrntrace`` may be different in your system. + + .. figure:: images/debug_image28.png + :align: center + + vmexit summary information + +Using Self-defined trace event id to analyze trace +================================================== + +For some undefined trace event id, we can define it by ourselves as +shown in the following example: + +1. Add the following new event id into + ``acrn-hypervisor/hypervisor/include/debug/trace.h``: + + .. figure:: images/debug_image25.png + :align: center + + trace event id + +2. Add the following format to + ``acrn-hypervisor/tools/acrntrace/scripts/formats``: + + .. figure:: images/debug_image1.png + :align: center + + acrntrace formatted information + + .. note:: + + Formats: + 0x00000005: event id for trace test + + %(cpu)d: corresponding cpu index with 'decimal' format + + %(event)016x: corresponding event id with 'hex' format + + %(tsc)d: corresponding event time stamp with 'decimal' format + + %(1)08x: corresponding first 'Long' data in TRACE_2L + +3. Add trace into function ``emulate_io`` in + ``acrn-hypervisor/hypervisor/arch/x86/guest/io_emul.c`` which we want to + trace for the calling times of function ``emulate_io``: + + .. figure:: images/debug_image2.png + :align: center + + inserted trace information + +4. After we have inserted the trace code addition, we need to rebuild + the acrn-hypervisor in the ``acrn-hypervisor`` directory:: + + # make PLATFORM=uefi + + and replace the existing ``acrn.efi`` with the new one we just + built in the ``build/hypervisor/`` folder:: + + # mount /dev/sda1 /mnt && mkdir -p /mnt/EFI/acrn + # mv /mnt/EFI/acrn/acrn.efi /mnt/EFI/acrn/acrn.efi.old + # cp build/hypervisor/acrn.efi /mnt/EFI/acrn/ + +5. Now we can use the following command in the SOS console + to generate acrntrace data into the current directory:: + + acrntrace -c + + .. figure:: images/debug_image3.png + :align: center + + trace collection + +6. Run the console command:: + + # acrntrace_format.py \ + formats /home/trace/acrntrace/20190219-001529/1 | grep "trace test" + + .. note:: The acrnalyze.py script is in the + ``acrn-hypervisor/tools/acrntrace/scripts`` folder. The location + of the trace files produced by ``acrntrace`` may be different in your system. + + and we will get the following log: + + .. figure:: images/debug_image4.png + :align: center + + trace collection + + .. note:: + The trace data may generate on any of the available CPUs, so + you'll need to check which CPU number was used and specify that + CPU to analyze its trace. diff --git a/doc/tutorials/images/debug_image1.png b/doc/tutorials/images/debug_image1.png new file mode 100644 index 000000000..dfa944bcb Binary files /dev/null and b/doc/tutorials/images/debug_image1.png differ diff --git a/doc/tutorials/images/debug_image19.png b/doc/tutorials/images/debug_image19.png new file mode 100644 index 000000000..36c74f307 Binary files /dev/null and b/doc/tutorials/images/debug_image19.png differ diff --git a/doc/tutorials/images/debug_image2.png b/doc/tutorials/images/debug_image2.png new file mode 100644 index 000000000..c11cd9808 Binary files /dev/null and b/doc/tutorials/images/debug_image2.png differ diff --git a/doc/tutorials/images/debug_image20.png b/doc/tutorials/images/debug_image20.png new file mode 100644 index 000000000..cc61047cd Binary files /dev/null and b/doc/tutorials/images/debug_image20.png differ diff --git a/doc/tutorials/images/debug_image21.png b/doc/tutorials/images/debug_image21.png new file mode 100644 index 000000000..20be432db Binary files /dev/null and b/doc/tutorials/images/debug_image21.png differ diff --git a/doc/tutorials/images/debug_image22.png b/doc/tutorials/images/debug_image22.png new file mode 100644 index 000000000..38acb12ac Binary files /dev/null and b/doc/tutorials/images/debug_image22.png differ diff --git a/doc/tutorials/images/debug_image23.png b/doc/tutorials/images/debug_image23.png new file mode 100644 index 000000000..72755c247 Binary files /dev/null and b/doc/tutorials/images/debug_image23.png differ diff --git a/doc/tutorials/images/debug_image24.png b/doc/tutorials/images/debug_image24.png new file mode 100644 index 000000000..3c348c366 Binary files /dev/null and b/doc/tutorials/images/debug_image24.png differ diff --git a/doc/tutorials/images/debug_image25.png b/doc/tutorials/images/debug_image25.png new file mode 100644 index 000000000..d9fb9f37b Binary files /dev/null and b/doc/tutorials/images/debug_image25.png differ diff --git a/doc/tutorials/images/debug_image26.png b/doc/tutorials/images/debug_image26.png new file mode 100644 index 000000000..ed5682f07 Binary files /dev/null and b/doc/tutorials/images/debug_image26.png differ diff --git a/doc/tutorials/images/debug_image27.png b/doc/tutorials/images/debug_image27.png new file mode 100644 index 000000000..a07fdf2c5 Binary files /dev/null and b/doc/tutorials/images/debug_image27.png differ diff --git a/doc/tutorials/images/debug_image28.png b/doc/tutorials/images/debug_image28.png new file mode 100644 index 000000000..800994106 Binary files /dev/null and b/doc/tutorials/images/debug_image28.png differ diff --git a/doc/tutorials/images/debug_image3.png b/doc/tutorials/images/debug_image3.png new file mode 100644 index 000000000..fb88376e9 Binary files /dev/null and b/doc/tutorials/images/debug_image3.png differ diff --git a/doc/tutorials/images/debug_image4.png b/doc/tutorials/images/debug_image4.png new file mode 100644 index 000000000..696ceabd4 Binary files /dev/null and b/doc/tutorials/images/debug_image4.png differ diff --git a/doc/tutorials/images/debug_image5.png b/doc/tutorials/images/debug_image5.png new file mode 100644 index 000000000..800994106 Binary files /dev/null and b/doc/tutorials/images/debug_image5.png differ diff --git a/doc/user-guides/acrn-shell.rst b/doc/user-guides/acrn-shell.rst index d85c7d372..86c7bff70 100644 --- a/doc/user-guides/acrn-shell.rst +++ b/doc/user-guides/acrn-shell.rst @@ -23,7 +23,7 @@ The ACRN hypervisor shell supports the following commands: - Dump host memory, starting at a given address, and for a given length (in bytes) * - sos_console - - Switch to the SOS's console. Use [Ctrl+Spacebar] to return to the ACRN + - Switch to the SOS's console. Use :kbd:`Ctrl+Spacebar` to return to the ACRN shell console * - int - List interrupt information per CPU @@ -33,9 +33,9 @@ The ACRN hypervisor shell supports the following commands: - Show virtual IOAPIC (vIOAPIC) information for a specific VM * - dump_ioapic - Show native IOAPIC information - * - loglevel + * - loglevel - * If no parameters are given, the command will return the level of - logging for respectively the console, memory and npk + logging for the console, memory and npk * Give (up to) three parameters between ``0`` (none) and ``6`` (verbose) to set the loglevel for the console, memory, and npk (in that order). If less than three parameters are given, the @@ -50,3 +50,178 @@ The ACRN hypervisor shell supports the following commands: * - wrmsr [-p] - Write ``value`` (in hexadecimal) to the Model-Specific Register (MSR) at index ``msr_index`` (in hexadecimal) for CPU ID ``pcpu_id`` + +Command examples +**************** + +The following sections provide further details and examples for some of these commands. + +vm_list +======= + +``vm_list`` provides the name of each virtual machine and its corresponding ID and +state. + +.. figure:: images/shell_image8.png + :align: center + + vm_list information + +vcpu_list +========= + +``vcpu_list`` provides information about virtual CPUs (vCPU), including +the VM ID, PCPU ID, VCPU ID, VCPU ROLE (primary or secondary), and VCPU +STATE (init, paused, running, zombie or unknown). + +.. figure:: images/shell_image7.png + :align: center + + vcpu_list information + +vcpu_dumpreg +============ + +``vcpu_dumpreg vmid cpuid`` provides vCPU related information such as +registers values, etc. + +In the following example, we dump vCPU0 RIP register value and get into +the SOS to search for the currently running function, using these +commands:: + + cat /proc/kallsyms | grep RIP_value + +As you can see, vCPU0 is running in +function ``acpi_idle_do_entry``. + +.. figure:: images/shell_image10.png + :align: center + + vcpu_dumpreg information + +.. figure:: images/shell_image9.png + :align: center + + system map information + +dumpmem +======= + +``dumpmem mem_address`` provides the specified memory target data such as +the physical CPU (pCPU) number, etc. + +In this example, we know the pCPU active bitmap and physical CPU number +physical memory address through +``build/hypervisor/acrn.map``. (Note that the path for +``acrn.map`` depends on how we build the hypervisor.) + +Then we can dump the memory address of the pCPU active bitmap and CPU +number, we will know that pCPU active bitmap is 0x000000000000000f and +pCPU number is 0x0000000000000004. + +.. figure:: images/shell_image12.png + :align: center + + dumpmem information + +.. figure:: images/shell_image11.png + :align: center + + acrn map information + +sos_console +=========== + +The ``sos_console`` command switches the ACRN's console to become the SOS's console. +Use a :kbd:`Ctrl-Spacebar` to return to the ACRN shell console. + +vioapic +======= + +``vioapic `` shows the virtual IOAPIC information for a specific +VM. In the following figure, we show the virtual IOPIC information for +VM1: + +.. figure:: images/shell_image6.png + :align: center + + vioapic information + +dump_ioapic +=========== + +``dump_ioapic`` provides IOAPIC information and we can get IRQ number, +IRQ vector number, etc. + +.. figure:: images/shell_image14.png + :align: center + + dump_ioapic information + +pt +== + +``pt`` provides pass-through detailed information, such as the virtual +machine number, interrupt type, interrupt request, interrupt vector, +trigger mode, etc. + +.. figure:: images/shell_image13.png + :align: center + + pt information + +int +=== + +``int`` provides interrupt information on all CPUs and their corresponding +interrupt vector. + +.. figure:: images/shell_image17.png + :align: center + + int information + +cpuid +===== + +``cpuid [subleaf]`` provides the CPUID leaf [subleaf] in +hexadecimal. + +.. figure:: images/shell_image15.png + :align: center + + cpuid information + +rdmsr +===== + +We can read model specific register (MSR) to get register +values through ``rdmsr [-p] ``. + +In the following example, we can get IA32_APIC_BASE value of pCPU 0 through +the command:: + + rdmsr -p0 1b + +and see that 1B (Hexadecimal) is the IA32_APIC_BASE MSR address. + +.. figure:: images/shell_image16.png + :align: center + + IA32_APIC_BASE register information + +.. figure:: images/shell_image18.png + :align: center + + rdmsr information + +wrmsr +===== + +We can write model specific register (MSR) to set register +values through ``wrmsr [-p] ``. + +In the following example, we can set IA32_APIC_BASE value of pCPU 1 through +the command:: + + wrmsr -p1 1b 0xfee00c00 diff --git a/doc/user-guides/images/shell_image10.png b/doc/user-guides/images/shell_image10.png new file mode 100644 index 000000000..45d7e423b Binary files /dev/null and b/doc/user-guides/images/shell_image10.png differ diff --git a/doc/user-guides/images/shell_image11.png b/doc/user-guides/images/shell_image11.png new file mode 100644 index 000000000..0bacb3b93 Binary files /dev/null and b/doc/user-guides/images/shell_image11.png differ diff --git a/doc/user-guides/images/shell_image12.png b/doc/user-guides/images/shell_image12.png new file mode 100644 index 000000000..71777f989 Binary files /dev/null and b/doc/user-guides/images/shell_image12.png differ diff --git a/doc/user-guides/images/shell_image13.png b/doc/user-guides/images/shell_image13.png new file mode 100644 index 000000000..84c6655c1 Binary files /dev/null and b/doc/user-guides/images/shell_image13.png differ diff --git a/doc/user-guides/images/shell_image14.png b/doc/user-guides/images/shell_image14.png new file mode 100644 index 000000000..82023011f Binary files /dev/null and b/doc/user-guides/images/shell_image14.png differ diff --git a/doc/user-guides/images/shell_image15.png b/doc/user-guides/images/shell_image15.png new file mode 100644 index 000000000..dca02ad6e Binary files /dev/null and b/doc/user-guides/images/shell_image15.png differ diff --git a/doc/user-guides/images/shell_image16.png b/doc/user-guides/images/shell_image16.png new file mode 100644 index 000000000..5bf430060 Binary files /dev/null and b/doc/user-guides/images/shell_image16.png differ diff --git a/doc/user-guides/images/shell_image17.png b/doc/user-guides/images/shell_image17.png new file mode 100644 index 000000000..e3aee06ec Binary files /dev/null and b/doc/user-guides/images/shell_image17.png differ diff --git a/doc/user-guides/images/shell_image18.png b/doc/user-guides/images/shell_image18.png new file mode 100644 index 000000000..c22a5ec5d Binary files /dev/null and b/doc/user-guides/images/shell_image18.png differ diff --git a/doc/user-guides/images/shell_image6.png b/doc/user-guides/images/shell_image6.png new file mode 100644 index 000000000..e4f985be3 Binary files /dev/null and b/doc/user-guides/images/shell_image6.png differ diff --git a/doc/user-guides/images/shell_image7.png b/doc/user-guides/images/shell_image7.png new file mode 100644 index 000000000..66b068cc7 Binary files /dev/null and b/doc/user-guides/images/shell_image7.png differ diff --git a/doc/user-guides/images/shell_image8.png b/doc/user-guides/images/shell_image8.png new file mode 100644 index 000000000..f21cbe71f Binary files /dev/null and b/doc/user-guides/images/shell_image8.png differ diff --git a/doc/user-guides/images/shell_image9.png b/doc/user-guides/images/shell_image9.png new file mode 100644 index 000000000..b825e8ea5 Binary files /dev/null and b/doc/user-guides/images/shell_image9.png differ