1 | .. SPDX-License-Identifier: CC-BY-SA-4.0 |
---|
2 | |
---|
3 | .. Copyright (C) 2019, 2020 embedded brains GmbH |
---|
4 | .. Copyright (C) 2019 Sebastian Huber |
---|
5 | |
---|
6 | .. _EventRecording: |
---|
7 | |
---|
8 | Event Recording |
---|
9 | =============== |
---|
10 | |
---|
11 | The `event recording` support focuses on the recording of high frequency |
---|
12 | events such as |
---|
13 | |
---|
14 | * thread switches, |
---|
15 | * thread queue enqueue and surrender, |
---|
16 | * interrupt entry and exit, |
---|
17 | * heap/workspace memory allocate/free, |
---|
18 | * UMA zone allocate/free, |
---|
19 | * Ethernet packet input/output, and |
---|
20 | * etc. |
---|
21 | |
---|
22 | There is a fixed set of 512 system reserved and 512 user defined events which |
---|
23 | are identified by an event number (:c:type:`rtems_record_event`). |
---|
24 | |
---|
25 | The event recording support allows post-mortem analysis in fatal error |
---|
26 | handlers, e.g. the last events are in the record buffers, the newest event |
---|
27 | overwrites the oldest event. It is possible to detect record buffer overflows |
---|
28 | for consumers that expect a continuous stream of events, e.g. to display the |
---|
29 | system state changes in real-time. |
---|
30 | |
---|
31 | The implementation supports high-end SMP machines (more than 1GHz processor |
---|
32 | frequency, more than four processors). It uses per-processor ring buffers to |
---|
33 | record the events. Synchronization is done without atomic read-modify-write |
---|
34 | operations. The CPU counter is used to get the time of events. It is combined |
---|
35 | with periodic uptime events to synchronize it with the monotonic system clock |
---|
36 | (:c:macro:`CLOCK_MONOTONIC`). |
---|
37 | |
---|
38 | To use the event recording three things come into play. Firstly, there is the |
---|
39 | generation of event records on the target system (the application running with |
---|
40 | RTEMS). Secondly, means to transfer the recorded events to the host computer |
---|
41 | for analysis. Thirdly, the analysis of the recorded events on the host |
---|
42 | computer. |
---|
43 | |
---|
44 | Target System: Configuration and Event Generation |
---|
45 | ------------------------------------------------- |
---|
46 | |
---|
47 | The application enables the event recording support via the configuration |
---|
48 | option :c:macro:`CONFIGURE_RECORD_PER_PROCESSOR_ITEMS`. The configuration |
---|
49 | option :c:macro:`CONFIGURE_RECORD_EXTENSIONS_ENABLED` enables the generation of |
---|
50 | thread create, start, restart, delete, switch, begin, exitted and terminate |
---|
51 | events. The configuration option |
---|
52 | :c:macro:`CONFIGURE_RECORD_INTERRUPTS_ENABLED` enables the generation of |
---|
53 | interrupt entry and exit events. Dumps of the event records in a fatal error |
---|
54 | handler can be enabled by the mutually exclusive |
---|
55 | :c:macro:`CONFIGURE_RECORD_FATAL_DUMP_BASE64` and |
---|
56 | :c:macro:`CONFIGURE_RECORD_FATAL_DUMP_BASE64_ZLIB` configuration options. |
---|
57 | |
---|
58 | Custom events can be recorded for example with the |
---|
59 | :c:func:`rtems_record_produce`, :c:func:`rtems_record_line`, |
---|
60 | :c:func:`rtems_record_caller`, etc. functions. |
---|
61 | |
---|
62 | .. code-block:: c |
---|
63 | |
---|
64 | #include <rtems/record.h> |
---|
65 | |
---|
66 | void f( void ) |
---|
67 | { |
---|
68 | rtems_record_produce( RTEMS_RECORD_USER( 0 ), 123 ); |
---|
69 | rtems_record_line(); |
---|
70 | rtems_record_caller(); |
---|
71 | } |
---|
72 | |
---|
73 | The variants of :c:func:`rtems_record_line` and :c:func:`rtems_record_caller` |
---|
74 | can be used to easily generate control flow events in the area of interest. |
---|
75 | The :file:`rtems-record-lttng` tool can use these events to associate source |
---|
76 | code files and line numbers to them using the ELF file of the application. |
---|
77 | |
---|
78 | The following code can be used together with the GCC option |
---|
79 | ``-finstrument-functions`` to generate function entry/exit events for |
---|
80 | instrumented functions: |
---|
81 | |
---|
82 | .. code-block:: c |
---|
83 | |
---|
84 | __attribute__(( __no_instrument_function__ )) |
---|
85 | void __cyg_profile_func_enter( void *this_fn, void *call_site ) |
---|
86 | { |
---|
87 | rtems_record_produce_2( |
---|
88 | RTEMS_RECORD_CALLER, |
---|
89 | (rtems_record_data) call_site, |
---|
90 | RTEMS_RECORD_FUNCTION_ENTRY, |
---|
91 | (rtems_record_data) this_fn |
---|
92 | ); |
---|
93 | } |
---|
94 | |
---|
95 | __attribute__(( __no_instrument_function__ )) |
---|
96 | void __cyg_profile_func_exit( void *this_fn, void *call_site ) |
---|
97 | { |
---|
98 | rtems_record_produce( |
---|
99 | RTEMS_RECORD_FUNCTION_EXIT, |
---|
100 | (rtems_record_data) this_fn |
---|
101 | ); |
---|
102 | } |
---|
103 | |
---|
104 | Transfer of Event Records to the Host Computer |
---|
105 | ---------------------------------------------- |
---|
106 | |
---|
107 | Recorded events can be sent to a host computer with a record server started by |
---|
108 | :c:func:`rtems_record_start_server` via a TCP connection. |
---|
109 | |
---|
110 | In the fatal error handler, the event records can be dumped via |
---|
111 | :c:func:`rtems_putc` in Base64 encoding. Optionally, the event records can be |
---|
112 | compressed via zlib before they are dumped in Base64 encoding. The compression |
---|
113 | needs roughly 512KiB of statically allocated memory. |
---|
114 | |
---|
115 | Analysis of Event Records on the Host Computer |
---|
116 | ---------------------------------------------- |
---|
117 | |
---|
118 | Use the command line tool :file:`rtems-record-lttng` to get recorded events |
---|
119 | from the record server running on the target system or from a file to convert |
---|
120 | the event records into CTF. It can be also used to read the dumps in Base64 |
---|
121 | encoding generated by the fatal error handler. The tool outputs the event |
---|
122 | records in the `Common Trace Format (CTF) <https://diamon.org/ctf/>`_ with some |
---|
123 | extra support for the |
---|
124 | `Linux Trace Toolkit Next Generation (LTTng) <https://lttng.org/>`_. This |
---|
125 | format can be analysed using `babeltrace <https://babeltrace.org/>`_ or |
---|
126 | `Eclipse Trace Compass <https://www.eclipse.org/tracecompass/>`_. |
---|
127 | The command line tool :file:`rtems-record-lttng` optionally uses |
---|
128 | `LLVM <https://www.llvm.org/>`_ to translate addresses to functions and source |
---|
129 | file locations. Make sure you have the LLVM development package installed when |
---|
130 | you build the RTEMS Tools to enable this feature. |
---|
131 | |
---|
132 | For example, to get the event records from the record server running on the |
---|
133 | target use: |
---|
134 | |
---|
135 | .. code-block:: none |
---|
136 | |
---|
137 | mkdir new-trace |
---|
138 | cd new-trace |
---|
139 | rtems-record-lttng -e application.exe -H 192.168.188.84 -l 100000 |
---|
140 | |
---|
141 | If everything is set up correctly, then the command produces a :file:`metadata` |
---|
142 | file and one stream file :file:`stream_0`, etc. for each processor which |
---|
143 | generated event records. |
---|
144 | |
---|
145 | .. code-block:: none |
---|
146 | |
---|
147 | $ ls -l |
---|
148 | total 120 |
---|
149 | -rw-r--r-- 1 user group 108339 Apr 11 15:28 metadata |
---|
150 | -rw-r--r-- 1 user group 8701 Apr 11 15:28 stream_0 |
---|
151 | |
---|
152 | This output in CTF can be used by :file:`babeltrace` and |
---|
153 | `Eclipse Trace Compass` for further analysis, for example: |
---|
154 | |
---|
155 | .. code-block:: none |
---|
156 | |
---|
157 | $ babeltrace . |
---|
158 | [07:28:15.909340000] (+?.?????????) RTEMS THREAD_STACK_CURRENT: { cpu_id = 0 }, { data = 0xB10 } |
---|
159 | [07:28:15.909340000] (+0.000000000) RTEMS sched_switch: { cpu_id = 0 }, { prev_comm = "UI1 ", prev_tid = 167837697, prev_prio = 0, prev_state = 0, next_comm = "IDLE/0", next_tid = 0, next_prio = 0 } |
---|
160 | [07:28:15.909519999] (+0.000179999) RTEMS THREAD_STACK_CURRENT: { cpu_id = 0 }, { data = 0xD68 } |
---|
161 | [07:28:15.909519999] (+0.000000000) RTEMS sched_switch: { cpu_id = 0 }, { prev_comm = "IDLE/0", prev_tid = 0, prev_prio = 0, prev_state = 1026, next_comm = "UI1 ", next_tid = 167837697, next_prio = 0 } |
---|
162 | [07:28:15.909579999] (+0.000060000) RTEMS THREAD_STACK_CURRENT: { cpu_id = 0 }, { data = 0xB10 } |
---|
163 | ... |
---|
164 | [07:28:15.999940999] (+0.000000000) RTEMS USER_4: { cpu_id = 0 }, { data = 0x4000192C } |
---|
165 | [07:28:15.999940999] (+0.000000000) RTEMS RETURN_0: { cpu_id = 0 }, { data = 0x0 } |
---|
166 | [07:28:15.999940999] (+0.000000000) RTEMS RETURN_1: { cpu_id = 0 }, { data = 0x1 } |
---|
167 | [07:28:15.999940999] (+0.000000000) RTEMS RETURN_2: { cpu_id = 0 }, { data = 0x2 } |
---|
168 | [07:28:15.999940999] (+0.000000000) RTEMS RETURN_3: { cpu_id = 0 }, { data = 0x3 } |
---|
169 | [07:28:15.999940999] (+0.000000000) RTEMS RETURN_4: { cpu_id = 0 }, { data = 0x4 } |
---|
170 | [07:28:15.999940999] (+0.000000000) RTEMS RETURN_5: { cpu_id = 0 }, { data = 0x5 } |
---|
171 | [07:28:15.999940999] (+0.000000000) RTEMS RETURN_6: { cpu_id = 0 }, { data = 0x6 } |
---|
172 | [07:28:15.999940999] (+0.000000000) RTEMS RETURN_7: { cpu_id = 0 }, { data = 0x7 } |
---|
173 | [07:28:15.999940999] (+0.000000000) RTEMS RETURN_8: { cpu_id = 0 }, { data = 0x8 } |
---|
174 | [07:28:15.999940999] (+0.000000000) RTEMS RETURN_9: { cpu_id = 0 }, { data = 0x9 } |
---|
175 | [07:28:15.999940999] (+0.000000000) RTEMS ISR_DISABLE: { cpu_id = 0 }, { code = "generate_events at init.c:154" } |
---|
176 | [07:28:15.999940999] (+0.000000000) RTEMS ISR_ENABLE: { cpu_id = 0 }, { code = "Init at init.c:181" } |
---|
177 | |
---|
178 | A dump from the fatal error handler looks like this: |
---|
179 | |
---|
180 | .. code-block:: none |
---|
181 | |
---|
182 | *** BEGIN OF RECORDS BASE64 ZLIB *** |
---|
183 | eNqtlE1vE1cUhsdJWgg0jU2GABILpxUVkaJcTxzH8QqThKpRKTIJlcoyeIKIhGCCEFnAAtAoKgXa |
---|
184 | phqx6gKk/AAXWHTpTMYZlg0rdpBdF7Dvsuec91jYFEo+HOnq0b33Oe/9mOtks9ns7Y1TK5ZlJah1 |
---|
185 | Uluw8HfJstqYA1b3WJG4a+p4aZpJbZzaXOlrw+4cte+p2Zcuz15kUstS3FhmZGiWOTs6nGM65Xye |
---|
186 | 6TqZEeZQNnOOWZh1y8KZfEHG3ewMszyE+XJ2hHNyg7lBrs9lhtIZpuMUHObR9LDwuxNnppgDufQ0 |
---|
187 | c2x6Ko35nLBcKOSEeXeYOXM+P8o8lR7oZ85dXJB1HDfN6+aGnbx4/YUR3t/+zgTfUaL3xMmJSe7v |
---|
188 | 0X7ameTzX9N7m6d7WyNetqyOI93HVgx7xKOWtTdJHOSc7rElo6TxrgvEQfHGbxkl/PFb8F/2GSX8 |
---|
189 | l33wX6WMEv6rlPjJ638YpfhE8ZM3Hhml+ETxUwdOG6X4RPFTB48bpfhE+E82jBL+kw34T9eNEv7T |
---|
190 | dfH3leaNUnyi+PtOzxil+ET4r1NGCf91Cv6bhFHCf5MQv+fHR0YpPlH8njtLRik+UXz7iGOU4hPF |
---|
191 | t7/qM0rxifCr60YJv7oOv/rX2aLVk1QetqvP5RFoP0N9/l2R95x/TG32SsTjo8Td4qE/0dDvFB/j |
---|
192 | Z94zvqch58L/zO8ltqt3cxPeZ8QO9X/fgt9F/ETrqtuo+5z4qdb/vYP6bv7fZIcVyrFtInLCCnLC |
---|
193 | CnLCCnLCCnLCCnLCCnLCSj0nSdytecUW5qX4/yyxt2gdGtD8b97p/2CHjy1dr3Hco3G8p/Bxm67f |
---|
194 | OH+jYZ+N4/fes//G+YcfPN/qMrzVZfb+JMJbXYa3ulz3cA/N/otN+Li35rp/tlCH+26q3394G/X4 |
---|
195 | Xs05EzvIwXdvzvNakId3FAXIjQLOfUhEbhQgNwqQGwXIjQLkRgFyowC5UYDcKKjn4n1GD9qRX2c9 |
---|
196 | /91+fb0Pjdf38bH5+j436+l5aovwaz78mg+/5sOv+fBrvvo+zr/tOh/3tuN6H/feshwf36/leT7e |
---|
197 | Q22xQ3LXrii9O5L/to/11jys9x/P+wnj3l3Zx0fnvXuyz0173n05z5Z972c5/7brvF/k3nZc7/0q |
---|
198 | 9x6fR07sIid2kRO7yIld5MQucmIXObGLnNjVHHdJvl/L89zf5D3E7rdF6+BV4knJf1b6Uuqelb7g |
---|
199 | df4FFmd4DQ== |
---|
200 | *** END OF RECORDS BASE64 ZLIB *** |
---|
201 | |
---|
202 | Copy everything between the ``*** BEGIN OF RECORDS BASE64 ZLIB ***`` and the |
---|
203 | ``*** END OF RECORDS BASE64 ZLIB ***`` markers into a file, for example |
---|
204 | :file:`dump.txt`. Use this command to convert the event records into the CTF |
---|
205 | for further analysis: |
---|
206 | |
---|
207 | .. code-block:: none |
---|
208 | |
---|
209 | rtems-record-lttng -e application.exe -b -z dump.txt |
---|