From RTSC-Pedia

[printable version]

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

Using xdc.runtime Logging/Example 2

Events provided by all RTSC target modules

Implicit Events from RTSC Modules

By default, all RTSC target modules support entry and exit events for every method. In other words, whenever any method of module's function is entered (called) a Log event containing the parameters passed to the function is triggered and when the function exits (returns) a Log event containing the function return value is triggered. In addition, for those modules that support instances, instance life-cycle trace is also available; whenever an instance is created or deleted, an appropriate Log event is triggered. All of these events are called implicit because the module's author did not have to add any code to their sources to trigger these events.

Applications that use RTSC target modules (e.g., any of the DSP/BIOS 6.x modules) can be configured to enable the generation and display of these events in much the same way as shown in Example 1. To illustrate how to use implicit events, we suppose there is a RTSC module named examples.runtime.Mod whose specification includes the following statements.

module Mod {
    Bool foo(Int x, String s); /*! A module function */
 
  instance:
    Int bar();                 /*! An instance function */
}
 

In this example we show a series of configuration files, each building on the previous, with differences indicated by a ! symbol at the beginning of each line that changed or a + in front of each line added. The first configuration file differs only slightly from the one in Example 1:

• we add an xdc.useModule() statement for the module examples.runtime.Mod that's used in the example applications, and
• rather than configuring the Main module (which only applies to non-RTSC modules), we configure the special Defaults module which specifies default settings for all modules (including Main).

var Mod = xdc.useModule("examples.runtime.Mod");
var Log= xdc.useModule("xdc.runtime.Log");
var Diags = xdc.useModule("xdc.runtime.Diags");
 
/* enable runtime entry events for all code (by default) */
var Defaults = xdc.useModule("xdc.runtime.Defaults");
Defaults.common$.diags_INFO = Diags.RUNTIME_ON;
 
/* use the LoggerSys ILogger service provider */
var Logger = xdc.useModule("xdc.runtime.LoggerSys");
 
/* create and bind a default logger for all code */
Defaults.common$.logger = Logger.create();

This new configuration has the advantage that it allows us to easily control all RTSC modules in the application with a single setting rather than having to individually control each module.

Before showing the Log events implicitly generated by RTSC modules, it is interesting to see the effect of this new configuration file on the "hello world" application shown in Example 1.

#include <xdc/std.h>
 
#include <xdc/runtime/Log.h>
#include <xdc/runtime/Diags.h>
 
int main(int argc, String argv[])
{
    Log_info0("hello world");
 
    return (0);
}

xdc.runtime.Main: "app.c", line 8: hello world

Notice that the output of hello.c is unchanged by this new configuration. Why? The Defaults module's configuration parameters apply to all modules (including Main) that have not been explicitly set. By setting a logger in the Defaults module and not setting one in Main, this configuration script has the same effect as hello.c's original configuration script.

Method Invocation Events

Unless explicitly disabled, every method of a RTSC module supports both "entry" and "exit" events: on entry to a method, the method's name and its arguments are marshalled into an "entry" (Diags_ENTRY) event and, on return from the method, the method's name and return value are marshalled into an "exit" (Diags_EXIT) event.

#include <xdc/std.h>
 
#include <examples/runtime/Mod.h>
 
int main(int argc, String argv[])
{
    /* call a "module-wide" method */
    Mod_foo(100, "a string");
 
    return (0);
}

examples.runtime.Mod: --> foo: (100, "a string")

Notice that the application never referenced Log or Diags and only calls the Mod_foo() method of the Mod module. Because we enabled "entry" events and specified LoggerSys as the default ILogger service provider, an "entry" event is generated on every call to any Mod method and this event is displayed by LoggerSys. The displayed entry event contains the name of the module, the name of the method, and the values of all arguments to the method.

RTSC modules support both "entry" events and "exit" events, so where is the output for the exit or return from Mod_foo()? In order to cause "exit" events to be generated, we need to return to the configuration file and enable these events.

var Mod = xdc.useModule("examples.runtime.Mod");
var Defaults = xdc.useModule("xdc.runtime.Defaults");
var Diags = xdc.useModule("xdc.runtime.Diags");
 
/* enable runtime controllable diagnostics in all modules (by default) */
Defaults.common$.diags_ENTRY = Diags.RUNTIME_ON;
 
Mod.common$.diags_EXIT = Diags.RUNTIME_ON;  /* enable Mod exit events only */
 
/* use the LoggerSys ILogger service provider */
var Logger = xdc.useModule("xdc.runtime.LoggerSys");
 
/* create an ILogger instance and make it the default program-wide logger */
Defaults.common$.logger = Logger.create();

With Mod exit events enabled, a second line of output from the logger (prefixed by the sequence "<--") shows both the name of the method and its return value (if there is any).

#include <xdc/std.h>
 
#include <examples/runtime/Mod.h>
 
int main(int argc, String argv[])
{
    /* call a "module-wide" method */
    Mod_foo(100, "a string");
 
    return (0);
}

examples.runtime.Mod: --> foo: (100, "a string")
examples.runtime.Mod: <-- foo: 1

Notice that we only enable "exit" events for the Mod module rather than making this setting the default for all modules as we did for "entry" events. Either would work for this example, but "entry" events are often sufficient to understand the operation of the application and, however small the logging overhead is, we don't want to add any unnecessary overhead. On the other hand, there are times when "exit" events can be vital to properly deciphering the operation of an application - especially in multi-threaded environments.

Instance Life-cycle Events

Like C++ (or Java) classes, RTSC modules often support instance object creation. While the implicit method event generation shown above might be sufficient in some cases, RTSC distinguishes the instance creation/deletion methods from "ordinary" methods: there is a separate "life-cycle" (Diags_LIFECYCLE) event type that is used exclusively for these methods.

var Mod = xdc.useModule("xdc.runtime.Mod");
var Defaults = xdc.useModule("xdc.runtime.Defaults");
var Diags = xdc.useModule("xdc.runtime.Diags");
 
/* enable runtime controllable diagnostics in all modules (by default) */
Defaults.common$.diags_ENTRY = Diags.RUNTIME_ON;
 
Mod.common$.diags_EXIT = Diags.RUNTIME_ON;       /* enable Mod exit events only */
Mod.common$.diags_LIFECYCLE = Diags.RUNTIME_ON;  /* enable Mod lifecycle events only */
 
/* use the LoggerSys ILogger service provider */
var Logger = xdc.useModule("xdc.runtime.LoggerSys");
 
/* create an ILogger instance and make it the default program-wide logger */
Defaults.common$.logger = Logger.create();

Given this new configuration it's instructive to walk through a test application and correlate its calls with the Log event output. Each line of the output below has been numbered and each of these numbers appears next to the line in the test that generates the output. A complete explanation of each output line appears below.

#include <xdc/std.h>
 
#include <examples/runtime/Mod.h>
 
int main(int argc, String argv[])
{
    Mod_Params prms;
    Mod_Handle heapInst, stackInst;
    Mod_Struct struc;
    /* create a heap-based instance  */
    Mod_Params_init(&prms);
    prms.instance->name = "myHeapInst";
    heapInst = Mod_create(&prms, NULL);
 
    /* call a per-instance function */
    Mod_bar(heapInst);
 
    /* construct a stack-based instance */
    prms.instance->name = "myStackInst";
    Mod_construct(&struc, &prms);
    stackInst = Mod_handle(&struc);
 
    /* call bar on "stack" instance */
    Mod_bar(stackInst);
 
    /* delete the heap instance, twice! */
    Mod_delete(&heapInst);
    Mod_delete(&heapInst); 
 
    /* delete the "stack" instance */
    Mod_destruct(&struc);
    return (0);
}

examples.runtime.Mod: <-- create: @08051010('(null)')
examples.runtime.Mod: --> bar: (@08051010)
examples.runtime.Mod: <-- bar: 110
examples.runtime.Mod: <-- construct: @bffff21c('(null)')
examples.runtime.Mod: --> bar: (@bffff21c)
examples.runtime.Mod: <-- bar: 110
examples.runtime.Mod: --> delete: (@08051010)
examples.runtime.Mod: --> delete: (@00000000)
examples.runtime.Mod: --> destruct: (@bffff21c)

The output messages are annotated below.

1	create a new Mod instance from a heap; the address of the instance is displayed
2,3	call the instance method bar; the name of the method, the parameters to the method, and its return value are displayed
4	construct a new Mod instance from stack memory; like the heap-based instance, the address of the instance is displayed
5,6	call the bar method again but this time with the new stack-based instance
7	delete the heap-based instance; the address of the instance being deleted is displayed
8	delete the heap-based instance again; notice that the address displayed in this case is 00000000. This is not an error - module instance delete methods automatically nullify instance handles the first time they are deleted (to prevent heap corruption that would arise if an application inadvertently frees instance memory twice). Subsequent redundent deletes are detected (by a NULL instance handle) and silently ignored.
9	destruct the stack-based instance; as with the heap-based instance, the address of the instance being destructed is displayed.

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 above did not provide the names of the instances that were specified in the application; the string " (null) " appears where the instance name would normally be displayed. Applications with thousands of instance objects can rarely afford the convenience of maintaining a unique symbolic name for every object. Once again, to enable symbolic instance name support (and the one extra word of overhead per instance object) we return to the configuration file and add this support for just the Mod module.

var Mod = xdc.useModule("examples.runtime.Mod");
var Defaults = xdc.useModule("xdc.runtime.Defaults");
var Diags = xdc.useModule("xdc.runtime.Diags");
 
/* enable runtime controllable diagnostics in all modules (by default) */
Defaults.common$.diags_ENTRY = Diags.RUNTIME_ON;
 
Mod.common$.diags_EXIT = Diags.RUNTIME_ON;       /* enable Mod exit events only */
Mod.common$.diags_LIFECYCLE = Diags.RUNTIME_ON;  /* enable Mod lifecycle events only */
Mod.common$.namedInstance = true;                /* enable Mod instance names  */
 
/* use the LoggerSys ILogger service provider */
var Logger = xdc.useModule("xdc.runtime.LoggerSys");
 
/* create an ILogger instance and make it the default program-wide logger */
Defaults.common$.logger = Logger.create();

examples. runtime.Mod: <-- create: @08051010('myHeapInst')
examples. runtime.Mod: --> bar: (@08051010)
examples. runtime.Mod: <-- bar: 110
examples. runtime.Mod: <-- construct: @bffff21c('myStackInst')
examples. runtime.Mod: --> bar: (@bffff21c)
examples. runtime.Mod: <-- bar: 110
examples. runtime.Mod: --> delete: (@08051010)
examples. runtime.Mod: --> delete: (@00000000)
examples. runtime.Mod: --> destruct: (@bffff21c)

Setting namedInstance to true enables the name of these instances to be displayed (instead of (null) as above) at the expense of one word per instance which is used to retain a pointer to the name.

See also

[printable version]

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