doc: add the ACRN debug tutorial document

Add a new debugging tutorial and update the acrn_shell documentation
with additional details.

Signed-off-by: David B. Kinder <david.b.kinder@intel.com>

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.

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 <console_loglevel> <mem_loglevel> <npk_logevel>
+   * - loglevel <console_loglevel> <mem_loglevel> <npk_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<pcpu_id>] <msr_index> <value>
      - 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 <vm_id>`` 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 <leaf> [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<pcpu_id>] <msr_index>``.
+
+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<pcpu_id>] <msr_index> <value>``.
+
+In the following example, we can set IA32_APIC_BASE value of pCPU 1 through
+the command::
+
+   wrmsr -p1 1b 0xfee00c00