Version 6 (modified by Chris Johns, on 03/29/15 at 10:14:58) (diff) |
---|
RTEMS Trace Buffering
Table of Contents
RTEMS Trace Buffering is a generator for the RTEMS Trace Linker. The trace buffering generator has the following features:
- Separate entry and exit records.
- Task details such as CPU, current priority, real priority, task state and interrupt state.
- Nano-second timestamp
- Interrupt safe buffer management.
- Function argument capture.
- Return value capture.
- Shell command support to report to the console or save a buffer.
The steps to trace are:
- Create a normal application. Include the RTEMS Shell in the application and enable the
rtrace
command. - Trace link the application using your RTEMS Trace Linker configuration.
- Executable the application, trigger the tracing and produce a report.
An example tracing exercise using the test suite's sample fileio
example will show you how to trace an application. We will use the shell to get a trace report on the console. We will trace the RTEMS Tasking and Semaphore API and the libc heap. The trace is triggered by the call to start a shell.
Configuration
The configuration INI file specification attached to this page. The first section is the standard tracer
section:
[tracer] name = File IO tracer ; ; The configuration ; options = fileio-options traces = fileio defines = fileio enables = fileio triggers = fileio functions = fileio-funcs, rtems-api, rtems-posix, libc-heap include = rtems.ini, rtld-base.ini, rtld-trace-buffer.ini, libc-heap.ini
The tracer name is File IO tracer
and the remainder of the configuration is held in separate sections. The first section is the options
section. It has:
[fileio-options] dump-on-error = true ; ; Tools ; prefix = /opt/rtems/4.11 rtems-path = /opt/rtems/kernel/4.11 rtems-bsp = sparc/sis ; ; Generator options. ; gen-enables = enable gen-triggers = enable
The first option is dump-on-error
. The option dumps a range of internal data from the trace linker on error. The see all the processing add -vvv
to the trace linkers command line. The next option is the tools prefix and is set /opt/rtems/4.11
. The tools prefix is not the install prefix and the RTEMS Trace linker automatically detects the installed prefix. The RTEMS BSP is installed to a different directory so an rtems-path
is provided as /opt/rtems/kernel/4.11
. The BSP is searched for under this path. The next option rtems-bsp
specifies the BSP as an arch/bsp
pair and in this example if the the sparc/sis
BSP. The trace linker searches for the installed configuration and extracts the compiler, linker and flags we need to build code for thsi BSP. The last 2 options control the enables and triggers. These result in the trace linker adding the enables and triggers to the wrapper C file.
The next section of the configuration file is specific to our fileio
trace:
[fileio] generator = trace-buffer-generator define = '#define RTLD_TRACE_BUFFER_SIZE (1UL * 1024 * 1024)' trace = rtems_shell_init trace = malloc, calloc, realloc, free traces = rtems-api-semaphore, rtems-posix-mutex enable = rtems_shell_init enable = malloc, calloc, realloc, free enables = rtems-api-semaphore, rtems-posix-mutex trigger = rtems_shell_init
This sections first specifies the generator
which is the trace-buffer-generator
. The generator is part of the trace linker and is installed with it. It's source is rtld-trace-buffer.ini and it details how to wrap each trace function. The second value in the fileio
configuration section is a define for RTLD_TRACE_BUFFER_SIZE
and it specifies to the trace buffering generator how much storage to statically allocate in bytes. The next lines specify the trace
, enables
and the trigger
. The traces
reference sections in the RTEMS and POSIX APIs and the C library heap calls and explicitly specified. The trace call rtems_shell_init
is specific to this trace configuration and we use it to trigger tracing.
The remaining sections specify the shell initialisation function we use to trigger the trace:
[fileio-funcs] headers = fileio-headers signatures = fileio-signatures [fileio-headers] header = '#include <rtems/shell.h>"' [fileio-signatures] rtems_shell_init = rtems_status_code, const char*, size_t, rtems_task_priority, const char*, bool, bool, rtems_shell_login_check_t
Save the configuration file to the top of your RTEMS SIS BSP build tree.
BSP Configuration
The BSP is configured with the following command line:
$ ../rtems.master/configure --target=sparc-rtems4.11 --prefix=/opt/rtems/kernel/4.11 \ --enable-networking --enable-tests --enable-rtemsbsp=sis --enable-cxx
Trace Linking
The fileio.exe
executable is linked using:
$ sparc-rtems4.11-gcc -Bsparc-rtems4.11/sis/lib/ -specs bsp_specs -qrtems \ -mcpu=cypress -O2 -g -ffunction-sections -fdata-sections -Wall \ -Wmissing-prototypes -Wimplicit-function-declaration -Wstrict-prototypes \ -Wnested-externs -Wl,--gc-sections -mcpu=cypress \ -o fileio.exe init.o
You can see this in the output of building RTEMS. The trace link command is:
$ rtems-tld -C fileio-trace.ini -W fileio-wrapper -- \ -Bsparc-rtems4.11/sis/lib/ -specs bsp_specs -qrtems \ -mcpu=cypress -O2 -g -ffunction-sections -fdata-sections -Wall \ -Wmissing-prototypes -Wimplicit-function-declaration -Wstrict-prototypes \ -Wnested-externs -Wl,--gc-sections -mcpu=cypress \ -o sparc-rtems4.11/c/sis/testsuites/samples/fileio/fileio.exe \ sparc-rtems4.11/c/sis/testsuites/samples/fileio/init.o
The BSP link command file follows the --
option escape sequence. The RTEMS linker options is the configuration and providing the -W fileio-wrapper
option the wrapper C is save so you can take a look.
Executing the Trace
Run the trace executable with the SPARC simulator:
$ sparc-rtems4.11-run sparc-rtems4.11/c/sis/testsuites/samples/fileio/fileio.exe
Make sure you hit enter quickly to enter the menu then enter s
and root
and pwd
:
*** BEGIN OF TEST FILE I/O *** Press any key to start file I/O sample (20s remaining) Press any key to start file I/O sample (19s remaining) Press any key to start file I/O sample (18s remaining) ========================= RTEMS FILE I/O Test Menu ========================= p -> part_table_initialize f -> mount all disks in fs_table l -> list file r -> read file w -> write file s -> start shell Enter your selection ==>s Creating /etc/passwd and group with three useable accounts root/pwd , test/pwd, rtems/NO PASSWORD, chroot/NO PASSWORD ========================= starting shell ========================= Welcome to rtems-4.10.99.0(SPARC/w/FPU/sis) COPYRIGHT (c) 1989-2008. On-Line Applications Research Corporation (OAR). Login into RTEMS /dev/foobar login: root Password: RTEMS Shell on /dev/foobar. Use 'help' to list commands. [/] #
Once at the shell prompt you can get the status of the trace buffering:
[/] # rtrace status RTEMS Trace Bufferring: status Running: yes Triggered: yes Level: 2% Traces: 27
The tracing has triggered and 2% of the buffer has been used. To report we need to stop tracing:
[/] # rtrace stop RTEMS Trace Bufferring: stop
Now we have stopped tracing we can report the contents of the trace buffer:
[/] # rtrace trace RTEMS Trace Bufferring: trace Trace buffer: 0x2092128 Words traced: 7939 Traces: 27 2:38:38.976752000 1329224064 0a010002 [ 1/ 1] > rtems_shell_init((const char*) 0x207eab0, (size_t) 00004000, (rtems_task_priority) 00000064, (const char*) 0x207eab8, (bool) 00, (bool) 01, (rtems_shell_login_check_t) 02023f04) 2:38:38.978233000 1481000 0a010002 [ 1/ 1] > malloc((size_t) 00000130) 2:38:38.978309000 76000 0a010002 [ 1/ 1] < malloc => (void*) 0x219f3a0 2:38:38.978386000 77000 0a010002 [ 1/ 1] > malloc((size_t) 00000006) 2:38:38.978460000 74000 0a010002 [ 1/ 1] < malloc => (void*) 0x219f4d8 2:38:38.978491000 31000 0a010002 [ 1/ 1] > malloc((size_t) 00000007) 2:38:38.978565000 74000 0a010002 [ 1/ 1] < malloc => (void*) 0x219f4e8 2:38:38.978615000 50000 0a010002 [ 1/ 1] > malloc((size_t) 000003fc) 2:38:38.978691000 76000 0a010002 [ 1/ 1] < malloc => (void*) 0x219f4f8 2:38:38.978754000 63000 0a010002 [ 1/ 1] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000) 2:38:38.978784000 30000 0a010002 [ 1/ 1] < rtems_semaphore_obtain => (rtems_status_code) 00000000 2:38:38.978860000 76000 0a010002 [ 1/ 1] > rtems_semaphore_release((rtems_id) 1a010001) 2:38:38.978893000 33000 0a010002 [ 1/ 1] < rtems_semaphore_release => (rtems_status_code) 00000000 2:38:38.978969000 76000 0a010002 [ 1/ 1] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000) 2:38:38.979000000 31000 0a010002 [ 1/ 1] < rtems_semaphore_obtain => (rtems_status_code) 00000000 2:38:38.979126000 126000 0a010002 [ 1/ 1] > rtems_semaphore_release((rtems_id) 1a010001) 2:38:38.979159000 33000 0a010002 [ 1/ 1] < rtems_semaphore_release => (rtems_status_code) 00000000 2:38:38.979193000 34000 0a010002 [ 1/ 1] > free((void*) 0x219f4f8) 2:38:38.979258000 65000 0a010002 [ 1/ 1] < free 2:38:38.979570000 312000 0a010003 [100/100] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000) 2:38:38.979601000 31000 0a010003 [100/100] < rtems_semaphore_obtain => (rtems_status_code) 00000000 2:38:38.979695000 94000 0a010003 [100/100] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000) 2:38:38.979725000 30000 0a010003 [100/100] < rtems_semaphore_obtain => (rtems_status_code) 00000000 2:38:38.979745000 20000 0a010003 [100/100] > rtems_semaphore_release((rtems_id) 1a010001) 2:38:38.979771000 26000 0a010003 [100/100] < rtems_semaphore_release => (rtems_status_code) 00000000 2:38:38.979819000 48000 0a010003 [100/100] > rtems_semaphore_release((rtems_id) 1a010001) 2:38:38.979851000 32000 0a010003 [100/100] < rtems_semaphore_release => (rtems_status_code) 00000000 2:38:38.979884000 33000 0a010003 [100/100] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000) 2:38:38.979914000 30000 0a010003 [100/100] < rtems_semaphore_obtain => (rtems_status_code) 00000000 2:38:38.979939000 25000 0a010003 [100/100] > rtems_semaphore_release((rtems_id) 1a010001) 2:38:38.979975000 36000 0a010003 [100/100] < rtems_semaphore_release => (rtems_status_code) 00000000 2:38:38.980077000 102000 0a010003 [100/100] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000) 2:38:38.980107000 30000 0a010003 [100/100] < rtems_semaphore_obtain => (rtems_status_code) 00000000 2:38:38.980230000 123000 0a010003 [100/100] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000) 2:38:38.980260000 30000 0a010003 [100/100] < rtems_semaphore_obtain => (rtems_status_code) 00000000 2:38:38.980280000 20000 0a010003 [100/100] > rtems_semaphore_release((rtems_id) 1a010001) 2:38:38.980306000 26000 0a010003 [100/100] < rtems_semaphore_release => (rtems_status_code) 00000000 2:38:38.980392000 86000 0a010003 [100/100] > rtems_semaphore_release((rtems_id) 1a010001) 2:38:38.980424000 32000 0a010003 [100/100] < rtems_semaphore_release => (rtems_status_code) 00000000 2:38:38.980462000 38000 0a010003 [100/100] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000)
The trace report has an entry and exit per line. The first value is the absolute time in nano-seconds and the second column is the trace sample difference also in nano-seconds. The third column is the executing thread RTEMS Id followed by the current and real priority for the executing thread. The >
is an entry record and <
is an exit record. Finally the trace function name and the arguments or return value. The arguments are annotated with the type of the function.
You can use the trace command with the following options. To report from record 0 for 200 records:
[/] # rtrace trace +200
To report from 300 to 350 use:
[/] # rtrace trace 300 350
To report from 500 and the next 200 records:
[/] # rtrace trace 500 +200
If you have the ability to extract data from your target with via a file system you can save the buffer to disk with:
[/] # rtrace save /net/nfs/fileio-trace.bin RTEMS Trace Bufferring: trace Trace File: /net/nfs/fileio-trace.bin Trace buffer: 0x2092128 Words traced: 7939 Traces: 27
Attachments (1)
-
fileio-trace.ini (1.5 KB) - added by Chris Johns on 03/29/15 at 10:19:56.
Trace buffering fileio configuration file.
Download all attachments as: .zip