Warning: main(/www/www/htdocs/style/globals.php) [function.main]: failed to open stream: No such file or directory in /www/www/docs/6.4.1/ide_en/user_guide/sysprof.html on line 1

Warning: main() [function.include]: Failed opening '/www/www/htdocs/style/globals.php' for inclusion (include_path='.:/www/www/common:/www/www/php/lib/php') in /www/www/docs/6.4.1/ide_en/user_guide/sysprof.html on line 1

Warning: main(/www/www/htdocs/style/header.php) [function.main]: failed to open stream: No such file or directory in /www/www/docs/6.4.1/ide_en/user_guide/sysprof.html on line 8

Warning: main() [function.include]: Failed opening '/www/www/htdocs/style/header.php' for inclusion (include_path='.:/www/www/common:/www/www/php/lib/php') in /www/www/docs/6.4.1/ide_en/user_guide/sysprof.html on line 8

Analyzing Your System with Kernel Tracing

In this chapter:

Introducing the QNX System Profiler

The System Profiler is a tool that works in concert with the Neutrino instrumented kernel (procnto-instr) to provide insight into the operating system's events and activities. Think of the System Profiler as a system-level software logic analyzer. Like the Application Profiler, the System Profiler can help pinpoint areas that need improvement, but at a system-wide level.

The instrumented kernel can gather a variety of events, including:

You might use the System Profiler to solve such problems as:


Note: Details on kernel instrumentation (such as types and classes of events) are more fully covered in the System Analysis Toolkit (SAT) User's Guide.

The QNX System Profiler perspective includes several components that are relevant to system profiling:

Navigator view
Events are stored in log files (with the extension .kev) within projects in your workspace. These log files are associated with the System Profiler editor.
Target Navigator view
When you right-click a target machine in the Target Navigator view, you can select Log With…-->Kernel Event Trace, which initiates the Log Configuration dialog. You use this wizard to specify which events to capture, the duration of the capture period, as well as specific details about where the generated event log file (.kev file) is stored.
System Profiler editor
This editor provides the graphical representation of the instrumentation events in the captured log file. Like all other Eclipse editors, the System Profiler editor shows up in the editor area and can be brought into any perspective. This editor is automatically associated with .kev files, but if you have other file types that contain instrumentation data, you could associate the editor with those files as well.
Trace Event Log view
This view lists instrumentation events, as well as their details (time, owner, etc.), surrounding the selected position in the currently active System Profiler editor.
General Statistics view
A tabular statistical representation of events.

Note: You can gather statistics for the entire log file or for a selected range.

Condition Statistics view
A tabular or graphical statistical representation of the conditions used in the search panel.
Event Owner Statistics view
A tabular statistical representation of events broken down per owner.

Other components help you determine why a given thread is running, examine the migration of threads from one processor or core to another, and so on. For more details, see Associated views,” later in this chapter.


Note: The QNX System Profiler perspective may produce incorrect results when more than one IDE is communicating with the same target system. To use this perspective, make sure only one IDE is connected to the target system.

Before you begin

You can perform heap memory profiling to achieve two goals: performance improvements (because heap memory allocation/deallocation is one of the most expensive ways of obtaining memory), and heap memory optimization. The QNX Momentics Memory Analysis tool can assist you with both of these goals.


Note: Before you begin to profile, your application should run without memory errors. You can use the IDE tools to find memory errors. For information about these tools, see Finding Memory Errors.

As mentioned earlier, to capture instrumentation data for analysis, the instrumented kernel (procnto-instr) must be running. This kernel is a drop-in replacement for the standard kernel (though the instrumented kernel is slightly larger). When you're not gathering instrumentation data, the instrumented kernel is almost exactly as fast as the regular kernel.


Note: To determine if the instrumented kernel is running, enter this command:
ls /proc/boot

If procnto-instr appears in the output, then the OS image is running the instrumented kernel.


To substitute the procnto-instr module in the OS image on your board, you can either manually edit your buildfile, then run mkifs to generate a new image, or use the System Builder perspective to configure the image's properties.

Replacing the kernel using the System Builder

  1. In the System Builder Projects view, double-click the project.bld file for the image you want to change.
  2. In the Images pane of the System Builder editor, select the image.
  3. In the Properties view, click the Procnto field (under System). A dropdown-menu button appears in the field:

    Instrumented kernel selection

  4. Select procnto-instr, press Enter, then save your change.
  5. Rebuild your project, then transfer your new OS image to your board.

Assuming you're running the instrumented kernel on your board, you're ready to use the System Profiler. A profiling session usually involves these three steps:

Configuring a target for system profiling

You can gather trace events from the instrumented kernel in two different ways. You can run a command-line utility (e.g. tracelogger) on your target to generate a log file, and then transfer that log file back to your development environment for analysis. Or, you can capture events directly from the IDE using the Log Configuration dialog.


Note: In order to get timing information from the kernel, you need to run tracelogger as the root user.

If you gather system-profiling data through qconn in the IDE, you're already accessing the instrumented kernel as root.


Using the command-line server currently offers more flexibility as to when the data is captured, but requires that you set up and configure filters yourself using the TraceEvent() API. The Log Configuration dialog lets you set a variety of different static filters and configure the duration of time that the events are logged for.

For more information on the tracelogger utility, see its entry in the Utilities Reference. For TraceEvent(), see the Neutrino Library Reference.

Launching the Log Configuration dialog

To launch the Log Configuration dialog:
In the Target Navigator view, right-click a target, then select Log With…-->Kernel Event Trace from the menu. If you don't have the Target Navigator view open, select Window-->Show View-->Other…, and then QNX Targets-->Target Navigator.

Note:

If you don't already have a target project, you'll have to create one.

To create a target project:

  1. In the Target Navigator view, right-click and select New QNX Target.
  2. Specify the required information for your new target.
  3. Click Finish.

You can use this target project for a number of different tasks (debugging, memory analysis, profiling), so once you create it, you won't have to worry about connecting to your target again. Note also that the qconn target agent must be running on your target machine.


Selecting options in the wizard

The Log Configuration dialog takes you through the process of selecting:


 Log Configuration dialog


Capturing event-specific information using kernel logging.

Here are the main fields in this wizard:

Tracing method Type (Period of time)
The duration of the capture of events as defined by a period of time. This is the default.
Tracing method, Period length
A floating-point value in seconds representing the length of time to capture kernel events on the target.
Tracing method, Type (Iterations)
The duration of the capture of events as defined by the number of kernel event buffers.
Tracing method, Number of Iterations
Total number of full kernel event buffers to log on the target.
Trace file, Mode (Save on target then upload)
In this mode, kernel event buffers are first saved in a file on the target, then uploaded to your workspace. This is the default.
Trace file, Filename on target
Name of the file used to save the kernel event buffers on the target.
Trace file, Mode (Stream)
In this mode, no file is saved on the target. Kernel event buffers are directly sent from qconn to the IDE.
Trace statistics file, Mode (Generate only on the target)
The information file is generated only on the target. This is the default.
Trace statistics file, Mode (Do not generate)
No file is generated.

Note: If your target is running earlier versions of QNX Neutrino, you must use this option instead of “Generate only on the target” because the trace statistics file is not supported on versions such as QNX Neutrino 6.2.1.

Trace statistics file, Mode (Save on target then upload)
The statistical information is first saved in a file on the target, then uploaded to your workspace.
Trace statistics file, Filename on target
Name of the file used to save the statistical information on the target.
Buffers, Number of kernel buffers
Size of the static ring of buffers allocated in the kernel.
Buffers, Number of qconn buffers
Maximum size of the dynamic ring of buffers allocated in the qconn target agent.

Capturing instrumentation data in event log files

Regardless of how your log file is captured, you have a number of different options for regulating the amount of information actually captured:

(For more information, see the SAT User's Guide.)

The IDE lets you access the first three of the above filters. You can enable tracing (currently done by activating the Log Configuration dialog), and then select what kind of data is logged for various events in the system.

The events in the system are organized into different classes (kernel calls, communication, thread states, interrupts, etc.). You can toggle each of these classes in order to indicate whether or not you want to generate such events for logging.

 Log Configuration filter dialog

The data logged with events comes in the following modes:

Fast mode
A small-payload data packet that conveys only the most important aspects of the particular event. Better for performance.
Wide mode
A larger-payload data packet that contains a more complete event definition, with more context. Better for understanding the data.
Class Specific
This mode lets you select Disable (no data is collected), Fast, Wide, or Event Specific for each of the following event classes:

Choosing Event Specific lets you select Disable, Fast, or Wide for each event in that class.

Depending on the purpose of the trace, you'll want to selectively enable different tracing modes for different types of events so as to minimize the impact on the overall system. For its part in the analysis of these events, the IDE does its best to work with whatever data is present. (But note that some functionality may not be available for post-capture analysis if it isn't present in the raw event log. ;-))

Importing part of a kernel trace into the Application Profiler

The IDE lets you import only a portion of a kernel trace into Application Profiler; however, you can also continue to import the entire kernel trace, if required. When you use the import action from the System Profiler editor, only the portion of the kernel trace that is currently selected will be imported into the Application Profiler. This means that the Application Profiler only considers a single process from the trace; it chooses the process that is associated with the binary selected by the user.

To import a selected portion of the kernel trace into Application Profiler:

  1. Highlight an area in the Timeline view.
  2. Right-click and select Open with QNX Application Profiler.

     Timeline view menu: Open QNX with Application Profiler

    After you select the menu option, the Import dialog is displayed.

    Importing part of a kernel trace: selecting an executable

  3. In the Executable field, select the executable file you want to associate with the import.
  4. Click Next
  5. If required, in the Source Lookup Path area, select a search path for sources, if the source isn't compiled on the same host.
  6. click Finish.

    The IDE opens the Application Profiler perspective.

Viewing and interpreting the captured data

Once an event file is generated and transferred back to the development host for analysis (whether it was done automatically by the IDE or generated by using tracelogger and manually extracted back to the IDE), you can then invoke the System Profiler editor.

Log files are loaded in a nonmodal activity that you can cancel. This lets you load multiple log files at the same time, and log file data can be normalized as a background task when it's out of order. The view shows data up to the point where the log file was processed.


Note: If you receive a “Could not find target: Read timed out” error while capturing data, it's possible that a CPU-intensive program running at a priority the same as or higher than qconn is preventing qconn from transferring data back to the host system.

If this happens, restart qconn with the qconn_prio= option to specify a higher priority. You can use hogs or pidin to see which process is keeping the target busy, and discover its priority.


The IDE includes a custom perspective for working with the System Profiler. This perspective sets up some of the more relevant views for easy access.

Searches in the System Profiler occur in the background, with results shown as they're found. The results of each search operation are managed separately and are “overlaid” on top of one another, allowing multiple search results to be graphically viewed together in the System Profiler Timeline editor pane.

Timeline view

You can configure the table that's shown in the search result view to show only the interesting trace event fields. The content of this table can be cut and pasted to the system clipboard as CSV-format data.


System Profiler Timeline view


The System Profiler's Timeline view.

Event labels

Timeline event labels let distinguish between different types of events (the label only shows the data for the event and its type). In addition, you can also set the Timeline view to display address translation information, such as function name. By using event labels, you can quickly differentiate between different types of events, or display multiple data values for the same event. The purpose of event labels is to annotate function entry and exit events in the Timeline pane with their corresponding function names.

To access the label options, select the Toggle Labels icon in the System Profiler perspective:

Icon: Toggle Labels for System Profiler Timeline view

The Timeline event label data selection dialog is available by clicking the Toggle labels icon, and then selecting Configuring Event Labels:


System Profiler Timeline view: Set Event Label dialog


Setting event labels in the System Profiler's Timeline view.

The data selection list lets you select multiple data keys. In addition, the dialog lets you define whether you want to customize the display pattern for the corresponding label. By default, a default display pattern is provided and consists of the event type label, followed by a comma separated list of data keys. The display pattern supports the following replacement patterns:

For a list of event data keys specific to address translation, see Address translation.”

The Timeline event preference page and the property page show the new properties of the labels (select Window-->Preferences and then expand QNX-->System Profiler and select Timeline Event labels):


System Profiler Timeline view preferences


Setting preferences for the System Profiler's Timeline view.

Once you specify any event labels, the Timeline view shows the display pattern for the label and displays multiple keys.


System Profiler Timeline view with labels


The System Profiler's Timeline view that includes labels.

In the Preferences dialog, click Edit to edit any existing labels, or click Add to select an event type for which a label had already been defined. Any changes you make change the previously defined label, for which you'll receive a notification message.


Note: The IDE performs kernel tracing events as background tasks. You can monitor the progress of the trace by opening the Progress view.

In the System Profiler editor's Timeline view, you can navigate to the next or previous event for a specific event owner only. This lets you follow a sequence of events generated by a particular set of event owners (for example finding the next event owned by a thread, or the messages generated by a client and server).

In locations where single events have been identified (for example, the Trace Log view, Search Results view), you can navigate directly to the event location in the System Profiler Timeline editor pane by double-clicking. The selection marker is moved to the event location and, if possible, the specific event owner is scrolled into view in the Timeline editor pane.

The Navigate menu contains a Go To Event command that lets you jump directly to a specific event. This command allows developers to collaborate more easily with one another by providing direct event navigation by event index, event cycle, or natural time.


Go to event


The System Profiler's Go To Event command.

These components of the QNX System Profiler are described in detail later in this chapter:

Address translation

You can set your address translation information within the Kernel Event Trace Log launch configuration.


Address translation in Log Configuration dialog


Address translation in Log Configuration dialog.

To enable address translation:

  1. From the Target Navigator view, select a target, right-click, and select Log With-->Kernel Event Trace.
  2. For a Kernel Event Trace configuration, select the Address Translation tab.
  3. Select Enable address translation, and then click Apply.

The address translation Binary Locations lets you specify the search locations to use for your binaries.

The Binary Mappings tab lets you specify the name of your binary (it will use the default load address). Click Add Binary to manually provide a binary name if your binary is not found. If you click Import, the Address Translation's pidin mem import lets you import only binaries that are contained within the defined binary search paths.


Note:

You can use the output from pidin to populate the binary mappings. The output will help you determine the load addresses of any libraries your application is using. To use this output, while your application is running, run the pidin command with the mem option, and output the results to a file (i.e. pidin mem > pidin_results). Use the Import button to select the results file.

For Address translation (for interrupt IP events), the log file must be matched with the binary files in your workspace for address decoding to occur.

When a new kernel trace that contains address translation information is generated using Kernel Event Trace logging, the kernel trace automatically contains the address translation information. If you launch an application using a launch configuration that has the Kernel Logging tool enabled, the address translation information for the generated kernel trace comes from the settings of the Kernel Event Trace configuration (specified by the Kernel Logging tool). Additionally, address translation information for the binary being launched will be added to the kernel trace (set using Window-->Preferences, and then select QNX-->System Profiler-->Address Translation Configuration).


Trace event labels for address translation

The Trace Event Label selection dialog includes address translation related keys (select System on the Select Event Data Key dialog) for Function Entry and Function Exit events. These address translation keys are:

Automatic discovery of library addresses

Address translation allows for the automatic discovery of library load addresses by analyzing the log file for events. By default, the Add Library dialog in the Address Translation dialog lets you specify that the library address should be discovered automatically. When kernel logging is used in conjunction with a C/C++ launch configuration and the Application Profiler tool, address translation for the generated kernel trace will have address translation information.


Address translation: Add Library dialog


Address translation: adding a library.

If you open a log file that has address translation information with libraries set to auto-discover, the log file will be analyzed and the library addresses determined for address translation. If library addresses are discovered, they're persisted to the trace log so that the lookup doesn't occur the next time you open the log. If the auto-discovery of library addresses isn't successful (i.e. generation of MMAPNAME events was disabled in the kernel trace log launch configuration), you'll receive a warning that you'll need to manually set this information.

You have the option to disable the warning, or by using the System Profiler address translation preference page (set using Window-->Preferences, and then select QNX-->System Profiler-->Address Translation Configuration, and set the option Provide a warning if address translation auto-discovery fails while opening a trace log):


Address translation Preferences dialog


Setting preferences for address translation.

The libraries associated with the launch are also added to the address translation, along with the binary. These libraries will be set to auto-discover, meaning that under most scenarios when running a C/C++ launch in combination with the Application Profiler and System Profiler tools, address translation will automatically function without requiring user intervention.

Trace Search panel

Invoked by Ctrl-H (or via Search-->Search…), this panel lets you execute more complex event queries than are possible with the Find dialog.

You can define conditions, which may include regular expressions for matching particular event data content (e.g. all MsgSend events whose calling function corresponds to mmap()). You can then evaluate these conditions and place annotations directly into the System Profiler editor. The results are shown in the Search view.

Unlike the other search panels in the IDE, the Trace Search panel can search for events only in the currently active System Profiler editor. You use this search panel to build conditions and then combine them into an expression. A search iterates through the events from the active log file and is applied against the expression; any “hits” appear in the Search Results view and are highlighted in the System Profiler editor.

By default, the Trace Search panel returns up to 1000 hits. You can change this maximum in the Preferences dialog (choose Window-->Preferences-->QNX-->System Profiler).

Properties view

This view shows the properties for selected objects.

This Properties view will show information about the log file that was captured, such as the date and time, as well as the machine the log file was captured on.

Filtering a profile

The IDE lets you filter profile data so that you can look at a subset of the captured information. You can specify filtering on the following items:

To filter profile data:

  1. After you've begun running your process(es) and started kernel logging for a project, you can select System Profiler-->Display-->Switch Pane-->Timeline to change to the Timeline editor state.
  2. Right-click on the Timeline canvas and select Filter.
  3. Specify your desired filtering options on the following tabs:

Notice that the Timeline will dynamically change (for the specified time range) based on the filtering selections you make.

Using Function Instrumentation mode with the System Profiler

You can use the data from the Function Instrumentation mode in System Profiler. For information about the benefits of using Function Instrumentation mode and for instructions about using this feature, see Using Function Instrumentation in the System Profiler.”

Associated views

The QNX System Profiler perspective includes the following views:

Filtering using partitions

The IDE includes partition-based filtering that lets editor panes and views support filtering to show only data related to the partitions that you select. If a pane or view supports filtering, The IDE updates the display as the filters change.


Partition filtering


Using partition filters to filter data based on selected partitions.

Filtering in Statistics views

The statistics views (such as General Statistics view, Client/Server CPU Statistics view, Condition Statistics view, and Event Owner Statistics view ) support filtering based on selected items in the Filters view. You can toggle an option to indicate whether filtering should take place. The IDE updates the Status Bar to indicate whether the results are being filtered.

System Profiler editor

In order to start examining an event file, the easiest way is to name it with a .kev (kernel event) extension. Files with this extension are automatically bound to the System Profiler editor.

The System Profiler editor is the center of all of the analysis activity. It provides different visualization options for the event data in the log files:


System Profiler editor


The System Profiler editor.

The System Profiler editor panes include the following:

Summary pane (the default)
Shows a summary of the activity in the system, accounting for how much time is spent processing interrupts, running system- or kernel-level code, running user code, or being idle.

The IDE generates an overview of the CPU and trace event activity over the period of the log file. This overview contains the same information displayed in the Overview view.

The process activity (amount of time spent RUNNING or READY, number of kernel calls) displayed in the Summary pane contains the same information as can be extracted by drilling down for a particular time range of the event log using the General Statistics view and the Event Owner Statistics view

CPU Activity pane
Shows the CPU activity associated with a particular thread or process. For a thread, CPU activity is defined as the amount of runtime for that thread. For a process, CPU activity is the amount of runtime for all of the process's threads combined.
CPU Migration pane
Show the potential performance problems that are associated with multiple-CPU systems.
CPU Usage pane
Show the percent of CPU usage associated with all event owners. CPU usage is the amount of runtime that event owners get. CPU usage can also be displayed as a time instead of a percentage.
Inter CPU Communication pane
Show CPU communication analysis for multi-core systems.
Partition Summary pane
Show adaptive partition usage and summary information.
Timeline pane
Show events associated with their particular owners (i.e. processes, threads, and interrupts) along with the state of those particular owners (where it makes sense to do so).

The Summary pane is on by default. To choose one of the other types, right-click in the editor, then select Display-->Switch Pane, or click this icon:

Switch to the next display type

You can choose a specific display type from the dropdown menu associated with this menu item or icon.

For the CPU Activity pane is not customizable. The CPU Usage pane is configurable (the graph types are line and area) by selecting Window-->Preferences-->QNX-->System Profiler-->CPU Usage.

3D versions of each chart are also available.

Each of these visualizations is available as a “pane” in a stack of “panes.” Additionally, the visualization panes can be split — you can look at the different sections of the same log file and do comparative analysis.

All panes of the same stack share the same display information. A new pane inherits the display information from the previous pane, but becomes independent after it's created.

To split the display, right-click in the editor, then select Display-->Split Display, or click this icon:

Split display

You can lock two panes to each other. From the Split Display submenu, choose the graph you want to display in the new pane, or click this icon:

Toggle Lock


Note: You can have a maximum of four panes displayed at once.

For the Timeline pane, a number of different features are available from within the editor:

Event owner selection
If you click on event owners, they're selected in the editor. These selected event owners can then be used by other components of the IDE (such as Find).

If an owner has children (e.g. a parent process with threads), you'll see a plus sign beside the parent's name. To see a parent's children, click the plus sign.

Filters
You can use the Filters view to filter out event owners, specific events, and by partitions. This lets you significantly cut down on the unwanted event “noise” that appears in the display. You can then save a new version of the log file (using Save As) to produce a smaller, more succinct log file for further examination.

For example, to view only processes that are sending pulses, choose Window-->Show view-->Other-->QNX System Profiler-->Filters to open the Filters view. Select the Events tab, and then replace type filter text with MsgSend. Click Deselect All, and then click the applicable MsgSend events that your search found. The selected events are added to your display dynamically.

Find
Pressing Ctrl-F (or selecting Edit-->Find/Replace) opens a dialog that lets you quickly move from event to event. This is particularly useful when following the flow of activity for a particular event owner or when looking for particular events. The Class and Code fields are filled with the values from the currently selected event in the Timeline pane.
Bookmarks
You can place bookmarks in the timeline editor just as you would to annotate text files. To add a bookmark, click the Bookmark icon in the toolbar (Add bookmark), or right-click in the editor and choose Bookmark from the menu.

These bookmarks show up in the Bookmarks view and can represent a range of time or a single particular event instance.


Bookmarks view


Cursor tracking
The information from the System Profiler editor is also made available to other components in the IDE such as the Trace Event Log view and the General Statistics view. These views can synchronize with the cursor, event owner selections, and time ranges, and can adjusts their content accordingly.
IPC representation
The flow of interprocess communication (e.g. messages, pulses) is represented by a vertical arrow between the two elements.

You can toggle IPC tracing on/off by clicking this button in the toolbar:

IPC tracing button

By default, this displays the IPC trace arrows for all event owners. You can choose to display only the arrows for the selected owners by choosing Selection from the button's dropdown menu.

Display Event Labels
The Display Event Labels button in the toolbar (Display Event Labels) lets you display labels in the timeline; open the button's dropdown menu and select the type of labels you want to display:

If you haven't expanded a process in the display, the labels for all of its threads are displayed. By default, no labels are displayed.

Display Event Labels

Types of selection

For the Timeline pane, within the editor you can select either of the following:

Owners

To select a single owner, simply click the owner's name. To unselect an owner, press and hold the Ctrl key, then click each selected owner's name.

To select multiple owners, press and hold the Ctrl key, then click each owner's name.

Time

To select a point in time, click an event on the timeline.

To select a range, click the start point on the timeline, then drag and release at the end point.

Or, select the start point, then hold down the Shift key and select the end point.

Zooming

When zooming in, the display centers the selection. If a time-range selection is smaller than the current display, the display adjusts to the range selection (or by a factor of two).

When zooming out, the display centers the selection and adjusts by a factor of two.

When using a preset zoom factor (100% to 0.01%), the display centers the current selection and adjusts to the new factor.

There are various ways to zoom:

Scrolling

You can use these keys to scroll through time:

To move: Use this key:
The selection to the left by one event Ctrl-
The selection to the right by one event Ctrl-
The display to the left
The display to the right
The selection for the current owner to the left by one event Ctrl-Shift-
The selection for the current owner to the right by one event Ctrl-Shift-

You can use these keys to scroll through the owners:

To move the display: Use this key:
Up by one owner
Down by one owner
Up by one page (horizontal scrollbar thumb size) Page Up
Down by one page (horizontal scrollbar thumb size) Page Down
To the top of the owner list Home
To the bottom of the owner list End

Hovering

When you pause your mouse pointer over an owner or an event, you'll see relevant information (e.g. PID, timestamps, etc.).

Bookmarks view

Just as you can bookmark lines in a text file, in the System Profiler editor, you can bookmark particular locations and event ranges displayed, and then see your bookmarked events in the Bookmarks view.

Client/Server CPU Statistics view

The Client/Server CPU Statistics view (Window-->Show View-->Other…-->QNX System Profiler-->Client/Server CPU Statistics) tracks the amount of client/server time spent in the RUNNING state. In a message-passing system, it may be that a particular thread is consuming a large amount of CPU time, but that CPU time is being consumed based on requests from one or more clients. In these cases, in order to achieve a higher performance, the client requests on the server must be reduced (assuming that the server is identified as a bottleneck).

This panel provides a tabular display of threads that spend time in a RUNNING state (slightly different from pure CPU usage) and breaks down the display such that for each thread there is a summary of how much time it spent directly in the RUNNING state and how much RUNNING time it “imposed” on other threads in the system and the total of those two times.


Client/Server CPU Statistics view


The System Profiler's Client/Server CPU Statistics view.

You can expand the table, via the View menu, to show how much time the client imposed on various server threads. The imposed time is cumulative: if client A sends to server B, then until B replies to A, any time that B consumes is seen as “imposed on” time. If during that time B sends to server C, then server C is also billed time as “imposed on” by A. The rationale here is that B would not have engaged with server C were it not for the initial message from A.

By sorting by imposed time, it is possible to identify which clients are predominantly driving the system and which servers may be bottleneck points.

Condition Statistics view

This view provides a tabular statistical representation of particular events. The statistics can be gathered for the entire log file or for a selected range.

When you first open the Condition Statistics view, it contains no data:

Initial Condition Statistics view

You must configure conditions and the table to view condition statistics.

Configuring conditions

To configure conditions for the Condition Statistics view:

  1. Click the Configure Conditions… button, or select Configure Conditions… from the view's dropdown menu (Menu icon). The IDE displays the Modify Conditions dialog.

    Modify Conditions

  2. Click Add to open the Trace Condition Wizard. The IDE displays the Trace Condition Wizard dialog:

    Trace condition definition

  3. Give your condition a unique name and select the appropriate class and code. For example, select Process and Thread from the Class dropdown menu, then select Mutex under the Code dropdown menu.
  4. Click Finish.
  5. Click OK in the Modify Conditions dialog.
  6. Click the Configure Table Condition Contents (Configure Table Condition Contents) button, or choose Configure Table... from the view's dropdown menu.

    The IDE displays the Condition Selection dialog:

    Condition Selection

  7. Add a check mark beside the conditions that you want to list in the table.
  8. Press OK to confirm your selections.

Note: You'll need to click the Refresh button (Refresh) to populate this view with data.

CPU Migration pane

The CPU Migration pane provides a display that draws attention to some of the potential performance problems that are associated with multiple-CPU systems.


CPU Migration pane


The System Profiler's CPU Migration pane.

There are two migration details that are currently charted over the period of the log file:

This pane contains valid data only when the log file contains events from a system where there are multiple CPUs.

Event Owner Statistics view

This view provides a tabular statistical representation of particular events. The statistics are organized and detailed by event owner.


Note: You'll need to click the Refresh button (Refresh) to populate this view with data.

Event owner statistics

General Statistics view

This view provides a tabular statistical representation of particular events, and statistics regarding states. The statistics can be gathered for the entire log file or for a selected range.

System Profiler General Statistics view


Note: You'll need to click the Refresh button (Refresh) to populate this view with data.

Raw Event Data pane

The Raw Event Data view (Window-->Show View-->Other…-->QNX System Profiler-->Raw Event Data) lets you examine the data payload of a particular selected event. It shows a table of event data keys and their values. For example if an event is selected in the Trace Log view, rather than attempting to look at all of the data in the single line entry, you can open the Raw Event Data view to display the data details more effectively.


Raw Event Data view


The System Profiler's Raw Event Data view.

Overview view

The Overview view (Window-->Show View-->Other…-->QNX System Profiler-->Overview) shows two charts spanning the entire log file range.


Overview view


The System Profiler's Overview view.

These charts display the CPU usage (per CPU) over time and the volume of events over time. The Overview reflects the current state of the active editor and active editor pane. You can select an area of interest in either one of the charts; then, using the right-click menu, zoom in to display only that range of events to quickly isolate areas of interest due to abnormal system activity.

Partition Summary pane

The Partition Summary pane provides a summary of the entire log file, focused on QNX's adaptive partitioning technology. For each distinct configuration of partitions detected in the log file, the distribution of CPU usage used by those partitions is displayed, along with a tabular display showing the distribution of CPU usage per event owner per partition.

You can use this information in conjunction with the CPU Usage editor pane to drill down into areas of interest. This pane contains valid data only when the log file contains partition information, and the process and thread states are logged in wide mode (so the partition thread scheduling information is collected).


Partition Summary pane


The System Profiler's Partition Summary pane.

You can also get snapshots of the usage of the adaptive partitioning on your system through the System Information perspective's Partition Summary view. For more information, see the Getting System Information chapter.

Notice that this pane displays its summary information based on a time range selection specified in the Timeline pane. At the bottom of the pane, the Status Bar indicates for which time range the data is being presented. By default, you'll see partition information for the full event log range; however, you can use the toggle button in the toolbar of the pane to indicate that you want the information filtered for a specified range.


Note: Since the calculations in the Partition Summary pane are intensive, you'll need to use the Refresh button to update the statistics each time you change the toggle, or adjust the range in the Timeline pane.

Thread State Snapshot view

In addition to asking why a particular process's thread may be running, developers are often faced with the task of understanding what the rest of the system is doing at a particular point in time. This question can easily be answered using the Thread State Snapshot view (Window-->Show View-->Other…-->QNX System Profiler-->Thread State Snapshot).

Thread State Snapshot view, is keyed off of the current cursor position in the System Profiler editor Timeline pane. For a given time/position, it determines the state of all of the threads in the system.


Thread State Snapshot view


The System Profiler's Thread State Snapshot view.

Note that when you select a point in the Timeline, you must click the Refresh icon in the Thread State Snapshot view's toolbar to update the contents of the Thread State Snapshot view .

Timeline State Colors view

You can use the Timeline State Colors view (Window-->Show View-->Other…-->QNX System Profiler-->Timeline State Colors) if you're unfamiliar with the System Profiler timeline editor pane state colorings, or if you'd like to change the color settings to something more appropriate for your task.

The view displays a table with all of the color and height markers that are used when drawing the timeline display. These settings can be bulk imported and exported using the view's dropdown menu based on particular task requirements. The default settings generally categorize states with similar activities together (synchronization, waiting, scheduling, etc.).


Timeline State Colors view


The System Profiler's Timeline State Colors view.

Trace Event Log view

This view can display additional details for the events surrounding the cursor in the editor. The additional detail includes the event number, time, class, and type, as well as decoding the data associated with a particular event.

System Profiler Trace Event Log

To set the format for event data, select Windows-->Preferences, expand QNX, and then select User Events Data.

The following is an example of an event configuration file that has been documented to describe it's contents:

<?xml version="1.0" encoding="UTF-8" ?>

<!--
  Root tag for the event definition file format
-->
<eventdefinitions>

 <!--
  Events definitions are broken down by the event class.
  The user event class is '6' (from <trace.h>); all event codes
  in this section are part of this event class.
 -->
 <eventclass id="6" name="User Events"<

  <!--
    The user event we want to describe is coded as event #12 within
    the user event class (6).  It is composed of a single 4 byte
    (32 bit) unsigned integer that is followed by a null terminated
    string.  In C the structure might look something like:

     struct event_twelve {
      uint32_t myvalue;
      char     mystring[28];    /* Null Terminated */
     };

    And be emitted using code:

     stuct event_twelve event;
     ... /* Fill event */
     TraceEvent(_NTO_TRACE_INSERTCUSEREVENT, 12, &event, sizeof(event));

  -->   
  <event id="12" sformat="%4u1x myvalue %1s0 mystring" />

  <!--
    In general an event is described as a serial series of event
    payload definitions:

      %<size><signed><count><format> <label>

    Where:
      <size>  
        Is the size in bytes (1,2,4,8)
      <signed>
        Is the signed/unsigned attribute of the value (s,u)
      <count>
        Is the number of items to read (ie an array).  There is a
        special case where if the <size> is 1 and there is _NO_
        format then the <count> can be 0 to accomodate NULL
        terminated strings.
      <format> (optional)
        Is a hint as to how to format this value: d=decimal,
        x=hexadecimal, o=octal, c=character 
      <label>
        Is a string label that can't contain the % character
  -->

 </eventclass>
</eventdefinitions>

Why Running? view

The Why Running? view (Window-->Show View-->Other…-->QNX System Profiler-->Why Running?) works in conjunction with the System Profiler timeline editor pane to provide developers with a single click to answer the question “Why is this thread running?” where “this thread” is the actively executing thread at the current cursor position.

By repeating this action (or generating the entire running backtrace) developers can get a clearer view of the sequence of activities leading up to their original execution position. Not to be confused with an execution backtrace, this “running backtrace” highlights the cause/effect relationship leading up to the initial execution position.


Why Running? view


The System Profiler's Why Running? view.

System Profiler use cases

This section describes some cases where you'd use the System Profiler:

Locating sources of high CPU usage

You might want to know where in time your CPU cycles are being consumed and who is doing the consuming. The System Profiler provides several tools to help extract this information and “drill down” to quickly and easily determine the source and distribution of CPU consumption.

Requirements

To extract CPU usage metrics using the System Profiler tools, the captured log file must contain at a minimum, the Neutrino RUNNING thread state. If the RUNNING thread state is logged in wide mode, then additional information regarding CPU usage distribution over priority and partitions can also be calculated.

In order to determine the CPU load caused by interrupts, you must also log the Interrupt Entry/Exit events.

Procedure

To start, open the target log file in the System Profiler editor. By default, the initial view should show the Summary editor pane; if this isn't the case, then you can get to the Summary editor pane via the menu item System Profiler-->Display-->Switch Pane-->Summary.

The Summary editor pane shows a high-level overview of the log file contents:

Summary editor

The System Activity section shows the distribution of time spent in the log file, separated into these categories:

Idle
The amount of time that the idle thread(s) spent running in this log file.
Interrupts
The amount of time that has been spent servicing hardware interrupts in this log file.
Kernel
The amount of time that has been spent making kernel calls (measured between kernel entry and exit events). This time doesn't include any of the time spent handling hardware interrupts.
User
The amount of time that non-idle threads spend in the Neutrino RUNNING state, minus the time spent performing kernel calls or in interrupt handlers.

Using these metrics, you can get a rough estimate of how efficiently your system is performing (e.g. amount of idle time, ratio of system to user time, possible interrupt flooding).

The distribution of CPU usage over the time of the entire log file is shown graphically in the Process & Thread Activity section overlaid with the volume of events that have been generated. This same data is also available as the Overview view accessed via Window-->Show View-->Other …-->Overview.

System Profiler: CPU activity

The peaks of these results indicate areas of particularly intense CPU usage and are the areas of most interest.

To focus on the particular threads that are causing these spikes, switch the editor display pane to the CPU Usage editor pane. You can do this via the menu item System Profiler-->Display-->Switch Pane-->CPU Usage or by using the editor pull down.

The CPU Usage editor display charts the CPU usage of consuming elements (threads and interrupts) over time and provides a tabular view showing the sum of this usage categorized by CPU, priority, or partition.

System Profiler: CPU usage

By selecting multiple elements in the table, you can “stack” the CPU usage to see how threads and interrupts are interacting. For example, selecting the first few non-idle CPU consumers in this example provides the following result:

System Profiler: nonidle CPU users

By selecting a region of the display, you can zoom in to the area of interest to further drill down into selected areas to better examine the profile of the CPU execution. As the display zooms in, the editor panel's time bar is updated to show the new range of time being examined.

System Profiler: zooming in

This example has shown the CPU usage for process threads, but this technique applies equally well to individual interrupt handlers, which show up as CPU consumers in the same manner as threads.

The CPU Usage editor pane lets you isolate and assign CPU consumption behavior to specific threads very quickly and easily. With this information, you can generally use a more specialized, and application centric, tool such as the Application Profiler to look more closely at execution behavior and to drill down directly to the application source code.

Mapping and isolating client CPU load from server CPU load

There are many cases where high CPU load is traced back to server activity. However, in most cases what is required to reduce this CPU load isn't to make the servers more efficient, but to look more closely at the client activity that is causing the servers to run.

Requirements


Note: Make sure you've read and understood Locating sources of high CPU usage before examining this use case.

In addition to the Neutrino RUNNING thread state, the log must contain the communication events SEND/RECEIVE/REPLY|ERROR. These communication events are used to establish the relationship between clients and servers.

Procedure

QNX Neutrino systems rely heavily on client/server communications most often performed via message passing. In these systems, clients send requests to servers asking them to do work on their behalf such as shown:

System Profiler: servers and clients

Here, A's real CPU usage would be considered to be 2 units of time, B's as 10, and C's as 2 units of time. Since B and C are both acting as servers, they really execute only when there are clients generating requests for action. Most standard CPU Usage metrics don't take this type of “on behalf of” work into consideration. However, if the goal of a kernel log file investigation is to locate the source or sources of CPU load, then this type of metric is invaluable in assigning “blame” for high CPU usage.

The System Profiler provides the Client/Server CPU Statistics view to help extract this type of “on behalf of” metric. You can activate this view via the Window-->Show View-->Other…-->Client/Server CPU Statistics.

Once activated, the Client/Server CPU Statistics are gathered on demand, by default, targeting the full range of the target log file:

System Profiler: Gather statistics

The default display of this view shows the simplified view that displays the RUNNING time (slightly different from the CPU Usage in that it doesn't remove the time spent interrupted by interrupt handlers) that CPU consumers are consuming directly, indirectly, and summed together as a total:

System Profiler: RUNNING time

In this case, it's clear that while the qconn- Thread 1 isn't consuming much CPU on its own, it's imposing a significant amount of time on the system indirectly. If you compare this data to what the CPU Usage editor pane displays, you'll see the difference in what's reported:

System Profiler: qconn Thread 1

In the CPU Usage table, procnto- Thread 8 ranks ahead of qconn- Thread 1 in its usage. However, procnto is a pure server process, so we know that it consumes no CPU resources without being solicited to do so. We suspect that perhaps qconn- Thread 1 is driving procnto- Thread 1.

We can confirm this suspicion by looking at which servers qconn- Thread 1 is imposing CPU usage on. You can configure the Client/Server CPU Usage view to display all of the CPU consumers that are being imposed on (and by whom) by selecting Show all times from the view's dropdown menu:

System Profiler: Show all times

The Client/Server CPU Usage view table changes to show all of the imposed-on servers that clients are communicating with. The servers are listed in the columns and the clients in the Owner column. Note that this may result in a table with many columns (imposed on servers):

System Profiler: imposed-on servers

Here we can see that in fact nearly all of the time that procnto- Thread 8 is spending consuming CPU is due to requests coming from qconn- Thread 1, with only a minimal amount being imposed on it by another qconn thread, qconn- Thread 6.

This is to be expected, since in order to query the system, the qconn process must communicate with the kernel to extract the system state and all the process and thread information.

Examining interrupt latency

There are several different types of interrupt latency that you can measure in a system:

The System Profiler, as a type of software logic analyzer, helps you look at the timing of activities once the interrupt has been acknowledged by the operating system. In order to accurately measure the time between the signal generation and the acknowledgment of it, you need additional hardware tools.

Requirements

To measure interrupt service time (the time taken for the operating system to acknowledge the interrupt, handle it, and return to normal processing), you must log the Neutrino Interrupt Entry/Exit events.

If you're interested in the time from the operating system's acknowledgment to a service handling routine, then you also need to capture the Interrupt Handler Entry/Exit events in the log file.

To properly gauge the latency in triggering a response in user code, you should also log the Neutrino thread READY and RUNNING states, in addition to the communication PULSE events, since these are often used to trigger a user application's behavior in response to an interrupt.

Procedure

Interrupt activity is best viewed in the System Profiler editor using the Timeline editor pane. Open the target log file in the System Profiler editor. Switch to the Timeline editor pane via the menu item System Profiler-->Display-->Switch Pane-->Timeline.

You should see a display that resembles the following. The details will of course be different, but the layout similar:

System Profiler: Timeline editor

This display shows the various event owners/sources (interrupts, interrupt handlers, processes and threads) as a tree with their associated events arranged horizontally as a timeline.

If you've logged Interrupt Handler Entry/Exit events, then you should be able to expand the interrupt entries to show the various handlers (more than one handler can be attached to service an interrupt source), such as the following:

System Profiler: interrupt handlers

Here you can see that the io-pkt process has attached to Interrupt 0x8c and that procnto has attached to Interrupt 0x800000000, which on this system is the timer interrupt firing once every millisecond or so.

You can determine how many interrupt events are occurring in this log file by using the General Statistics view. This view is part of the default System Profiler perspective, and you can also access it via Window-->Show View-->Other…-->General Statistics.

System Profiler: Refresh statistics

If you use the refresh button, this view extracts the event statistics for the entire log file (default), or for only a selected area if specified. This results in the following display:

System Profiler: entire log file

This table provides a breakdown for all of the event sources, showing the number of raw events and also the maximum, minimum, average, and total duration of the various Neutrino thread states in this log file.

If you're interested in only the events associated with the timer interrupt (Interrupt 0x80000000), you can select that event owner in the Timeline editor pane:

System Profiler: timer interrupt

Next, uncheck the Show statistics for all elements check box at the bottom of the General Statistics view:

The General Statistics view tables will show the content limited to just the selected event owners.

Using this technique, you can get an estimate of the rough order of magnitude of how many events you're looking at in a log file, and in the case of interrupts, you can see some of the statistics about what the maximum, minimum, average, and total times spent were.

This display also lets you drill down further into the results, by allowing navigation in the Timeline editor pane directly to the maximum and minimum times, where you can look at the exact timing sequences. To do this, select one of the entries in the States table, and then right-click or use the toolbar to jump to the appropriate selection.

In order to look at the timing sequence of an interrupt, you usually have to zoom in on the timeline a significant amount to achieve an adequate level of visual detail, since interrupt processing is typically fast compared to the length of the log files. If you zoom into an area where a networking interrupt is being processed, the Timeline editor pane will change to look something like:

System Profiler: interrupt details

At this level of granularity, it also helps to see the trace event log concurrently with the Timeline editor pane. This is part of the standard System Profiler perspective, and you can access it using Window-->Show View-->Other…-->Trace Event Log. The Trace Event Log and the Timeline editor pane are synchronized; when you change your cursor in the editor, the selection in the Trace Event Log view also changes.

System Profiler: synchronizing

The selection synchronization is shown here. In the Trace Event Log view, we've selected the Interrupt 0x8c Entry event through to the Interrupt 0x8c Exit event. This represents the start to end of the processing of the interrupt event. In the timeline display, this selection is made and the timing measurement of 11.304 microseconds is displayed:

System Profiler: timing measurement

So the total interrupt handling time from start to end of the operating system interrupt service routine, including the event handler was 11.304 microseconds. If you want to just look at the handling time for interrupt handler attached by the io-pkt process, you can see that this time is only 8 microseconds. These times represent the earliest and latest points in time that can be measured before entering/exiting control of the software.

You can also see in this example that the io-pkt interrupt handler is returning a pulse that's triggering something in the user's application (event 13515) and that an io-pkt thread is then scheduled to service that request. You can also measure this latency to determine how long it takes to go from operating system awareness of the interrupt to eventual application processing, using the same selection technique:

System Profiler: interrupt latency

There are many different choices in terms of what time ranges are of interest to measure. Here we've decided to measure from the time that the operating system is aware of the interrupt (event 13511) through to the point at which the user process has started to respond to the signal generated by the io-pkt interrupt handler. Since the interrupt handler communicates using a pulse (event 13515), then the earliest that the user code can respond is when the MsgReceive() kernel call exits (event 13519) with the received pulse. In this case, we can see that the end-to-end latency from OS awareness to the start of user processing (nonprivileged) is 46.304 microseconds:

System Profiler: timing measurement

Alternate measurements that could be of interest and that you can easily examine include:

Locating Events of Interest

Trace event log files contain a wealth of information, but unfortunately that information is often buried deep in among thousands, if not millions, of other events. The System Profiler tooling helps provide tools to reduce and remove some of this “noise” to help you focus on the areas of a log that are important to you.

Requirements

There are no specific requirements for this use case, but some of the topics may not apply, depending on the types of events that have been captured.

Procedure

We'll walk through some of the tools available to help you to reduce and filter the data contained in a trace event file. Where this information is most useful is during investigations involving the Timeline editor pane. The timeline displays information with a very fine granularity and is often the display that users turn to in order to “single step” through the execution flow of an activity of interest. To open the Timeline editor pane, select System Profiler-->Display-->Switch Pane-->Timeline.

Timeline editor pane filters

The first level of data reduction is to use the Filters view to remove information that isn't significant for the tracing of the problem you're interested in. By using filters in conjunction with zooming and searching capabilities, you can quickly reduce the overall data set.

The Filters view is synchronized with the active System Profiler editor; you can display it via the menu Window-->Show View-->Other…-->Filters or by right-clicking Filters… in the Timeline editor pane.

This view provides you with the following types of filtering:

Select the context menu in the Filters view to access additional filter options. Select Configure Filters… from the Filters view menu to configure the filters for System Profiler.


System Profiler: Configure filters


Configuring filters for System Profiler.

The Configure System Profiler Filters dialog provides a listing of preconfigured filters that are available for use. These filters are often based on more sophisticated criteria for determining if events, event owners, or partitions are to be displayed.

Trace event log filter synchronization

By default, the Trace Event Log view presents a display that uses the same filters as the currently active editor. However, there are times when it's useful to be able to temporarily “unfilter” the Trace Event Log view display to see the raw content of the log file. You can accomplish this by toggling the editor's Synchronize button on the Trace Event Log view display:

System Profiler: Trace Event sync

Timeline “find”

There are times when you're looking at an event stream and want to quickly navigate through it. One mechanism for doing this is to move to the next or previous event, using the toolbar commands (Next, Previous, Next Event In Selection, Previous Event In Selection).

Another, more flexible, alternative is to use the Find functionality of the Timeline editor pane. Selecting Edit-->Find/Replace opens a dialog similar to the one found in many text editors:

The dialog supports searching a restricted set of event owners (based on the selection made in the Timeline editor pane) as well as searching forwards and backwards through the log file. This is convenient when you know specifically what type of event you're looking for in a sequence of events (e.g. the next RUNNING state for a thread).

The Find dialog moves the selection marker in the Timeline editor pane to the appropriate event.

Trace Search

If you need to generate a collection of events matching a particular condition, or you need to construct a more complicated expression (perhaps including event data) in order to find the events you're looking for, you need the power of trace event conditions and the Trace Search tool.

The Trace Search tool is invoked via the menu item Search-->Search. Opening this up presents a dialog similar to the following:

System Profiler: Search dialog

Searching is based on trace conditions. Trace conditions describe a selection criterion for matching an event and can be based on anything that an event provides (ownership, data payload, and so on).

To add a condition that will locate all of the MsgSend() calls that may have been made for write system calls:

  1. Add a new condition via the Add button in the search dialog. This brings up a new condition dialog that you can fill in with the MsgSendv() kernel call and the write() function entry to match. When matching string values (such as function names), the matching is done based on a regular-expression match.

    System Profiler: Trace Condition wizard

  2. Once you've defined the condition, it shows up in the Defined Conditions table shown in the Trace Search panel. You can combine individual conditions to form Boolean expressions if required.

    System Profiler: Defined conditions

  3. Specifying the newly created condition in the Search Expression drop-down and selecting Search automatically opens up the Search Results view. If the Timeline editor pane is open, double-clicking on a search result (assuming that the result isn't filtered) moves the timeline selection directly to that event:

    System Profiler: Search results

Search results are also marked in the timeline to help show the event distribution over the period of the log file:

System Profiler: search results on the timeline

Exporting filtered log files with Save As

Often the kernel event files that are captured are large and contain a significant amount of nonessential data for the problem at hand. Of course, this is generally only determined after the fact, once you've performed some basic analysis.

You can use the File-->Save As menu command to create a new log file that's based on the current log file in the System Profiler editor.

You can restrict the new log file to just the selected area (if you've made a selection), and you can also use the current filter settings (event and event owner) to reduce the amount of additional data that's stored in the log file.

The new log file contains the same attribute information as the original log file (including the system version, system boot time, number of CPUs, and so on). Any event owners, such as interrupts, processes, and threads, which are referenced by events in the new log file, are synthetically created with timestamps matching the start time(s) of the new log file.


Warning: main(/www/www/htdocs/style/footer.php) [function.main]: failed to open stream: No such file or directory in /www/www/docs/6.4.1/ide_en/user_guide/sysprof.html on line 2677

Warning: main() [function.include]: Failed opening '/www/www/htdocs/style/footer.php' for inclusion (include_path='.:/www/www/common:/www/www/php/lib/php') in /www/www/docs/6.4.1/ide_en/user_guide/sysprof.html on line 2677