1.. _acrn-debug:
2
3ACRN Debugging Tools
4####################
5
6This document describes how to use ACRN tools to collect log
7and trace data for debugging.
8
9ACRN Console Command
10********************
11
12The ACRN console provides shell commands for a user to check system states
13and environment settings. See the :ref:`acrnshell` documentation for a
14full list of commands, or see a summary of available commands by using
15the ``help`` command within the ACRN shell.
16
17
18An Example
19**********
20
21As an example, we'll show how to obtain the interrupts of a passthrough USB device.
22
23First, we can get the USB controller BDF number (0:15.0) through the
24following command in the Service VM console::
25
26   lspci | grep "USB controller"
27
28
29.. figure:: images/debug_image19.png
30   :align: center
31
32   USB controller BDF information
33
34Second, we use the ``pt`` command in the ACRN console, and use this BDF number
35to find the interrupt vector (VEC) "0x31".
36
37.. figure:: images/debug_image20.png
38   :align: center
39
40   USB controller interrupt information
41
42Finally we use the ``int`` command in the ACRN console, and use this
43interrupt vector to find the interrupt number (909) on CPU3.
44
45.. figure:: images/debug_image21.png
46   :align: center
47
48   USB controller interrupt number information
49
50ACRN Log
51********
52
53ACRN log provides a console log and a mem log for a user to analyze.
54We can use console log to debug directly, while mem log is a userland tool
55used to capture an ACRN hypervisor log.
56
57Turn on the Logging Info
58========================
59
60ACRN enables a console log by default.
61
62To enable and start the mem log::
63
64   $ systemctl enable acrnlog
65   $ systemctl start acrnlog
66
67
68Set and Grab Log
69================
70
71We have six (1-6) log levels for console log and mem log. The following
72functions print different levels of console log and mem log::
73
74      pr_dbg("debug...level %d", LOG_DEBUG);       //level 6
75      pr_info("info...level %d", LOG_INFO);        //level 5
76      pr_warn("warn...level %d", LOG_WARNING);     //level 4
77      pr_err("err...level %d", LOG_ERROR);         //level 3
78      pr_acrnlog("acrnlog...level %d", LOG_ACRN);  //level 2
79      pr_fatal("fatal...level %d", LOG_FATAL);     //level 1
80
81If the built-in logging doesn't provide enough information, you can add
82additional logging in functions you want to debug, using the functions
83noted above.  For example, add the following code into function
84``shell_cmd_help`` in the source file
85``acrn-hypervisor/hypervisor/debug/shell.c``:
86
87.. figure:: images/debug_image22.png
88   :align: center
89
90   shell_cmd_help added information
91
92Once you have instrumented the code, you need to rebuild the hypervisor and
93install it on your platform. Refer to :ref:`gsg`
94for detailed instructions on how to do that.
95
96We set console log level to 5, and mem log level to 2 through the
97command::
98
99   loglevel 5 2
100
101Then we input ``help`` into the ACRN console (this is the command that we have
102just instrumented with additional log information), and check the log as follows.
103
104.. figure:: images/debug_image23.png
105   :align: center
106
107   console log information
108
109Then we use the command, on the ACRN console::
110
111   vm_console
112
113to switch to the Service VM console. Then we use the command::
114
115   cat /var/log/acrnlog/acrnlog_cur.0
116
117and we will see the following log:
118
119.. figure:: images/debug_image24.png
120   :align: center
121
122   mem log information
123
124
125ACRN Trace
126**********
127
128ACRN trace is a tool running on the Service VM to capture trace
129data. We can use the existing trace information to analyze, and we can
130add self-defined tracing to analyze code that we care about.
131
132Using Existing Trace Event ID to Analyze Trace
133==============================================
134
135As an example, we can use the existing vm_exit trace to analyze the
136reason and times of each vm_exit after we have done some operations.
137
1381. Run the following Service VM console command to collect
139   trace data::
140
141      # acrntrace -c
142
1432. Check current directory, and confirm the directory contains four
144   trace files::
145
146      # ls
147      0 1 2 3
148
1493. Use the command to get a summary of vmexit::
150
151      # acrnalyze.py -i /home/trace/acrntrace/20190219-001529/1 -o vmexit --vm_exit
152
153   .. note:: The acrnalyze.py script is in the
154      ``misc/debug_tools/acrn_trace/scripts`` folder.  The location
155      of the trace files produced by ``acrntrace`` may be different in your system.
156
157   .. figure:: images/debug_image28.png
158      :align: center
159
160      vmexit summary information
161
1624. Use the command to get a summary of cpu usage in cpu-sharing case::
163
164      # acrnalyze.py -i /home/trace/acrntrace/20231122-054116/0 -o cpu_usage --cpu_usage
165
166   .. figure:: images/debug_image29.png
167      :align: center
168
169      cpu usage summary information
170
171
172Using Self-Defined Trace Event ID to Analyze Trace
173==================================================
174
175For some undefined trace event ID, we can define it by ourselves as
176shown in the following example:
177
1781. Add the following new event ID into
179   ``acrn-hypervisor/hypervisor/include/debug/trace.h``:
180
181   .. figure:: images/debug_image25.png
182      :align: center
183
184      trace event ID
185
1862. Add the following format to
187   ``misc/debug_tools/acrn_trace/scripts/formats``:
188
189   .. figure:: images/debug_image1.png
190      :align: center
191
192      acrntrace formatted information
193
194   .. note::
195
196      Formats:
197        ``0x00000005``: event ID for trace test
198
199        ``%(cpu)d``: corresponding CPU index with decimal format
200
201        ``%(event)016x``: corresponding event id with hex format
202
203        ``%(tsc)d``: corresponding event time stamp with decimal format
204
205        ``%(1)08x``: corresponding first Long data in TRACE_2L
206
2073. Add trace into function ``emulate_io`` in
208   ``acrn-hypervisor/hypervisor/arch/x86/guest/io_emul.c`` that we want to
209   trace for the calling times of function ``emulate_io``:
210
211   .. figure:: images/debug_image2.png
212      :align: center
213
214      inserted trace information
215
2164. After we have inserted the trace code addition, we need to rebuild
217   the ACRN hypervisor and install it on the platform. Refer to
218   :ref:`gsg` for detailed instructions on how to do that.
219
2205. Now we can use the following command in the Service VM console
221   to generate acrntrace data into the current directory::
222
223      acrntrace -c
224
225   .. figure:: images/debug_image3.png
226      :align: center
227
228      trace collection
229
2306. Run the console command::
231
232      # acrntrace_format.py \
233        formats /home/trace/acrntrace/20190219-001529/1 | grep "trace test"
234
235   .. note:: The acrnalyze.py script is in the
236      ``misc/debug_tools/acrn_trace/scripts`` folder.  The location
237      of the trace files produced by ``acrntrace`` may be different in your system.
238
239   and we will get the following log:
240
241   .. figure:: images/debug_image4.png
242      :align: center
243
244      trace collection
245
246   .. note::
247      The trace data may generate on any of the available CPUs, so
248      you'll need to check which CPU number was used and specify that
249      CPU to analyze its trace.
250