240 lines
6.6 KiB
ReStructuredText
240 lines
6.6 KiB
ReStructuredText
.. _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 passthrough USB device.
|
|
|
|
First, we can get the USB controller BDF number (0:15.0) through the
|
|
following command in the Service VM 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 a console log and a 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 an 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 six (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
|
|
|
|
Once you have instrumented the code, you need to rebuild the hypervisor and
|
|
install it on your platform. Refer to :ref:`gsg`
|
|
for detailed instructions on how to do that.
|
|
|
|
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 (this is the command that we have
|
|
just instrumented with additional log information), and check the log as follows.
|
|
|
|
.. figure:: images/debug_image23.png
|
|
:align: center
|
|
|
|
console log information
|
|
|
|
Then we use the command, on the ACRN console::
|
|
|
|
vm_console
|
|
|
|
to switch to the Service VM console. Then we use the command::
|
|
|
|
cat /var/log/acrnlog/acrnlog_cur.0
|
|
|
|
and we will 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 VM to capture trace
|
|
data. We can use the existing trace information to analyze, and we can
|
|
add self-defined tracing to analyze code that 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 Service VM 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
|
|
``misc/debug_tools/acrn_trace/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
|
|
``misc/debug_tools/acrn_trace/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`` that 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 and install it on the platform. Refer to
|
|
:ref:`gsg` for detailed instructions on how to do that.
|
|
|
|
5. Now we can use the following command in the Service VM 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
|
|
``misc/debug_tools/acrn_trace/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.
|