SystemAnalyzerTutorial1F

System Analyzer Tutorial 1F

Function Profiling

System Analyzer's Context-aware Profiling feature allows you to do inclusive and exclusive profiling of functions in your application. In order to collect profiling information, a UIA Benchmark start event needs to be logged at the function entry point, and a UIA Benchmark stop event needs to be logged at the exit point of the function. The simplest way to do this is to configure the compiler to call entry and exit hook functions, and to instrument these hook functions to log the required events.

Profiling the UIA Stairstep Example Project

Here's how to enable function profiling for the UIA Stairstep example project:

1) Create a new CCS project based on the Stairstep JTAG RunMode example project

• New / Project / CCS Project
• From the new project wizard, select your Device type and, from Project Templates and examples, select System Analyzer (UIA) / Single-core Examples / Stairstep JTAG RunMode (or Stairstep JTAG StopMode for devices other than the C6X or C28X).

• Click next and select the platform file for your hardware

2) In the CCS Project Explorer view, right click on your project and select 'Show Build Settings'. In the left pane, select Build / <CPU type> Compiler / Advanced Options / Entry/Exit Hook Options and configure the dialog as shown below:

3) Add the UIABenchmark module to your application's .cfg file

var UIABenchmark = xdc.useModule('ti.uia.events.UIABenchmark');

4) Include the UIABenchmark.h and LogUC.h files in the file you wish to add your hook functions to (e.g. main.c):

#include <ti/uia/runtime/LogUC.h>
#include <ti/uia/events/UIABenchmark.h>

5) Add entry and exit hook functions to the source

void functionEntryHook( void (*addr)() ){
    Log_writeUC3(UIABenchmark_startInstanceWithAdrs, (IArg)"context=0x%x, fnAdrs=0x%x:",(IArg)0, (IArg)addr);
}

void functionExitHook( void (*addr)() ){
    Log_writeUC3(UIABenchmark_stopInstanceWithAdrs,  (IArg)"context=0x%x, fnAdrs=0x%x:",(IArg)0, (IArg)addr);
}

The 2nd parameter (IArg)0 is a context parameter and can be used to specify an additional level of qualification (e.g. Task Context). If functions are not called by multiple threads in your application, you can ignore this and just set it to 0 as shown above. If you have multiple tasks calling the same function, however, you should set it to the current task handle e.g. by calling SysBios's Task_selfMacro() as shown below:

#include <ti/sysbios/knl/Task.h>
...

void functionEntryHook( void (*addr)() ){
    Log_writeUC3(UIABenchmark_startInstanceWithAdrs, (IArg)"context=0x%x, fnAdrs=0x%x:",(IArg)Task_selfMacro(), (IArg)addr);
}

void functionExitHook( void (*addr)() ){
    Log_writeUC3(UIABenchmark_stopInstanceWithAdrs,  (IArg)"context=0x%x, fnAdrs=0x%x:",(IArg)Task_selfMacro(), (IArg)addr);
}

If task aware profiling is needed, the Task context has to be logged. SYS/BIOS automatically logs events for task switches and SWI and HWI Start and Stop events. See Enabling and Disabling logging Sec 5.2.2 in System Analyzer User's Guide. Context change can also be explicitly logged by the application.

NOTE: Calling the Log_writeUC* APIs from a module that does not have a logger assigned will cause your application to crash. If you wish to add protection against this you can use Log_write3 instead of Log_writeUC3 in the above code snippets. The Log_write* macros have additional checks that will prevent calling the logger's APIs if a logger has not been assigned to the module. Please see Tutorial 1E for more info on this.

Running the example application

After modifying the example project as described above, you should be able to build it. A warning about the use of the LogUC macros will be generated automatically by the compiler (#warn LogUC.h is a preliminary set of optimized Log APIs ... etc.) It is safe to ignore this warning since the LoggingSetup module in the .cfg script will automatically configure your application to assign a logger to log these events.

Once your application is built, you should be able to launch your target, load your project and run to main. Once it is halted at main, start System Analyzer (Tools / System Analyzer / Live). Check "Context Aware Profile" and the "Summary" view item in that row. Then click Start.

If your project is using JTAG stop-mode to capture events, the views will be updated after halting the target. For JTAG run-mode, the views will start showing events and populating the Context-Aware Profiling table as the events are collected.

Analyzing Results

The Context Aware Profile feature calculates duration while considering context switches, interruptions, and execution of other functions.

The Context Aware Profile displays data only if you modify your target code to include UIABenchmark events as described above.

You can use this feature to see information about "inclusive time" vs. "exclusive time".

• Inclusive time is the entire time between a given pair of start times and stop times.
• Exclusive time is the inclusive time minus any time spent running any other thread context.

• Time spent in called functions and time spent running threads that preempt are yielded to by the thread being measured are not counted in exclusive time.

See Section 4.13.3 of the System Analyzer Users Guide (SPRUH43D) for details about how inclusive and exclusive time are calculated.

Summary View for Context Aware Profile

The Context Aware Profile Summary View
The Summary view shows the minimum, maximum, average, and total number of nanoseconds within each thread for the selected core. These statistics are reported both for inclusive and exclusive time.

The summary view shows statistics about each duration context that was measured. The statistics summarize multiple measurements made for each context. The columns in this view are as follows:

• Name. The name of the item for this row of statistics. The name has the following format:

<master>,<task name>,<function name>.<function id logged> If the Task context or the function running cannot be determined, those portions of the name are listed as “Unknown” in the generated Name.

• Count. The number of start/stop pairs that measured this item’s duration.
• Incl Count Min. The minimum inclusive time measured.
• Incl Count Max. The maximum inclusive time measured.
• Incl Count Average. The average inclusive time measured.
• Incl Count Total. The total inclusive time measured.
• Incl Count Percent. The percent of all the inclusive times reported due to this item.
• Excl Count Min. The minimum exclusive time measured.
• Excl Count Max. The maximum exclusive time that was measured.
• Excl Count Average. The average exclusive time measured.
• Excl Count Total. The total exclusive time measured.
• Excl Count Percent. The percent of all the exclusive times reported due to this item.

The Context Aware Profile Detail View
The Detail view presents the raw start and stop times for each start/stop pair measured.

• To open the Detail view, use the Views drop-down list in the toolbar of the Context Aware Profile Summary view.

Profiling Results when using Libraries:
If your code calls a function that is in a library that was built without entry and exit hook functions, then the entry and exit points of the library functions will not be instrumented so they won't show up in the Context Aware Profile: Summary view's table. The amount of time spent in these functions will be included in Exclusive counts of the functions making calls to the Library.

Going Further:
For more info on Profiling using system analyzer, please refer to sections 3.5 and 4.12 of the System Analyzer Users Guide (SPRUH43D).

For more info on configuring UIA to work with SysBios, including information on how to configure the ti.uia.sysbios.LoggingSetup module, please see Tutorial 3.

Next: Tutorial 2: Graphing Events and using JTAG Run-mode

Links:

• Back up to the System Analyzer Tutorials page
• Back up to the System Analyzer Home