You can select a topic from this diagram:
Use the System Profiler to analyze your system via instrumentation.
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:
 |
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:
|
You can gather statistics for the entire log file or for a selected range. |
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.
|
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. |
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.
|
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.
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:
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.
|
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.
|
If you don't already have a target project, you'll have to create one. To create a target project:
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. |
The Log Configuration dialog takes you through the process of selecting:
Here are the main fields in this wizard:
|
If your target is running QNX Neutrino 6.2.1, you must use this option instead of "Generate only on the target" because the trace statistics file is not supported under QNX Neutrino 6.2.1. |
Regardless of how your log file is captured, you have a number of different options for how to regulate 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.
The data logged with events comes in the following modes:
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. ;-))
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 display will show data up to the point where the log file has been processed.
|
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 displayed 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. You can configure the table that's displayed in the search result view to display only the interesting trace event fields. The content of this table can be cut and pasted to the system clipboard as CSV-format data.
The tracing of kernel events from the IDE is performed as a background task. You can monitor the progress of the trace by opening the Progress view.
In the System Profiler editor's Timeline pane, you can navigate to the next or previous event limited to only those event owners. 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 lets developers collaborate more easily with one another by providing direct event navigation by event index, event cycle, or natural time.
The System Profiler's Go To Event command.
These components of the QNX System Profiler are described in detail later in this chapter:
There are a number of additional components outside of the editor that you can use to examine the event data in more detail:
Invoked by Ctrl-H (or via ), 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 be applied against the expression; "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 on the of the Preferences dialog ().
This view shows 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.
This section describes some cases where you'd use the System Profiler:
In many cases you 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.
In order 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.
If you need to determine the CPU load caused by interrupts, then you must also log the Interrupt Entry/Exit events.
To start, open the target log file in the System Profiler editor. By default the initial display 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 .
The Summary editor pane shows a high level overview of the log file contents:
The System Activity section displays the distribution of time spent in the log file, carved into these broad categories:
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 vs user time, possible interrupt flooding).
The distribution of CPU usage over the time of the entire log file is displayed 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 .
The peaks of this display indicate areas of particularly intense CPU usage and are the areas of most interest.
In order to drive down to 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 or directly 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 display showing the sum of this usage categorized by CPU, priority or partition.
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 nonidle CPU consumers in this example provides the following display:
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 time bar is updated to show the new range of time being examined.
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.
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 activate.
|
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.
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:
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 is activated via the .
Once activated, the Client/Server CPU Statistics are gathered on demand, by default, targeting the full range of the target log file:
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:
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:
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 who qconn- Thread 1 is imposing CPU usage on. You can configure the Client/Server CPU Usage view to display all of the CPU consumers who are being imposed on (and by whom) by selecting Show all times from the view's dropdown menu:
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):
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.
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.
In order 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 the log file should also contain the Interrupt Handler Entry/Exit events.
In order to properly gauge the latency in triggering a response in user code, then 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.
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 .
You should see a display that resembles the following. The details will of course be different, but the layout similar:
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:
Here you can see that the io-net 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 is via .
If you use the refresh button, this view extracts the event statistics for the entire log file (default), or for just the selected area if specified. Doing that results in the following display:
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:
Then uncheck the Show statistics for all elements check box at the bottom of the General Statistics view:
Now the General Statistics view tables show the content limited to just the selected event owners (in this case Interrupt 0x80000000):
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:
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 in general 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:
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 . 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 and vice versa.
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:
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-net 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-net interrupt handler is returning a pulse that's triggering something in the user's application (event 13515) and that an io-net 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:
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-net 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:
Alternate measurements that could be of interest and that can easily be examined include:
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.
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.
This will 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 .
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. The Filters view is synchronized with the active System Profiler editor and can be displayed via the menu or by right-clicking Filters... in the Timeline editor pane.
This view provides you with the following types of filtering:
By default, the Trace Event Log view presents a display that uses the same filters as the editor it's reflecting from. 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:
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 brings up 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.
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 search tool is invoked via the menu item . Opening this up presents a dialog similar to the following:
There are many different search mechanisms in Eclipse, but the Trace Search is the one that we're interested in as a "super find" for the event files.
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:
Search results are also marked in the timeline to help show the event distribution over the period of the log file:
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 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 (system version, system boot time, number of CPUs, etc.), and any event owners such as interrupts, processes, and threads that are referenced by events in the new log file are synthetically created with timestamps matching the start time(s) of the new log file.
The QNX System Profiler perspective includes the following views:
They're described in the pages that follow.