Instrumentation

Instrumentation is a valuable performance analysis and debugging mechanism that can be useful when porting eCos, developing drivers and other subsystems, and during eCos application development. It can provide insights into the real-time behaviour of the system - encompassing the ordering, frequency and timing of selected system and application events, whilst also providing associated event specific context information.

Instrumentation works by selecting the set of events of interest during configuration, followed by the runtime capture and logging of these events into either a in-memory buffer for later extraction, or immediately via an external hardware debug interface. The resulting binary instrumentation log is then processed by a host-based tool to either convert into a human-readable textual format, or into formats supported by various graphical trace viewers.

Examples of the use of instrumentation include analysis of the timing and ordering of control flow between different threads, the duration of interrupt service routines, or within a specific device driver to identify transitions between various states of its state machine.

The run-time instrumentation support is provided by the the CYGPKG_KERNEL package, but is not limited to supporting the Kernel. Instrumentation event points can be added to packages or user applications as required.

The Kernel header file cyg/kernel/instrmnt.h provides the implementation definitions, and should normally be included by any code wishing to use instrumentation.

The fundamental identity of instrumentation points is the event “type” value, which comprises an 8-bit class value and a 5-bit code value (range 1..31). The value 0 is reserved in both the class and code space. Some further type bits define how many argument values are associated to an event type. The class space is further sub-divided into space for the Kernel instrumentation (previously the only classes defined and supported), space for well-known (standard eCos) packages and space from CYG_INSTRUMENT_CLASS_APPLICATION_BASE set aside for per-application tracing.

Note: It is the responsibility of the developer to manage the use of the instrumentation application space within their own code. The currently defined application class/code space allows for 1953 unique instrumentation identifiers.

CYGDBG_KERNEL_INSTRUMENT_FLAGS

The configuration option CYGDBG_KERNEL_INSTRUMENT_FLAGS controls whether run-time support for enabling/disabling individual event class/code output is provided. If the feature is disabled then ALL instrumentation macro calls will result in instrumentation records being generated. The sub-option CYGDBG_KERNEL_INSTRUMENT_FLAGS_ALL controls whether the run-time flag support is only provided for the original Kernel instrumentation classes (disabled), or for the complete event class range (enabled). Normally this option would be disabled since supporting run-time flags for the complete class range has a large memory footprint, and if disabled non-Kernel packages can implement their own run-time control if needed.

CYGPKG_KERNEL_INSTRUMENT_BUFFER

The configuration option CYGPKG_KERNEL_INSTRUMENT_BUFFER controls whether the default Kernel memory buffer based instrumentation is used, or an alternative instrumentation system is being provided by other packages or the application run-time. Certain architectures, or specific target platforms, may provide alternative implementations that provide for direct low-overhead output of instrumentation. For example, some Cortex-M designs may include support for outputting instrumentation immediately via the on-chip ITM stimulus port interfaces to a suitable host SWD tool, allowing for continuous streams of instrumentation events to be captured.

CYGPKG_KERNEL_INSTRUMENT_TIMESTAMPS

The configuration option CYGPKG_KERNEL_INSTRUMENT_TIMESTAMPS, along with the sub-configuration items it enables, control whether the run-time includes timestamps in event records. For some applications the delta between events is not important, only the order that events happen in. By disabling timestamps then the memory footprint of individual instrumentation records can be reduced. Alternative direct output implementations might provide their own implicit timestamp capability - in which case the built-in timestamp feature would not be required.

The default implementation makes use of local memory instrument buffers to hold a number of event records. Whilst being simple, the use of memory buffers for recording instrumentation events does impose a limitation on the number of events that can be held at any single moment, and the amount of memory available for holding instrumentation records may be severely limited on deeply embedded systems with small amounts of available RAM.

Kernel Instrumentation

The CYGPKG_KERNEL package also provides instrumentation covering the major components of the eCos Kernel. Examples of Kernel events that can be monitored are:

  • scheduler events

  • thread operations

  • interrupts

  • mutex operations

  • binary semaphore operations

  • counting semaphore operations

  • clock ticks and interrupts

Examples of fine-grained scheduler event types are:

  • scheduler lock

  • scheduler unlock

  • rescheduling

  • time slicing

Embedded (non-loaded) information

To allow for generic post-processing tools (that are not tied to any specific eCos configuration, architecture or platform) the configuration option CYGIMP_KERNEL_INSTRUMENT_IMAGE_SECTIONS can be enabled to provide instrumentation description information that is embedded in the ELF application image.

Note: Even when the binary code and initialised data from an application image are written to ROM, it is important to keep a copy of the original application image for future reference. This is so that any instrumentation data that is generated by executing the application code can be interpreted correctly. Keeping a copy of the application image used for releases is always a good idea anyway, since the image file contains symbolic and debugging information that may also be useful at a later date if problems need to be investigated.

The instrumentation description information is encoded in specifically named sections that are NOT referenced from the actual application code or data, and so do not form part of the loaded data or ROM image. The sections are purely present to provide details of the actual instrumentation generated by the application using the specific eCos configuration the application was built against.

For example, an embedded section describing the format of the actual event records may be provided. Such a section will contain information about the field sizes and types so that the external tool can determine what fields were actually used, in which order, with what alignment or endianness.

Similarly the mapping between the internal event record class and code values to the fixed ASCII tags used to identify particular events is provided in an embedded section. This ensures that regardless of the actual binary value used to encode the event in the event record, the external tool used to analyse instrumentation event records can correctly identify (for example) the SCHED:LOCKED event.

The header file cyg/kernel/instrument_data.h defines the layout of these embedded structures. Even though the header is provided within the eCos Kernel source tree, it is common amongst all eCos releases and when updated will ensure backwards compatibility so that any external tool built against the header will still be valid and will NOT need to be re-built just because a newer eCos release is being used.

The use of such structures embedded in the executable image ensures that the description of instrumentation records produced is held with the actual application image; and there does not need to be magic collusion between the external tools and any specific eCos configuration used for interpreting the generated data. The information embedded is designed to be future-proof to allow “old” tools to extract the information they can process from newer binaries that may actually provide more embedded data.

instdump tool

The Kernel package includes the source code for the instdump command line tool. The instdump tool can be used to convert binary instrumentation data created by an application into human readable form, or into formats required by specific trace viewers. It can also be used to examine the information embedded in application images. The source for the instdump tool can be found in the BASE_DIR/packages/kernel/<version>/host/instr directory. The tool currently requires libelf for parsing the application image to extract the embedded information, and libiberty for C++ symbol de-mangling. It can be built as follows on a suitable Linux host:

$ cd $ECOS_REPOSITORY/kernel/$ECOS_VERSION/host/instr
$ gcc -o instdump instdump.c -lelf -liberty

A Windows binary can be cross-built on a Linux host, assuming a suitable mingw environment is available. The following example build sequence assumes that the relevant libiberty and libelf sources have been downloaded and un-packed into the relevant /tmp/mingw directories.

An example mingw libelf cross-build:

$ mkdir -p /tmp/mingw/build_libelf
$ cd /tmp/mingw/build_libelf
$ AR="i686-pc-mingw32-ar" CC="i686-pc-mingw32-gcc" ../libelf-0.8.13/configure --disable-shared --disable-nls --enable-compat \
  --target=i686-pc-mingw32
$ make
$ i686-pc-mingw32-ranlib lib/libelf.a

An example mingw libiberty cross-build:

$ mkdir -p /tmp/mingw/build_libiberty
$ cd /tmp/mingw/build_libiberty
$ CC="i686-pc-mingw32-gcc" ../libiberty/configure --host=i686-pc-mingw32 --disable-shared
$ make

Once the static libraries are available the actual instdump.exe can be compiled and linked by executing the following commands:

$ cd $ECOS_REPOSITORY/kernel/$ECOS_VERSION/host/instr
$ i686-pc-mingw32-gcc -I/tmp/mingw/libelf-0.8.13/lib/ -I/tmp/mingw/build_libelf/lib/ -o instdump.exe instdump.c \
  /tmp/mingw/build_libelf/lib/libelf.a /tmp/mingw/build_libiberty/libiberty/libiberty.a

In the future extended versions of instdump or additional tools may be provided to make use of the embedded (INFO) sections for specific uses. For example, to convert the eCos specific binary instrumentation into other trace/instrumentation formats such as the Common Trace Format (CTF). The source code of instdump provides a useful example of how to extract and process the embedded sections and eCos trace information.

The tool provides a simple overview of its options by using the --help option.

The instdump tool can then be used to display embedded (INFO) data held within an ELF application image for verification of the embedded data. e.g.

$ instdump elfimage

It can also interpret raw binary instrumentation dump as produced by executing the elfimage application with whatever instrumentation capture support is suitable. e.g.

$ instdump --record-format instdata.bin elfimage

The --instrumentation option allows a binary file of contiguous records to be passed. This would normally be used when examining memory buffer captures. The --record-format option allows the Cortex-M specific ITM record format to be parsed as captured by suitable SWD hardware debug interfaces (e.g. OpenOCD ST-LINKv2, PEEDI).

Further, when instrumentation data is being parsed then the --chrome-json option can be used to have instdump generate JSON trace-viewer compatible output. This can be displayed using the trace viewer that is built in to the Chrome browser. You can activate this by entering about:tracing as the URL, and then clicking the Load button on the tool bar that then appears.

If needed the example tool can extract the binary (INFO) sections if they need to be processed by some other tool. e.g.

$ instdump --only-section .ecos_inst_time -o time.bin elfimage
Though it should be noted that the standard objcopy tool also provides support for extracting arbitrary sections from an executable.

For backwards compatibility it can also be used to generate an instrument_desc.h compatible header.

$ instdump --gen-header --output instrument_desc.h elfimage

Adding new instrumentation

At its simplest adding new instrumentation is simply a case of defining manifests for the class, and the (up to 31) sub-codes within that class; and specifying the number of arguments (currently 0, 1 or 2) that the class/code pairing provides.

To make full use of the support provided by the Kernel package instrmnt.h header file, the manifests defining new event classes, and the event codes within each class, should adhere to the relevant CYG_INSTRUMENT_ prefix form. This allows the macros provided by the instrmnt.h header to be used to insert instrumentation points and to declare the mappings in the embedded information structures.

Note: Due to backwards compatibility with the previous instrumentation implementation, which is still supported for the moment, there can be NO whitespace in the manifest definitions for the individual event code definitions, e.g. the CYG_INSTRUMENT_EVENT_ prefix. When the previous implementation no longer needs to be supported then this limitation will be lifted. This is due to the use of a simple build-time script to parse the instrmnt.h source file.

Example 25-2. Including instrumentation

The following simple example inserts an instrumentation point between the two function calls. If instrumentation is disabled in the configuration; then no code will be produced for the CYG_INSTRUMENT() macro call.

#include <cyg/kernel/instrmnt.h>

// Normally would be in a shared header file for use by the whole application
#define CYG_INSTRUMENT_CLASS_OURCLASS 0xc000
#define CYG_INSTRUMENT_EVENT_OURCLASS_OURCODE (CYG_INSTRUMENT_ARGS_VAL(2)|5)

void some_function(cyg_uint32 arg1,cyg_uint32 arg2) {
  do_something();
  CYG_INSTRUMENT(OURCLASS,OURCODE,arg1,arg2);
  do_more_stuff();
}

When the CYGIMP_KERNEL_INSTRUMENT_IMAGE_SECTIONS feature is enabled then for each new event class being defined then suitable descriptors should be provided ONCE in a CYG_KERNEL_INSTRUMENT_SECTION_EVENT_DESCRIPTORS linked section so that the class/code mappings for an event are available to the external processing tools.

Example 25-3. Providing class/code information

The following is a simple example of how the event class/code information is provided in the embedded section for future access by suitable external processing tools. This example provides the definitions for the named “OURCLASS”, “EXAMPLE” and “TEST” classes.

#if defined(CYGIMP_KERNEL_INSTRUMENT_IMAGE_SECTIONS)
const struct instrument_event_descriptor
  ecos_kernel_instrument[] CYGBLD_ATTRIB_SECTION(CYG_KERNEL_INSTRUMENT_SECTION_EVENT_DESCRIPTORS) = {
    // Event class:
    CYG_INSTRUMENT_DESCRIPTOR_ECLASS(OURCLASS),
    // Event code entries:
    CYG_INSTRUMENT_DESCRIPTOR_ECODE(OURCLASS,OURCODE),
    // Event class:
    CYG_INSTRUMENT_DESCRIPTOR_ECLASS(EXAMPLE),
    // Event code entries:
    CYG_INSTRUMENT_DESCRIPTOR_ECODE(EXAMPLE,POINT1),
    CYG_INSTRUMENT_DESCRIPTOR_ECODE(EXAMPLE,SOMEWHERE),
    CYG_INSTRUMENT_DESCRIPTOR_ECODE(EXAMPLE,STARTPOINT),
    CYG_INSTRUMENT_DESCRIPTOR_ECODE(EXAMPLE,ENDPOINT),
    // Event class:
    CYG_INSTRUMENT_DESCRIPTOR_ECLASS(TEST),
    // Event code entries:
    CYG_INSTRUMENT_DESCRIPTOR_ECODE(TEST,ERROR1),
    CYG_INSTRUMENT_DESCRIPTOR_ECODE(TEST,KEYPRESSED),
    // Terminator
    { 0x00, 0x00, 0x00, { "" } },
};
#endif // CYGIMP_KERNEL_INSTRUMENT_IMAGE_SECTIONS

The source file cyg/kernel/instrument_kernel.h contains a good real-world example. It provides the definitions for the Kernel provided instrumentation classes and the sub-codes for each class.

Memory buffer instrumentation

The default instrumentation implementation (when CYGPKG_KERNEL_INSTRUMENT_BUFFER is defined) uses instrument buffers.

Information about the events is stored in an event record. The structure that defines this record has type struct Instrument_Record. As previously described in the Section called Embedded (non-loaded) information, when CYGIMP_KERNEL_INSTRUMENT_IMAGE_SECTIONS is enabled then a description of the memory layout of instrumentation records is embedded into the linked application image. This is so that external tools can process the records written by the application without having to have access to the build source used to create that application, or for the tool to be created against a specific revision of the source used to create the application.

The list of records is stored in an array called instrument_buffer which you can let the kernel provide or you can provide yourself by setting the configuration option CYGVAR_KERNEL_INSTRUMENT_EXTERNAL_BUFFER.

To write a program that examines the instrumentation buffers:

  1. Enable instrumentation buffers in the eCos kernel configuration. The component macro is CYGPKG_KERNEL_INSTRUMENT.

  2. To allocate the buffers yourself, enable the configuration option CYGVAR_KERNEL_INSTRUMENT_EXTERNAL_BUFFER.

  3. Include the header file cyg/kernel/instrmnt.h:

    #include <cyg/kernel/instrmnt.h>

  4. Enable the events you want to record using cyg_instrument_enable(), and disable them later. Look at cyg/kernel/instrmnt.h and the examples below to see what Kernel events can be enabled.

  5. Place the code you want to debug between the matching functions cyg_instrument_enable() and cyg_instrument_disable().

  6. Examine the buffer either from within the application, from an attached debugger (e.g. GDB), or from an external (post-processing) tool with a binary image of the captured instrumentation.

Instrumentation buffer API

If the CDL option CYGDBG_KERNEL_INSTRUMENT_BUFFER_API is enabled then a simple API is provided to allow for the application to cleanly access the instrumentation buffer itself. Without this API the application is itself responsible for ensuring serialised access to the instrumentation memory to ensure that valid/complete records are interpreted.

Note: This API may be extended in the future to allow for multiple instrumentation buffers to be supported, allowing for better memory buffer instrumentation coverage (to minimise the times when records may be missed due to unavailability of buffer space).

The API has the following interface functions:

void *cyg_instrument_buffer_claim(size_t *bsize)

For the current single buffer implementation this just claims the instrumention lock for the duration that the caller holds the buffer. Any instrumentation events raised during the client processing will be dropped.

void cyg_instrument_buffer_release(void *ibuff)

Return a claimed buffer back to the instrumentation world. For the current single instrumentation buffer implementation this just releases the held lock.

size_t cyg_instrument_buffer_size(void)

This function returns the number of bytes used in the instrument_buffer. This is most useful when an external buffer is being provided that is not an exact multiple of the Instrument_Record structure being written.

If needed the internal buffer lock control can be directly accessed via the cyg_instrument_lock() and cyg_instrument_unlock() functions. When the lock is held any calls to the underlying cyg_instrument() function will result in missed events since the aim is to never block the run-time processing from within the instrumentation recording support.

Using GDB to save instrument buffers

If GDB is being used to control the execution of the application, then when the CPU is halted it is very easy to save the instrumentation buffer to a file on the host. From the GDB prompt we can do something like:

(gdb) dump binary memory test.bin &instrument_buffer[0] &instrument_buffer[256]
to get hold of the binary data. For a system configured with buffer wrapping capture enabled (CYGDBG_KERNEL_INSTRUMENT_BUFFER_WRAP) this does not track where the active “head” of the captured data is. For “halt when full” capture then the above command is sufficient to record the instrumentation data.

When wrapping support is being used then the pointer variable instrument_buffer_pointer references the next slot to be filled. In conjunction with information regarding the instrument_buffer:

(gdb) p sizeof(instrument_buffer)
we can just access the relevant parts of the instrument_buffer address space and save the image in two parts if we want a time-ordered capture:
(gdb) dump binary memory file start end
(gdb) append binary memory file start end

It is envisaged that generic host tools like instdump (as described in the Section called instdump tool) will be used to examine the instrumentation data produced when used in conjunction with the ELF image for the application that generated the binary data.

Simple application access

Example 25-4. Using instrument buffers

This program is also provided in the examples directory, and is a very simple example of directly decoding the instrumentation buffer from within the application.

/* this is a program which uses eCos instrumentation buffers; it needs
 to be linked with a kernel which was compiled with support for
 instrumentation */

#include <stdio.h>
#include <pkgconf/kernel.h>
#include <cyg/kernel/instrmnt.h>
#include <cyg/kernel/kapi.h>

#ifndef CYGPKG_KERNEL_INSTRUMENT_BUFFER
# error You must configure eCos with CYGPKG_KERNEL_INSTRUMENT_BUFFER
#endif
#ifndef CYGVAR_KERNEL_INSTRUMENT_EXTERNAL_BUFFER
# error You must configure eCos with CYGVAR_KERNEL_INSTRUMENT_EXTERNAL_BUFFER
#endif

struct Instrument_Record instrument_buffer[20];
cyg_uint32 instrument_buffer_size = 20;

int main(void)
{
 int i;

 cyg_instrument_enable(CYG_INSTRUMENT_CLASS_CLOCK, 0);
 cyg_instrument_enable(CYG_INSTRUMENT_CLASS_THREAD, 0);
 cyg_instrument_enable(CYG_INSTRUMENT_CLASS_ALARM, 0);

 printf("Program to play with instrumentation buffer\n");

 cyg_thread_delay(2);

 cyg_instrument_disable(CYG_INSTRUMENT_CLASS_CLOCK, 0);
 cyg_instrument_disable(CYG_INSTRUMENT_CLASS_THREAD, 0);
 cyg_instrument_disable(CYG_INSTRUMENT_CLASS_ALARM, 0);

 for (i = 0; i < instrument_buffer_size; ++i) {
 printf("Record %02d: type 0x%04x, thread %d, ",
        i, instrument_buffer[i].type, instrument_buffer[i].thread);
#if defined(CYGPKG_KERNEL_INSTRUMENT_TIMESTAMPS_HAL)
 printf("time %5d, ",
        instrument_buffer[i].timestamp_hal);
#endif // CYGPKG_KERNEL_INSTRUMENT_TIMESTAMPS_HAL
 printf("arg1 0x%08x, arg2 0x%08x\n",
        instrument_buffer[i].arg1,
        instrument_buffer[i].arg2);
 }
 return 0;
}

Here is how you could compile and run this program in the examples directory, using (for example) the MN10300 simulator target:

$ make XCC=mn10300-elf-gcc INSTALL_DIR=/tmp/ecos-work-mn10300/install instrument-test
mn10300-elf-gcc -c -o instrument-test.o -g -Wall -I/tmp/ecos-work-mn10300/install/include \
        -ffunction-sections -fdata-sections instrument-test.c
mn10300-elf-gcc -nostartfiles -L/tmp/ecos-work-mn10300/install/lib -W1,--gc-sections -o \
        instrument-test instrument-test.o -Ttarget.ld -nostdlib
$ mn10300-elf-run --board=stdeval1 instrument-test

Example 25-5. Instrument buffer output

Here is the output of the instrument-test program. Notice that in little over 2 seconds, and with very little activity, and with few event types enabled, it gathered 17 records. In larger programs it will be necessary to select very few event types for debugging.

Program to play with instrumentation buffer
Record 00: type 0x0207, thread 2, time  6057, arg1 0x48001cd8, arg2 0x00000002
Record 01: type 0x0202, thread 2, time  6153, arg1 0x48001cd8, arg2 0x00000000
Record 02: type 0x0904, thread 2, time  6358, arg1 0x48001d24, arg2 0x00000000
Record 03: type 0x0905, thread 2, time  6424, arg1 0x00000002, arg2 0x00000000
Record 04: type 0x0906, thread 2, time  6490, arg1 0x00000000, arg2 0x00000000
Record 05: type 0x0901, thread 2, time  6608, arg1 0x48009d74, arg2 0x48001d24
Record 06: type 0x0201, thread 2, time  6804, arg1 0x48001cd8, arg2 0x480013e0
Record 07: type 0x0803, thread 1, time    94, arg1 0x00000000, arg2 0x00000000
Record 08: type 0x0801, thread 1, time   361, arg1 0x00000000, arg2 0x00000000
Record 09: type 0x0802, thread 1, time   548, arg1 0x00000001, arg2 0x00000000
Record 10: type 0x0803, thread 1, time    94, arg1 0x00000000, arg2 0x00000000
Record 11: type 0x0801, thread 1, time   361, arg1 0x00000001, arg2 0x00000000
Record 12: type 0x0903, thread 1, time   513, arg1 0x48009d74, arg2 0x48001d24
Record 13: type 0x0208, thread 1, time   588, arg1 0x00000000, arg2 0x00000000
Record 14: type 0x0203, thread 1, time   697, arg1 0x48001cd8, arg2 0x480013e0
Record 15: type 0x0802, thread 1, time   946, arg1 0x00000002, arg2 0x00000000
Record 16: type 0x0201, thread 1, time  1083, arg1 0x480013e0, arg2 0x48001cd8
Record 17: type 0x0000, thread 0, time     0, arg1 0x00000000, arg2 0x00000000
Record 18: type 0x0000, thread 0, time     0, arg1 0x00000000, arg2 0x00000000
Record 19: type 0x0000, thread 0, time     0, arg1 0x00000000, arg2 0x00000000
2017-02-09
Documentation license for this page: Open Publication License