System Profiler editor

When you open a kernel event log file, whether you're prompted by the IDE after a kernel event trace finishes or you manually open a file copied into your workspace, the IDE uses the System Profiler editor to visually present the file's data.

Note: Due to the large amount of data generated by kernel tracing, the IDE can't display data while tracing is in progress. The System Profiler editor is used to show kernel event details gathered during the trace only after it's finished.

The editor lets you examine the captured events through numerous panes, which visualize event data in different ways. Initially, the editor displays the Summary pane, which shows general trace statistics such as CPU time breakdown. But you can open another pane by clicking the Switch Pane dropdown in the upper right controls (Icon: Switch Pane dropdown) and selecting an option. Or, you can right-click in the editor and select Display > Switch Pane and then a particular pane.

You can display more than one pane at a time by using the Split Display dropdown (Icon: Split Display dropdown). This is useful for looking at different sections of a log file and doing comparative analysis. When you click the name of a pane that's not currently displayed, the IDE opens it. You can open up to four panes, although it can be hard to read statistics when that many are displayed. The right-click menu has an equivalent submenu, Display > Split Display, as well as the Display > Switch Orientation option, which lets you alternate between stacking the panes horizontally or vertically.

With the split display, any newly opened pane displays data based on the same events selected in the previously opened one. But the pane becomes independent right away, meaning you can change the zoom level or highlight a timeframe in its display without affecting the events selected in other panes.

If you want to synchronize the selection in multiple panes, click the Toggle Display Lock button (Icon: Toggle Display Lock button) in each one, or choose Display > Lock Pane from the right-click menu; for convenience, this menu also has the Display > Lock All Panes option. After you do this, any timeframe selection or zooming that you do in one pane automatically updates the display in the other locked panes.

To close a pane, click the close button (Icon: Close Pane button) or choose Display > Close Pane. You must leave one pane open, so this button and option do nothing when a single pane is displayed.

Finally, the right-click menu has the Open with QNX Application Profiler option, for extracting any function profiling data into a new profiling session. Note that the Bookmark option, although present in the context menu of any pane, really applies to the Timeline pane only.

Summary

This pane shows a summary of the kernel, process, and thread activity that occurred during the trace.

Screenshot of Summary pane in System Profiler editor
In the upper left corner, the piechart and table show you how busy the target machine was over the trace period. This graph and its accompanying statistics reveal the CPU time spent being idle, running user code, running kernel (system) code, or processing interrupts. In the upper right corner, the kernel event trace statistics include but aren't limited to:
  • how long the trace ran
  • how many events occurred
  • user time, which is the CPU time spent running user code
  • system time, which is the sum of the idle, kernel, and interrupts times
The Process & Thread Activity area contains a bar graph illustrating the change in CPU usage and the event rate. Below the chart, a table lists the processes and threads and for each one, reveals the time spent in the Ready, Running, or any blocked state, and the number of kernel calls made and messages sent. For each state, two columns are shown:
State Time
For processes, this is the total time during the trace period when at least one of their threads was in the given state.
Consider a process with two threads running on different processors or cores. The first thread runs from 0 to 3 s within the trace period and the second thread from 0 to 1 s. The Running Time column shows 3 seconds because the two threads ran over a three-second interval.
For threads, which can run on only one CPU core at a time, this is their total time in that state throughout the trace.
State Time (Sum)
For processes, this is the sum of all individual thread times for that state, throughout the trace. In the previous example, the Running Time (Sum) column shows 4 seconds because this is how much runtime was used by the two threads, even though their overlapping execution meant they finished running by the 3 second mark.
Note: This column can differ from the previous one only for processes on multiprocessor or multicore systems. With single-processor single-core systems, only one thread in the system can be moved into a given state at a time. For threads, the columns always match because they can't run on multiple CPU cores concurrently.

The Process & Thread Activity table contains the same information that you can extract by examining a particular time range of the kernel event log using the General Statistics view.

CPU Activity

This pane displays how the load changed on each CPU over time, as a percentage of cycles consumed.

Screenshot of CPU Activity pane in System Profiler editor

The default chart type is a 3D line graph. You can right-click anywhere in the pane and in the Graph Type submenu, select another type based on a 2D or 3D display, lines or bars, or what shading to use.

The zoom feature lets you scale the graph to better see changes in CPU load over short timeframes. To change the zoom level, you can use the zoom in (Icon: Zoom in button) and zoom out (Icon: Zoom out button) buttons in the upper left corner of the IDE. There are equivalent options in the right-click menu. For Zoom In, you can first select a region of the graph by clicking and dragging the mouse, then click this option to zoom in on the highlighted timeframe. The right-click menu also has the Zoom Level submenu, which lets you return to the full-scale graph (i.e., at 100%) or set a custom zoom level. Above the graph, the yellow band in the timescale and the start and end times are updated to reflect the time period now displayed.

CPU Migration

The CPU migration pane tells you how many times the kernel migrated threads between CPUs, for whatever reason. This information is useful for finding performance problems on multiprocessor or multicore target systems. Note that this pane is meaningful only for these system types.

The bar graph in the top area illustrates the number of thread migrations over time. The table in the bottom area lists the total migrations for each thread that was active during the displayed timeframe; this table provides data for all threads within processes as well as interrupt handlers.

Screenshot of CPU Migration pane in System Profiler editor

The zoom feature lets you scale the graph to better examine CPU migrations over short timeframes. The controls are the same as those for the CPU Activity pane. Unlike in this other pane, however, you can't change the chart type.

Individual bars represent the number of CPU scheduling migrations over fixed time intervals. The migration count is incremented whenever a thread switches CPUs, so the peaks in the graph indicate times when there was a lot of contention for certain CPUs. Frequent CPU migration reduces performance because the instruction cache is regularly flushed, invalidated, and reloaded on the new CPU.

The length of the time intervals represented by the bars is based on the time period displayed. Thus, when you zoom in, these intervals get shorter. As well, the vertical axis of the graph is rescaled based on the maximum number of migrations for a thread in the newly selected timeframe, and the table is refreshed based on the graph.

In addition to total migrations, the kernel trace also tracks how many threads are migrated due to cross-CPU communication. This is shown in Inter CPU Communication.

CPU Usage

This pane shows the CPU usage history for various event owners. CPU usage is amount of runtime that threads get. The graph draws separate colored lines and shaded areas for each owner selected in the table underneath. In this example, we selected process threads, but the functionality works the same for interrupt handlers:

Screenshot of CPU Usage pane in System Profiler editor

The zoom feature lets you scale the graph to better read changes in CPU consumption over short timeframes. The controls are the same as those for the CPU Activity pane.

The table area contains three tabs that display the times that various threads ran on individual CPUs, at specific priority levels, and within certain partitions. The last tab shows data only if the target uses adaptive partioning. For all three tabs, the threads are initially sorted by their total running times across all CPUs (in descending order), but you can click the column headers to change the sorting order.

The measurements reflect the CPU consumption over the time period selected in the chart. By default, they appear as percentages followed by time values, but you can display just one of these metrics or both of them in reverse order, by selecting Window > Preferences > QNX > System Profiler > CPU Usage and clicking an option in the Table Data Format dropdown. This same preference dialog lets you switch between a line and an area chart, using the Chart Type dropdown.

Clicking table rows updates the graph to display the CPU usage history of the associated threads. Multi-select is supported, by holding the Ctrl and/or Shift keys, similar to Windows Explorer. Below the table, a summary row displays the sums of the values for the selected threads.

Inter CPU Communication

The Inter CPU Communication pane shows you how often the kernel migrated threads due to message passing. This information helps you find performance bottlenecks caused by messaging on multiprocessor or multicore target systems. Note that this pane is meaningful only for these system types.

In the top area, the bar graph illustrates the number of thread migrations over time. In the bottom area, the table lists the total migrations for each thread that was active during the displayed timeframe.

Screenshot of Inter CPU Communication pane in System Profiler editor

This pane tells you how many cross-CPU messages were exchanged. When a message-sending (client) thread and the corresponding message-receiving (server) thread run on different CPUs, the message sending data must be migrated from the client's CPU to the server's. This activity reduces performance because the first CPU's cache is invalidated when the data get moved.

You can adjust the zoom level to see the message-related migration counts for specific time periods. The bars then change to reflect new fixed time intervals based on the timeframe now displayed and the table gets updated, similar to the CPU Migration pane. Note that this other pane reports how often threads were migrated for any reason, not just due to messaging.

Partition Summary

This pane displays the CPU usage of partitions and individual event owners that ran within each one. Note that this pane is meaningful only when the target uses adaptive partitioning.

Screenshot of Partition Summary pane in System Profiler editor
In the top left corner, the piechart illustrates the breakdown of CPU usage by partition. Next to it, the table lists the partitions and their desired CPU load or budget (what percentage of cycles they're guaranteed in a fully loaded system) and observed CPU load (what percentage of cycles they got). Just below the table, there are two buttons:
  • Find Bankruptcy Events — searches for all APS Bankruptcy events and displays the results in the Search view
  • Mark Critical Sections — adds bookmarks for all events marking the entry into a critical section; the newly marked events are listed in the Bookmarks view

In the bottom area, the table lists the per-event owner CPU usage across all partitions and within each one. A process can run threads in separate partitions, and a thread can switch partitions, using the SchedCtl() C library function. For more information about adaptive partition scheduling and examples of using this API to configure it, see the Adaptive Partitioning User's Guide.

Note: To see realtime statistics about the current load, you can examine the APS View in the System Information.

By default, the statistics shown reflect the entire trace period, even if you selected a time range in another pane. To see the CPU usage metrics for only the highlighted range, click the Focus on Range Selection button (Icon: Focus on Range Selection button), then click Refresh (Icon: Button to refresh statistics).

Whenever you select another time range, you must refresh this pane using the second button. You can click the two buttons again (in the same order) to disable the range selection focus and redisplay the statistics from the entire kernel trace. The reason for this design is that the calculations for finding CPU usage by partition are intensive enough that the System Profiler doesn't automatically perform them as soon as you change the timeframe selection.

At the bottom of the pane, the status bar indicates the time range that the current statistics reflect.

Timeline

This pane provides a detailed chronology of the logged kernel events by illustrating the timing of events belonging to particular owners. The timescale along the top shows the relative start and end times of the trace and highlights the currently selected timeframe. In the main area, timelines are drawn for individual owners, with indvidual events represented by vertical tick marks.

Screenshot of Timeline pane in System Profiler editor

Given the huge number of events in even brief traces, you typically have to zoom in considerably to find an exact event sequence of interest (e.g., a message exchange or unexpected thread scheduling). To change the zoom level, you can use the zoom in (Icon: Zoom in button) and zoom out (Icon: Zoom out button) buttons in the upper left corner of the IDE. There are equivalent options in the right-click menu. For Zoom In, you can first select a region of the graph by clicking and dragging the mouse, then click this option to zoom in on the highlighted timeframe. The right-click menu also has the Zoom Level submenu, which lets you return to the full-scale graph (i.e., at 100%) or set a custom zoom level. Above the graph, the yellow band in the timescale and the start and end times are updated to reflect the time period now displayed.

The Timeline pane lets you scroll vertically, to see timelines from different owners, and horizontally, to navigate to earlier or later in the trace period when you're zoomed in. With this last action, the timescale selection is automatically updated.

Note: Several other panes—CPU Activity, CPU Migration, CPU Usage, and Inter CPU Communication—also display the timescale. When you change the selection in any of these panes or in Timeline, if you then switch to another of these panes, the graph and data tables will reflect the new selection. But when multiple panes are displayed concurrently (using the Split Display feature), changing the selection in one does not update the others.

Initially, a summary timeline is drawn for each process and interrupt vector. The tick marks on this timeline represent specific events belonging to any thread within the process or any interrupt handler attached to the vector. You can click the plus sign (+) next to the owner's name to display the timelines for its threads or handlers; when you do this, the summary tick marks are cleared. Clicking the minus sign (-) next to an expanded owner hides these other timelines and redraws the summary marks.

The System Profiler illustrates thread states by drawing, on thread timelines, color bands between state change events. Areas with a thinner line represent timeframes when the thread was blocked.

Screenshot of Timeline pane in System Profiler editor

Timeline: Hover-based information

When you hover the pointer over an owner name or an event tick mark, the editor shows related information in a popup box. For owners, the details shown depend on the owner type:
  • processes — process name and PID
  • threads — TID and parent process information
  • interrupts — interrupt vector number, in hexadecimal and decimal
  • interrupt handlers — name of process in which handler runs, and interrupt vector number
For events, the details vary with the event type. Generally, you see the owner, event type, event number within the log, timestamp, PID, and other specific data such as the new state or the semaphore address.

Timeline: Owner and event selection

To select an owner, click its name. The owner and its summary timeline are highlighted in grey, and you can then find specific events or navigate between events within the selection. Multi-select is supported, by holding the Ctrl and/or Shift keys when selecting processes, similar to Windows Explorer.

To select an event, click its tick mark. The editor highlights the owner's name in yellow and draws a marker (which is a yellow arrow pointing downwards) just above the event, as well as a dotted vertical line that lets you see when the event occurred relative to others. Near the top, just below the timescale, the middle value is updated to the selected event's timestamp. Highlighting one event is useful for navigating through other events.

Screenshot of Timeline pane with an interrupt selected and a handler entry event highlighted

Multi-select is supported for events differently than for owners. You can hold Shift and click two events to select the timeframe between them, which is useful for zooming in on a specific event sequence.

Timeline: Navigation

The System Profiler provides toolbar buttons (in the upper left corner) and shortcut keys to navigate between events in the Timeline pane:
To navigate to the: Click this toolbar button: Use this shortcut key:
Previous event by the same owner Icon: Previous Event By Owner button  
Previous event in the selection Icon: Previous Event In Selection button CtrlShiftLeft
Previous event Icon: Previous Event button CtrlLeft
Next event Icon: Next Event button CtrlRight
Next event in the selection Icon: Next Event In Selection button CtrlShiftRight
Next event by the same owner Icon: Next Event By Owner button  

You can navigate directly to an event. When the editor is in focus, pressing CtrlL or selecting Navigate > Go To Event opens a window that lets you enter a sequence number, timestamp (in nanoseconds), or event cycle. When you provide one such value and click OK, the System Profiler looks for the event. If it finds the event, it moves the yellow arrow marker and highlights the owner in the Timeline pane. For the timestamp, the IDE navigates to the event closest to the specified time.

Some QNX System Profiler views, such as Trace Event Log and General Statistics, are synchronized with the Timeline pane; selecting an event in one display navigates to that event in the other display. Thus, if the event marker seems to have jumped unexpectedly, most likely, you clicked a table row in one of these views. When you change the timerange selection in the Timeline pane, you can then filter the statistics shown in General Statistics; for details, see the General Statistics reference.

Timeline: Scrolling

You can move backwards or forwards along the timelines by pressing the left and right arrow keys when the editor is in focus. You can also scroll between event owners:
To navigate: Use this shortcut key:
To the top of the owner list Home
Up by one screenful Page Up
Up by one owner Up
Down by one owner Down
Down by one screenful Page Down
To the bottom of the owner list End
Note: Scrolling doesn't change the owner or event selection.

Timeline: Find

You search for events by pressing CtrlF, selecting Edit > Find, or clicking the Find button (Icon: Find button) in the upper left toolbar. This action opens a window with controls for finding events in open log files:

Screenshot of Find window with Events tab filled out
The Events tab, which is initially selected, lets you specify the:
  • class
  • code (event type)
  • search scope, either all owners or the selected ones
  • search direction (forward or backward)
  • whether to wrap the search

If you click the Owners tab on the right, you can then select a single thread in which to search. The text field at the top lets you begin typing the thread name, to filter the list. Multi-select is not supported.

When you click Find, the System Profiler navigates to the first matching event found. This simple search feature is good for most times when you want to locate an event, but you can also search for events matching specific criteria, as explained below.

If you want to see all kernel events matching certain conditions, you can use the search feature. To use it, press CtrlH or select Search > Search, then click the Trace Search tab. The fields for selecting search conditions for kernel events then appear:

Screenshot of Search window with Trace Search tab selected

The Search expression field at the top lets you name one or more search conditions to use. You can combine results from multiple conditions by specifying the AND (&&) and OR (||) operators between condition names. You can also use the dropdown on the right to choose exactly one condition.

The radio buttons in the middle let you choose the search scope, which can be the entire trace, the timeframe scrolled to in the editor, or the selected timeframe (which is the area colored light grey).

The Defined Conditions panel lists the existing search conditions. On the right are buttons for adding, removing, and editing conditions. The Add button opens a wizard that lets you define a new search condition. Clicking the Edit button after you've selected a list entry opens the same window but any settings made modify the existing condition.

Screenshot of Trace Condition Wizard with the Communcation class and Receive Message event type selected and the list of possible owners expanded underneath

Through the text field at the top, you can give the new condition an insightful name. Below, you can select a class, code (event type), and other data fields related to the code; these last fields appear after you select a specific class and code. By default, the Select all elements box is checked (in the bottom area), so the search applies to all owners. But you can uncheck this box and select one or more owners from the list that appears, to restrict the search. Also, you can expand entries for processes and interrupt vectors to choose individual threads and handlers.

Click Finish to close the wizard and save the new condition. In the Trace Search tab, this condition now appears in the list. When you click Search in this tab, the IDE runs the search and lists the results in the Search view, with a maximum of 1000 results. Each row lists the following details for an event:
  • sequence number within the log
  • timestamp, relative to the trace start
  • owner
  • event type
  • all type-specific data fields

You can customize which details are shown by selecting Configure Trace Event Table in the upper right dropdown (Icon: Search View dropdown); this action opens a window in which you can select individual columns to display.

If you double-click a row, the System Profiler navigates to that event in the Timeline pane. The owner is highlighted in yellow, the yellow arrow marker is placed above the event's tick mark, and thin red circles are drawn around this tick mark and those for all other events of the same type.

Screenshot of Search view with a result row selected and the corresponding Running event highlighted in the Timeline pane

You can select individual rows with the left mouse button and multiple rows by also holding down Ctrl and/or Shift. This allows you to remove only those events by using the first control outlined just below, but also to copy the corresponding event data to the clipboard (using CtrlC) and then paste the data into an Excel workbook or another program that reads data in CSV format.

The upper right toolbar in the Search view has the following controls:
  • Remove Selected Items (Icon: Remove Selected Items button)
  • Remove All Items (Icon: Remove All Items button)
  • Run the Current Search Again (Icon: Run Current Search Again button)
  • Cancel Current Search (Icon: Cancel Current Search button) — This is active only when the search is running.
  • Show Previous Searches (Icon: Show Previous Searches dropdown) — This dropdown lists recent searches so you can easily rerun them (by clicking their entries) and provides options to access the full history and clear the history.
  • Pin the Search View (Icon: Pin Search View button) — This button lets you keep the current results for reference. When this button is clicked, the next time you run a search, the IDE displays the results in a separate window.

Timeline: Bookmarks

Bookmarks help you keep your place in a kernel event log. To bookmark an event, click its tick mark and then right-click and choose Bookmark. (There's also a bookmark button, Icon: Bookmark button, in the upper left toolbar.) In the resulting window, you must enter a description for the bookmark. When you do so and click OK, the IDE adds the event to those listed in the Bookmarks view. In this way, you can annotate a log file to mark the most interesting events.

At any time, you can double-click a row in this view to directly navigate to an event that you bookmarked. You can also choose Go To from the context (right-click) menu. This menu also has options for copying the event data to the clipboard, deleting the selected entries, selecting all events, and viewing the properties of a single event. When you select two events, you can choose Select Range in Editor to select the timeframe between them.

Timeline: IPC representation

The Timeline pane can illustrate IPC activity such as message exchanges by displaying arrows between the owners involved. This lets you quickly see when certain processes and threads interacted with each other.

To turn this on, click the Toggle IPC Lines dropdown (Icon: Toggle IPC Lines dropdown) in the upper left toolbar, then choose All to see IPC arrows for all owners or Select Owners to see arrows only within the selection.

Screenshot of Timeline pane with IPC lines between a server and two client threads, with the SyncSemPost Enter event selection reflected in the Trace Event Log view

Pulses are indicated by orange arrows. Message sends are shown in blue while replies are shown in either green, for a successful reply, or red, for an error reply. In this example, the user has selected a Reply event from hw_server Thread 5. The arrow is green to indicate that the server replied to the client (low_prio_client Thread 1) after its request succeeded. Earlier in the timeline (i.e., to the left of the selected event), we can see a blue arrow between the same two owners but pointing in the opposite direction; this indicates the client's message send containing the request.

Timeline: Event labels

You can annotate timelines with event labels to easily distinguish between event types and see data associated with individual events. This latter feature is particularly helpful for matching Function Entry and Function Exit events with function names.

By default, no labels are drawn. To see them, click the Toggle Labels dropdown (Icon: Event Labels button) and select from among these options:
  • Priority Labels — for Running events, shows the owner's priority level
  • State Labels — for State events, shows the owner's new state; this means you don't have to remember the colors for specific states
  • State Icons — shows icons representing state changes; this saves space compared to names, but you must recognize the icons
  • IPC Labels — for Communication events, shows the name of the thread receiving the message or pulse or being replied to
  • Event Labels — for message-related events, shows entries into key functions (e.g., read(), write())
Note: Event labels for all threads within a process are shown on the process's timeline. This can make it quite crowded, so it's often best to expand a process that you want to analyze, and view the labels on the thread timelines.
The last dropdown option, Configure Event Labels, opens a properties window that you lets you select the data fields to display in the event labels as well as how the data are formatted. Note that the settings in this window apply to the current log file only.

Screenshot of Timeline Event Labels window

By default, Use global label settings is checked, so the System Profiler inherits the label display settings preconfigured for common events such as MsgSendV Enter. The link next to this box lets you change the default display settings used by all traces. The window opened by this link has the same table listing of individual settings and the same controls for configuring them as the first window. Note that you can also access the global label settings through Window > Preferences > QNX > System Profiler > Timeline Event Labels.

In both the trace-specific and global settings windows, the label display settings are shown in a table, with each row showing the data display pattern and data keys (fields) for a specific event type. On the right, there are buttons for adding, editing, and removing settings. Clicking Add opens the Set Event Label Details window.

Screenshot of Timeline Event Labels window
This other window lets you select an event type, by expanding an event class on the left and checking the box for an individual type, then one or many data keys to display in the corresponding labels, by checking the relevant boxes on the right. It also lets you customize the display pattern. The default pattern consists of the event type followed by a comma-separated list of data keys. If you check Customize display pattern, the text field underneath becomes active and you can enter patterns containing literal text as well as these symbols:
  • Data keys are specified by using $data_key_name$; in the Timeline pane, they're replaced with the actual event values for the given keys.
  • To make the label text span multiple lines, use \n.

Timeline: Renaming processes and threads

Renaming processes and threads makes the Timeline pane more readable. Often, threads are unnamed, so this feature allows you to better identify them based on their purpose. If you run tracelogger in ring mode, the thread names are lost, so this way, you can assign your own names when viewing the trace results.

To rename an event owner, first select it (by left-clicking) in the Timeline display. Then, either right-click and choose Rename or press F2, and type the new name.