= RTEMS Trace Buffering =

[[TOC(Developer/Tracing/Trace_Buffering , depth=3)]]

RTEMS Trace Buffering is a generator for the [wiki:Developer/Tracing/Trace_Linker 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:

1. Create a normal application. Include the RTEMS Shell in the application and enable the `rtrace` command.
1. Trace link the application using your RTEMS Trace Linker configuration.
1. 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:

{{{
#!ini
[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:

{{{
#!ini
[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:

{{{
#!ini
[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 [https://git.rtems.org/rtems-tools/tree/linkers/rtld-trace-buffer.ini 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:

{{{
#!ini
[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
}}}