From RTSC-Pedia

[printable version]  [offline version]

offline version generated on 04-Aug-2010 21:08 UTC

Using xdc.runtime Logging

How to generate and control Log events

Introduction

The xdc.runtime package contains several modules that work together to provide rich application diagnostic support that can be controlled in real-time within deployed systems. This section focuses on those modules that are used to generate "events", enable/disable their generation, and display the events: Log, Diags, and LoggerSys, respectively.

Use of these modules is illustrated below by a series of examples that take advantage of two other distinguished xdc.runtime modules:

1. Main - a module whose configuration applies to all code that is not a RTSC module; e.g., existing C code bases, and
2. Defaults - a module whose configuration applies to all RTSC modules (including Main), unless explicitly overridden on a per-module basis.

Overview

The xdc.runtime package's logging support enables developers to embed "printf-like" Log statements virtually anywhere in an embedded real-time code base. In addition to the traditional printf() format string and arguments, each Log statement is associated with a calling module and an "event mask" - a bit mask that identifies the "type" of statement. The Log statements

• provide all the functionality of a "normal" printf,
• can be enabled or disabled at runtime on a per-module and per-type basis, and
• have fixed low execution time independent of the arguments passed.

Applications can be configured to eliminate the data space required for the format strings, permanently disable (or enable) selected statements, eliminate the code space required for runtime control, and provide application-specific handling of the "events" produced by these statements. All of these configuration options are possible without requiring re-compilation of any source code.

Architecture

For the purpose of logging, every line of code in an application is treated as being part of some RTSC module. All code falls into one of three classes:

1. code that is part of a RTSC module
2. code that is part of a dynamically registered module. Code can dynamically register itself as a module through the xdc.runtime.Registry module.
3. all other code. Any code that is not part of a RTSC module or a registered module is considered to be part of the distinguished xdc.runtime.Main module.

All RTSC target modules, including xdc.runtime.Main, have a

• current "event mask" - a set of event categories that are enabled for the module,
• an optional ILogger service provider - a module that handles events generated by the module, and
• an optional string name used to display the source of events

All dynamically registered modules also have an event mask and a required string name.

The Log_print or Log_write methods are used to generate or log "events". These methods are simply in-line macros that conditionally invoke the calling module's underlying ILogger service provider to "handle" the events. This service provider is called only if:

1. the module has a non-null ILogger service provider, and
2. the mask argument passed to Log_print (or the mask of the event passed to Log_write) anded with the calling module's current "event mask" is non-zero

The initial value of a module's event mask is specified during configuration and may be changed at runtime via Diags_setMask().

Beyond the parameters passed to Log_print (or Log_write), the id of the module that called Log_print (or Log_write) is communicated to the ILogger service provider so that it knows the source of the events. This information, possibly in addition to a timestamp recorded by the ILogger service provider, can be used to correlate events from multiple sources (even from different CPUs).

Two ILogger service providers are included in the xdc.runtime package:

1. LoggerBuf - copies events to a circular buffer in a fixed small number of cycles and is suitable for real-time high-frequency event sources, and
2. LoggerSys - outputs events as they occur using System_printf() and is suitable for initial development or low-rate non-real-time event sources.

Custom ILogger service providers can easily be created to address platform or application specific needs. These custom providers can, of course, filter events and call LoggerBuf or LoggerSys. For information about creating and deploying a custom logger see Extending xdc.runtime Logging.

As part of an application's configuration step, developers "bind" zero or more ILogger service providers to the modules that comprise the application. Each module in a system can have a different ILogger service provider or they can all share the same provider. Events generated by modules without an ILogger service provider are silently ignored.

Configuration

Users of libraries that embed xdc.runtime.Log statements can configure their application to specify:

• what modules should be "traceable" and whether their Log events are controllable at runtime or only at configuration time
• on a per-module basis, what ILogger service providers should be used to "handle" the events as they are generated
• for the ILogger service providers LoggerBuf and LoggerSys, what ITimestampProvider service module to use to timestamp individual events

The ability to configure a unique ILogger service provider for each module in an application together with the xdc.runtime.Main module representing all other code, enables the integrator to separately manage events from all parts of the code base independent of who produced the code.

Since the computation of timestamps is highly platform-specific and the required precision of timestamps is application dependent, the ILogger service providers in the xdc.runtime package can be configured with an appropriate timestamp service provider.

These configuration options make it possible for the system integrator to strike a balance between the need for application runtime visibility against the overhead required for this visibility without making any changes to the code containing embedded Log_print (or Log_write) statements. Even better, these options are possible without requiring re-compilation of any source code making it possible to (re)configure pre-built binary libraries that utilize xdc.runtime.Log methods.

Examples

The best way to understand how to use and take advantage of the logging facilities provided by the xdc.runtime package is to study some simple examples. In the table below, we provide a series of graduated examples that illustrate the key capabilities of logging and provide links to more advanced topics.

In addition to the "client-side" examples above, the table below lists examples of how to create ILogger modules that "handle" the events generated by clients. The examples listed below illustrate how one can provide sophisticated application and platform specific capabilities and require a bit more experience with RTSC modules. However, they are simple enough to be used and modified by relative novices.

Built-in Loggers

The xdc.runtime package includes two built-in loggers:

1. LoggerBuf - a logger that simply records events in a memory buffer, and
2. LoggerSys - a logger that uses System_printf() to output events as they occur.

The following sections briefly describe these loggers and show examples of their use. Extending xdc.runtime Logging describes how to create additional loggers.

LoggerBuf Module

The xdc.runtime.LoggerBuf module provides a logger that stores run-time Log events in a buffer.

This logger captures Log events in real-time to a buffer. The Log events stored in the buffer are unformatted; the log event formatting is deferred. Use LoggerBuf_flush() to process the Log events stored in the buffer and stream the formatted output to stdout.

The implementation of this logger is fast with minimal stack usage making it appropriate for real-time applications. If this logger is used in a preemptive environment, then an appropriate gate must be assigned to the module. For example, if you wish to generate Log events from an interrupt context, then a gate that disables interrupts must be used.

var LoggerBuf = xdc.useModule('xdc.runtime.LoggerBuf');
LoggerBuf.common$.gate = ...some gate instance...

If the buffer type is circular, the log buffer contains the last LoggerBuf_numEntries events. If the bufType is fixed, the log buffer contains the first LoggerBuf_numEntries events since the buffer was cleared.

Configuration example

Configuration example.  The following configuration statements create a logger instance, assign it as the default logger for all modules, and enable USER1 logging in all modules of the package my.pkg. See the Diags.setMaskMeta() reference documentation for details on specifying the module names.

var LoggerBuf = xdc.useModule('xdc.runtime.LoggerBuf');
LoggerBuf.enableFlush = true;
 
var Defaults = xdc.useModule('xdc.runtime.Defaults');
Defaults.common$.logger = LoggerBuf.create({exitFlush: true});
 
var Diags = xdc.useModule('xdc.runtime.Diags');
Diags.setMaskMeta("my.pkg.%", Diags.USER1, Diags.RUNTIME_ON);

LoggerSys Module

The xdc.runtime.LoggerSys module routes events to the System_printf() function.

This logger processes Log events as they are generated and routes them through the System_printf() function. The final disposition of the log event is dependent on which system provider has been assigned to System.SupportProxy.

Note that the Log events are processed within the run-time context of the Log_write() or Log_print() function that generated the event. It is important to account for the processing overhead and stack usage imposed on the runtime context. The cost of this processing is defined by the implementation of the system provider.

Configuration example

Configuration example.  The following configuration statements create a logger instance, assign it as the default logger for all modules, and enable USER1 logging in all modules of the package my.pkg. See the Diags.setMaskMeta() reference documentation for details on specifying the module names.

var LoggerSys = xdc.useModule("xdc.runtime.LoggerSys");
 
var Defaults = xdc.useModule("xdc.runtime.Defaults");
Defaults.common$.logger = LoggerSys.create();
 
var Diags = xdc.useModule("xdc.runtime.Diags");
Diags.setMaskMeta("my.pkg.%", Diags.USER1, Diags.RUNTIME_ON);

Performance Considerations

This section provides an overview of the performance overhead you can expect when using the xdc.runtime logging facilities. Generally speaking, the configuration capabilities included allow developers to strike a balance between runtime visibility and overhead for even the most resource constrained systems. Several common configuration options are described in the Configuration Options section below.

Execution Time

Because Log_print and Log_write are inline macros, when events are disabled, the time overhead for these statements is quite low; typically only a few instruction cycles. As a result, leaving these statements in deployed applications is quite practical. When events are enabled, the time overhead is largely a function of the underlying module's ILogger service provider.

For providers like LoggerBuf, even this overhead is small enough to allow most applications to continue to meet their real-time deadlines even while simultaneously capturing logging events. On the other hand, the LoggerSys provider does not simply record event data to a buffer, it "formats" each event as it occurs using System_printf(). While useful during initial development, this processing can be somewhat expensive and should not be used with modules whose methods are time critical.

Runtime control of event generation is supported via Diags_setmask(). Since this method uses a string to "look up" module event masks, its execution time is a function of the number of modules in the system and the lengths of their names. Although relatively efficient, this method should not be used in time sensitive legs of an application.

Code Space

Code space overhead for logging support comes from three places:

1. the instructions required at each Log_print() / Log_write() call site (to test the current mask and conditionally generate a Log event)
2. the xdc.runtime modules themselves, and
3. the underlying ILogger service provider

Although the code space overhead per Log_print() / Log_write() call site is only a few words, thousands of call sites can add up to a significant amount of code. Since "entry", "exit" and "life-cycle" events are added during configuration for RTSC modules (and don't appear in the module's sources), the overhead for this support is 100% controllable by the system integrator via configuration options; on a per module basis, the end user can add or remove varying degrees of logging support.

The code space required for the xdc.runtime library is relatively small (e.g., approximately 2K bytes for the C64) but, even if there are embedded references to the Log_print() / Log_write() functions, the runtime library code can be completely "configured out" of an application by the system integrator; i.e., no recompilation of any sources is required.

Finally, the ILogger service provider's code size is a function of the module used to "handle" Log events. Although only LoggerBuf and LoggerSys are provided by xdc.runtime package, it is expected that customized ILogger service provider will be used to leverage platform-specific communication mechanisms. A practical estimate of the code size overhead is the code size of the larger of the two supplied loggers, LoggerBuf, which is about 2K bytes on a C64 architecture.

Data Space

Data space overhead for logging support comes from three places:

1. the format strings required at each Log_print() call site and the format strings in each Log_Event
2. the data space for the module name lookup tables required to support Diags_setMask(), and
3. one string pointer per "named" instance object to maintain a "human readable" name for these instances

The format strings used for each event can add up to be relatively significant amount of space, especially on very small systems. Using Log_write() in lieu of Log_print() allows these strings to be moved entirely off the target. In addition, since RTSC modules do not need to add Log statements to provide "entry", "exit", or "lifecycle" events, the only significant overhead comes from explicit calls to Log_print(). Judicious use of Log_print() should ensure that this overhead is acceptable for most applications.

To support runtime control of Log events via Diags_setMask() a table of module names is created during configuration. This table is relatively small (approximately two words per module plus a module name string). For systems that do not need runtime control of events, it is possible to disable the generation of this table; see the Configuration Options section below.

Finally, all RTSC modules optionally support the ability to associate a string name with instances. While this can be beneficial for systems with a relatively small number of instances (hundreds), high density systems that need to support thousands of channels don't need (or want) a distinct string name for each instance, for example. Each RTSC module can be separately configured to reserve space for instance names (or not).

Configuration Options

The xdc.runtime logging support offers a variety of configuration options to satisfy the often conflicting performance requirements of different embedded applications. This section summarizes some of these options.

• every module can have a different ILogger service provider
• every RTSC instance object can have a "human readable" string name
• runtime control via Diags_setMask() can be "configured out" of an application
• event format strings do not need to be stored in the application

Making Log_print() or Log_write() deterministic

Making Log_print() or Log_write() deterministic. When an event is generated by either Log_print() or Log_write(), the execution time overhead is purely a function of the underlying ILogger serive provider. So, to get deterministic low overhead execution times, you must use an appropriate service provider: you can use LoggerBuf or, of course, write your own ILogger service provider. You must then configure the modules in you application to use this logger. The following configuration script fragment sets LoggerBuf to be the default logger for all modules.

var Defaults = xdc.useModule("xdc.runtime.Defaults");
var Logger = xdc.useModule("xdc.runtime.LoggerBuf");
Defaults.common$.logger = Logger.create();

Eliminating unnecessary strings

Eliminating unnecessary strings.  Adding "printf-like" statements to a C code base not only increases code space (the instructions to put arguments in registers and call a function) but it can significantly increase an application's data space requirements; each "printf-like" format string is added to a data section reserved for constants and the size of section can grow quickly as more and more logging statements are added. While it's not possible to stop the strings used in Log_print() statements from taking up space in the target, it is possible to completely eliminate the format strings by used by Log_write().

In lieu of a mask and a format string as initial arguments, Log_write() takes a Log_Event. A Log_Event is an opaque reference to a structure that contains a mask and a format string. How does this help? By eliminating direct references to literal strings in the C sources, the C compiler only sees an integer index being passed to Log_write() and never needs to allocate space for the constant format string. During configuration, it's possible to generate a table of all Log_Event format strings, define Log_Event as an index into this table, and arrange for this table to loaded in a separate output section. Since this table is only needed when the event is "decoded", the table (with the strings) does not need to be loaded into the target's memory; events can be decoded by host-based development tools which simply lookup the event based on the index supplied by Log_write(). This table of strings is managed by the xdc.runtime.Text module.

To eliminate the runtime strings you must configure the Text module to place all strings in a special section that will not be loaded onto the target.

var Text = xdc.module("xdc.runtime.Text");
Text.isLoaded = false;

In addition to format strings used in Log_print() statements, string names of all modules and (optionally) instances are also maintained on the target. Again, in systems where space is a precious resource, it is sometimes necessary to eliminate these "conveniences" in favor of other critical data. The next section shows how to not only eliminate the strings but also the one-word per-instance and per-module overhead to hold a pointer to these strings.

Eliminating per-instance and per-module space overhead

Eliminating per-instance and per-module space overhead.  To facilitate deciphering an application's Log events, all RTSC modules can optionally reserve an extra word to hold a pointer to a string name for each instance. Unless you specify otherwise, space required to hold a pointer to a name is not reserved in instance objects and, as a result, the "life-cycle" events do not provide the names of the instances that were specified in the application. Make sure you have not inadvertently enabled instance names via the namedInstance configuration parameter.

On the other hand, all RTSC modules do have a string name that is part of the target runtime (by default). You can eliminate these names for all modules, except for Memory and Main, by setting the and namedModule configuration parameter to false.

   var Defaults = xdc.module("xdc.runtime.Defaults");
   Defaults.common$.namedModule = false;

Since the overhead of two module names is quite small and both Memory and Main are referenced in many Error events, to eliminate the names for Main and Memory you must explicitly set their common$.namedModule configuration parameter to false.

   var Main = xdc.module("xdc.runtime.Main");
   Main.common$.namedModule = false;
 
   var Memory = xdc.module("xdc.runtime.Memory");
   Memory.common$.namedModule = false;

Eliminating runtime event control code

Eliminating runtime event control code.  The ability to control event masks at runtime is a common requirement but, in extremely resource constrained systems it may not be a luxury that can be afforded. Eliminating this support is possible by setting the Diags.setMaskEnabled configuration parameter to false.

[printable version]  [offline version]

offline version generated on 04-Aug-2010 21:08 UTC