Changes between Version 3 and Version 4 of Developer/Tracing/Trace_Buffering


Ignore:
Timestamp:
Mar 29, 2015, 10:08:58 AM (5 years ago)
Author:
Chris Johns
Comment:

Add the fileio example.

Legend:

Unmodified
Added
Removed
Modified
  • Developer/Tracing/Trace_Buffering

    v3 v4  
    1111 * Function argument capture.
    1212 * Return value capture.
    13 
     13 * Shell command support to report to the console or save a buffer.
     14
     15The steps to trace are:
     16
     171. Create a normal application. Include the RTEMS Shell in the application and enable the `rtrace` command.
     181. Trace link the application using your RTEMS Trace Linker configuration.
     191. Executable the application, trigger the tracing and produce a report.
     20
     21An 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.
     22
     23== Configuration ==
     24
     25The configuration INI file specification attached to this page. The first section is the standard `tracer` section:
     26
     27{{{
     28#!ini
     29[tracer]
     30name = File IO tracer
     31;
     32; The configuration
     33;
     34options = fileio-options
     35traces = fileio
     36defines = fileio
     37enables = fileio
     38triggers = fileio
     39functions = fileio-funcs, rtems-api, rtems-posix, libc-heap
     40include = rtems.ini, rtld-base.ini, rtld-trace-buffer.ini, libc-heap.ini
     41}}}
     42
     43The ''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:
     44
     45{{{
     46#!ini
     47[fileio-options]
     48dump-on-error = true
     49;
     50; Tools
     51;
     52prefix = /opt/rtems/4.11
     53rtems-path = /opt/rtems/kernel/4.11
     54rtems-bsp = sparc/sis
     55;
     56; Generator options.
     57;
     58gen-enables = enable
     59gen-triggers = enable
     60}}}
     61
     62The 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.
     63
     64The next section of the configuration file is specific to our `fileio` trace:
     65
     66{{{
     67#!ini
     68[fileio]
     69generator = trace-buffer-generator
     70define = '#define RTLD_TRACE_BUFFER_SIZE (1UL * 1024 * 1024)'
     71trace = rtems_shell_init
     72trace = malloc, calloc, realloc, free
     73traces = rtems-api-semaphore, rtems-posix-mutex
     74enable = rtems_shell_init
     75enable = malloc, calloc, realloc, free
     76enables = rtems-api-semaphore, rtems-posix-mutex
     77trigger = rtems_shell_init
     78}}}
     79
     80This 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.
     81
     82The remaining sections specify the shell initialisation function we use to trigger the trace:
     83
     84{{{
     85#!ini
     86[fileio-funcs]
     87headers = fileio-headers
     88signatures = fileio-signatures
     89
     90[fileio-headers]
     91header = '#include <rtems/shell.h>"'
     92
     93[fileio-signatures]
     94rtems_shell_init = rtems_status_code, const char*, size_t, rtems_task_priority, const char*, bool, bool, rtems_shell_login_check_t
     95}}}
     96
     97
     98Save the configuration file to the top of your RTEMS SIS BSP build tree.
     99
     100=== BSP Configuration ===
     101
     102The BSP is configured with the following command line:
     103
     104{{{
     105$ ../rtems.master/configure --target=sparc-rtems4.11 --prefix=/opt/rtems/kernel/4.11 \
     106                --enable-networking --enable-tests --enable-rtemsbsp=sis --enable-cxx
     107}}}
     108
     109=== Trace Linking ===
     110
     111The `fileio.exe` executable is linked using:
     112
     113{{{
     114sparc-rtems4.11-gcc -Bsparc-rtems4.11/sis/lib/ -specs bsp_specs -qrtems \
     115          -mcpu=cypress -O2 -g -ffunction-sections -fdata-sections -Wall \
     116          -Wmissing-prototypes -Wimplicit-function-declaration -Wstrict-prototypes \
     117          -Wnested-externs -Wl,--gc-sections -mcpu=cypress \
     118          -o fileio.exe init.o
     119}}}
     120
     121You can see this in the output of building RTEMS. The trace link command is:
     122
     123{{{
     124rtems-tld -C fileio-trace.ini -W fileio-wrapper -- \
     125          -Bsparc-rtems4.11/sis/lib/ -specs bsp_specs -qrtems \
     126          -mcpu=cypress -O2 -g -ffunction-sections -fdata-sections -Wall \
     127          -Wmissing-prototypes -Wimplicit-function-declaration -Wstrict-prototypes \
     128          -Wnested-externs -Wl,--gc-sections -mcpu=cypress \
     129          -o sparc-rtems4.11/c/sis/testsuites/samples/fileio/fileio.exe \
     130          sparc-rtems4.11/c/sis/testsuites/samples/fileio/init.o
     131}}}
     132
     133The 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.
     134
     135=== Executing the Trace ===
     136
     137Run the trace executable with the SPARC simulator:
     138
     139{{{
     140$ sparc-rtems4.11-run sparc-rtems4.11/c/sis/testsuites/samples/fileio/fileio.exe
     141}}}
     142
     143Make sure you hit enter quickly to enter the menu then enter `s` and `root` and `pwd`:
     144
     145{{{
     146*** BEGIN OF TEST FILE I/O ***
     147Press any key to start file I/O sample (20s remaining)
     148Press any key to start file I/O sample (19s remaining)
     149Press any key to start file I/O sample (18s remaining)
     150 =========================
     151 RTEMS FILE I/O Test Menu
     152 =========================
     153   p -> part_table_initialize
     154   f -> mount all disks in fs_table
     155   l -> list  file
     156   r -> read  file
     157   w -> write file
     158   s -> start shell
     159   Enter your selection ==>s
     160Creating /etc/passwd and group with three useable accounts
     161root/pwd , test/pwd, rtems/NO PASSWORD, chroot/NO PASSWORD
     162 =========================
     163 starting shell
     164 =========================
     165
     166Welcome to rtems-4.10.99.0(SPARC/w/FPU/sis)
     167COPYRIGHT (c) 1989-2008.
     168On-Line Applications Research Corporation (OAR).
     169
     170Login into RTEMS
     171/dev/foobar login: root
     172Password:
     173
     174RTEMS Shell on /dev/foobar. Use 'help' to list commands.
     175[/] #
     176}}}
     177
     178Once at the shell prompt you can get the status of the trace buffering:
     179
     180{{{
     181[/] # rtrace status
     182RTEMS Trace Bufferring: status
     183    Running:   yes
     184  Triggered:   yes
     185      Level:    2%
     186     Traces:   27
     187}}}
     188
     189The tracing has triggered and 2% of the buffer has been used. To report we need to stop tracing:
     190
     191{{{
     192[/] # rtrace stop
     193RTEMS Trace Bufferring: stop
     194}}}
     195
     196Now we have stopped tracing we can report the contents of the trace buffer:
     197
     198{{{
     199[/] # rtrace trace
     200RTEMS Trace Bufferring: trace
     201 Trace buffer: 0x2092128
     202 Words traced: 7939
     203       Traces: 27
     204    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)
     205    2:38:38.978233000    1481000  0a010002 [  1/  1] > malloc((size_t) 00000130)
     206    2:38:38.978309000      76000  0a010002 [  1/  1] < malloc => (void*) 0x219f3a0
     207    2:38:38.978386000      77000  0a010002 [  1/  1] > malloc((size_t) 00000006)
     208    2:38:38.978460000      74000  0a010002 [  1/  1] < malloc => (void*) 0x219f4d8
     209    2:38:38.978491000      31000  0a010002 [  1/  1] > malloc((size_t) 00000007)
     210    2:38:38.978565000      74000  0a010002 [  1/  1] < malloc => (void*) 0x219f4e8
     211    2:38:38.978615000      50000  0a010002 [  1/  1] > malloc((size_t) 000003fc)
     212    2:38:38.978691000      76000  0a010002 [  1/  1] < malloc => (void*) 0x219f4f8
     213    2:38:38.978754000      63000  0a010002 [  1/  1] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000)
     214    2:38:38.978784000      30000  0a010002 [  1/  1] < rtems_semaphore_obtain => (rtems_status_code) 00000000
     215    2:38:38.978860000      76000  0a010002 [  1/  1] > rtems_semaphore_release((rtems_id) 1a010001)
     216    2:38:38.978893000      33000  0a010002 [  1/  1] < rtems_semaphore_release => (rtems_status_code) 00000000
     217    2:38:38.978969000      76000  0a010002 [  1/  1] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000)
     218    2:38:38.979000000      31000  0a010002 [  1/  1] < rtems_semaphore_obtain => (rtems_status_code) 00000000
     219    2:38:38.979126000     126000  0a010002 [  1/  1] > rtems_semaphore_release((rtems_id) 1a010001)
     220    2:38:38.979159000      33000  0a010002 [  1/  1] < rtems_semaphore_release => (rtems_status_code) 00000000
     221    2:38:38.979193000      34000  0a010002 [  1/  1] > free((void*) 0x219f4f8)
     222    2:38:38.979258000      65000  0a010002 [  1/  1] < free
     223    2:38:38.979570000     312000  0a010003 [100/100] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000)
     224    2:38:38.979601000      31000  0a010003 [100/100] < rtems_semaphore_obtain => (rtems_status_code) 00000000
     225    2:38:38.979695000      94000  0a010003 [100/100] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000)
     226    2:38:38.979725000      30000  0a010003 [100/100] < rtems_semaphore_obtain => (rtems_status_code) 00000000
     227    2:38:38.979745000      20000  0a010003 [100/100] > rtems_semaphore_release((rtems_id) 1a010001)
     228    2:38:38.979771000      26000  0a010003 [100/100] < rtems_semaphore_release => (rtems_status_code) 00000000
     229    2:38:38.979819000      48000  0a010003 [100/100] > rtems_semaphore_release((rtems_id) 1a010001)
     230    2:38:38.979851000      32000  0a010003 [100/100] < rtems_semaphore_release => (rtems_status_code) 00000000
     231    2:38:38.979884000      33000  0a010003 [100/100] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000)
     232    2:38:38.979914000      30000  0a010003 [100/100] < rtems_semaphore_obtain => (rtems_status_code) 00000000
     233    2:38:38.979939000      25000  0a010003 [100/100] > rtems_semaphore_release((rtems_id) 1a010001)
     234    2:38:38.979975000      36000  0a010003 [100/100] < rtems_semaphore_release => (rtems_status_code) 00000000
     235    2:38:38.980077000     102000  0a010003 [100/100] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000)
     236    2:38:38.980107000      30000  0a010003 [100/100] < rtems_semaphore_obtain => (rtems_status_code) 00000000
     237    2:38:38.980230000     123000  0a010003 [100/100] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000)
     238    2:38:38.980260000      30000  0a010003 [100/100] < rtems_semaphore_obtain => (rtems_status_code) 00000000
     239    2:38:38.980280000      20000  0a010003 [100/100] > rtems_semaphore_release((rtems_id) 1a010001)
     240    2:38:38.980306000      26000  0a010003 [100/100] < rtems_semaphore_release => (rtems_status_code) 00000000
     241    2:38:38.980392000      86000  0a010003 [100/100] > rtems_semaphore_release((rtems_id) 1a010001)
     242    2:38:38.980424000      32000  0a010003 [100/100] < rtems_semaphore_release => (rtems_status_code) 00000000
     243    2:38:38.980462000      38000  0a010003 [100/100] > rtems_semaphore_obtain((rtems_id) 1a010001, (rtems_option) 00000000, (rtems_interval) 00000000)
     244}}}
     245
     246The 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.
     247
     248If you have the ability to extract data from your target with via a file system you can save the buffer to disk with:
     249
     250{{{
     251[/] # rtrace save /net/nfs/fileio-trace.bin
     252RTEMS Trace Bufferring: trace
     253   Trace File: /net/nfs/fileio-trace.bin
     254 Trace buffer: 0x2092128
     255 Words traced: 7939
     256       Traces: 27
     257}}}
     258