Chapter 2, “Collecting Event Data,” described how to collect event data; now you are ready to work with it. By “working with the event data,” we mean navigating the event log, selecting event data, and analyzing event data.
 | Note: In most cases, this chapter does not distinguish between raw event logs and processed event logs. This is because once you have imported event data into the View Graph, it is considered processed. |
This chapter covers the following topics:
This chapter assumes that WindView has been installed and configured for your environment; see the WindView release notes for details. It also assumes that you have followed the instructions in Chapter 2, “Collecting Event Data” to start WindView, open a View Graph, and import event data into the View Graph.
For specific information on any of the WindView GUI commands mentioned in this chapter, see Chapter 5, “Command Reference.”
Depending on the real-time system and the event logging modes that have been started, the View Graph looks something like the one shown in Figure 3-1. Use your window manager to resize the View Graph, if need be. You can refresh the View Graph at any time by moving the cursor into the window and clicking the right mouse button.
The View Graph is a window into the event data; in most cases, it does not show the entire event log. Instead, what is shown is a time interval. In Figure 3-1, for example, the time interval shown is roughly second 3.7496 to second 3.7501.
The first View Graph that you display is labeled View 1. You can display up to 16 View Graph windows at one time, which can be useful for looking at different portions of the same event log. Each one is numbered in the order that it is displayed; that is, the second View Graph is labeled View 2, and so on.
When you display auxiliary windows, they are numbered to match the View Graph from which they were invoked. For example, if you display a View Control window from View 2, it is also labeled View 2. A Search window displayed from View 2 is labeled Search 2.1, because you can display multiple Search windows: the next one displayed from View 2 is labeled Search 2.2, and so on. (Information on how to display auxiliary windows is provided below.)
Time Units Menu Icon |
sec seconds (the default) msec milliseconds usec microseconds nsec nanoseconds For detailed description, see “Time Units Menu Icon”. | |
View Control Window Icon |
| |
Zoom In/Zoom Out Icons |
Zoom In halves the time interval displayed, preserving the screen's midpoint. If a sub-interval is selected, the boundaries of the sub-interval become the time interval's boundaries. For information on selecting a sub-interval, see “Selecting Data”. Zoom Out doubles the current time interval (or a selected sub-interval), preserving the midpoint, if possible. For a detailed description of these icons, see “Zoom In/Zoom Out Icons”. | |
Pan Left/Pan Right Icons |
| |
Push Icon | The Push icon saves the current time interval. You can later move back to this time interval with the Pop or Exchange icon (see below). You can push up to 16 time intervals; if you push more than 16, the oldest intervals are discarded in FIFO order. For a detailed description of this icon, see “Push/Pop/Exchange Icons”. | |
Pop Icon | The Pop icon causes the most recently pushed time interval to be displayed (see the Push icon, above). For a detailed description of this icon, see “Push/Pop/Exchange Icons” | |
Exchange Icon |
| |
Search Window Icon |
| |
Search Accelerator Icons |
| |
The underlined arrows find the next (or previous) occurrence of the currently selected event in the same context, that is, in the same interrupt level, process, or idle loop context. | ||
The arrows without underlines search for the next or previous occurrence of the currently selected event, regardless of context. | ||
Legend Window Icon |
| |
Interrupts | At the top of the View Graph, the interrupts used in this event log are listed. If you need more space above the interrupts to view icons that appear there, place the cursor over a context label, and then press <Ctrl> and click the right mouse button. To remove the extra space, press <Shift> and click the right mouse button. | |
Processes | After the interrupts, the processes are listed in random order. | |
Idle Loop | After the processes is the kernel's idle loop, listed by processor. | |
Detailed Time Information Field |
| |
Scrollbars | Use either scrollbar by dragging the scrollbar's thumb (the rectangle in the scrollbar), clicking in the gutters (the area on either side of the thumb), or clicking the arrows. | |
To move the thumb to a particular point in the scrollbar, put the cursor where you want to move, then click the middle mouse button. To move the thumb to one of the scrollbar's extreme ends, press the <Ctrl> key and click the left mouse button in the gutter. Figure 3-18 summarizes these instructions. | ||
The vertical scrollbar scrolls among the contexts that were valid when this event log was collected: interrupts, processes, and the kernels' idle loop. | ||
The horizontal scrollbar scrolls along the time or event sequence axis, starting at 0 when event logging began. | ||
State Stipples | These are the horizontal lines that show the state of each process. The state stipple shown here is the Suspended stipple. For information on what each state stipple represents, see the Legend window (described above). | |
Event Icons | Depending on the current event logging mode and the events you have suppressed (see “Examining Data”), various icons are displayed that correspond to events. The event icon shown here is the sigwrapper icon. For information on what each event icon represents, see the Legend window (described above). To learn specific information on a particular occurrence of an icon, see “Examining Data”. | |
Timeline | The timeline displays the time in seconds since event logging began. You can change the units that are displayed using the Time Units Menu. |
There are various types of event data that can be selected and examined: time intervals, time instants, sub-time intervals, and events. This section first describes ways to select data, then describes how to examine it.
| Note: Clicking the right mouse button at any time refreshes the View Graph. |
A time interval is that portion of the event log that is currently displayed in the View Graph. You can select a particular time interval with the View Control window, first mentioned in “Understanding the View Graph”. Clicking on the V icon in the View Graph displays the View Control window; see Figure 3-22.
In the From and To fields, you can specify which time interval, in units of seconds or event sequence numbers, you would like to examine. For example, type 62.7 in the From field and 62.8 in the To field, and then click the Go To button to view the interval from second 62.7 to second 62.8. (The rest of the View Control window is described in “View Control Window Icon”.)
Select a time instant by clicking the left mouse button over a time of interest in the View Graph. (The cursor must be in the View Graph window; it cannot be over the timeline, for example.) A vertical line appears in the event log, and details about that time instant are displayed in the Detailed Time Information field; see Figure 3-23.
Select a sub-time interval by first selecting a time instant, then moving the cursor to another time of interest and clicking the left mouse button a second time. Now two vertical lines are displayed in the event log, and the times of each “leg” of the sub-interval and the difference between them are displayed in the Detailed Time Information field.
For example, Figure 3-24 shows a sub-interval with legs at 0.6037 and 0.6177 seconds; the difference between these legs is 0.0139 seconds.
Selecting a sub-time interval can tell you the amount of time that has occurred between events. You can also select a sub-interval and zoom in on it by using the Zoom In icon.
To cancel a time instant or sub-time interval and set a new time instant, move the cursor to where you want the new vertical line; then press the <Shift> key and click the left mouse button. To cancel a time instant or sub-interval entirely, press the <Ctrl> key and click the middle mouse button.
You can select an event by using the mouse or by searching for the event.
Click the middle mouse button on an event icon to view its timestamp in the Detailed Time Information field. For example, Figure 3-25 shows a selected signal event icon, with a timestamp of 0.0851 seconds. You can also select an event by moving the cursor near the icon, then pressing the <Ctrl> key and clicking the left mouse button. The vertical line “snaps” to the nearest event. To cancel an event selection, press the <Ctrl> key and click the middle mouse button.
The various mouse clicks described in this section are summarized in Table 3-1
Table 3-1. Selecting Data With the Mouse
Mouse Click | Description |
|---|---|
Right button | Refresh screen |
Left button | Select a time instant |
Left button, move, left button | Select a sub-time interval |
<Shift> + left button | Cancel a time instant or sub-interval and set a new time instant |
Middle button | Select an event |
<Ctrl> + left button | Select nearest event |
<Shift> + middle button | Cancel any selection |
Another way to select an event is to search for it; the search commands were first mentioned in “Understanding the View Graph”. Clicking on the S icon in the View Graph displays a Search window labeled Search 1.1; see Figure 3-26.
| Note: You can display multiple Search windows for a View Graph. Each Search window is labeled sequentially: the first number represents the View Graph from which you invoked the Search window (1 in the example above); the second number represents which Search window it is relative to all Search windows currently displayed for this View Graph (again, 1 in the example above). The next Search window for View 1 would be labeled Search 1.2; the first Search window for View 2 would be labeled Search 2.1. The maximum number of Search windows that can be displayed for each View Graph is 16. |
With this window, you can search for a particular event, the next or previous event in a particular context, or the next or previous event of any type in any context. Follow these steps to use the Search window:
Specify a particular event by entering its name in the Event field, for example, sigwrapper.
Enter the event name by typing it or by dragging the icon of interest into the field; see “Examining Data” for information on dragging event icons. You can also drag icons from the Legend window into this field.
Note: You cannot drag the defaultUser and unknown event icons into this field. Leave this field blank if you are searching for any event in a particular context, or any event in any context.
You can further constrain the search for a particular event by specifying the event's object ID (the ID of the object being acted on; for example, a signal number).
Enter the object information by typing it or by dragging the icon into the field.
If the Event field is blank, any data in the Object ID field is ignored.
You can further constrain the search for a particular event by specifying its context ID (interrupt level, process, or idle loop).
Enter the context information by typing it or by dragging the icon of interest into the field. Or, you can enter the information by selecting the context label from the vertical axis with the middle mouse button, then dragging the word “CONTEXT” that appears into the Context ID field.
If the Event field is blank, any data in the Object ID field is ignored, and the next or previous event of any type is found in the specified context.
If the Event field and the Context ID field are blank, then the next or previous event of any type in any context is found.
After you have specified the search parameters, click the appropriate arrow to perform the search.
When the next occurrence of the event is found, the View Graph displays the time interval in which it occurs and indicates the found occurrence by placing a vertical line through it. Timing information is displayed in the Detailed Information field.
To search for another occurrence of the event, you can use the Search window again, or you can use the Search Accelerator icons in the View Graph. For information on these icons, see “Understanding the View Graph”.
An obvious way to examine the event data is to simply look at it. Use the scrollbars to scan the data as a whole, zooming in and out as appropriate with the Zoom icons. Even with this simple method you can gain useful information about your real-time system; for example, you can answer the following questions:
Are deadlines being met?
Are all the application processes getting a chance to execute?
Is too much time being spent in ISRs or in the idle loop?
Another way to examine the event data is to use the methods described in “Selecting Data” to select time intervals or events of interest, zoom in or out on them, and examine their timestamps and sub-intervals.
For a more in-depth analysis of your real-time system, you can examine specific events. To do so, first choose the “Tcl: Event Inspector” command from the Windows menu. The Event Inspector window appears, as shown in Figure 3-27.
Now, select an event icon with the middle button and drag it to the Event Inspector. The cursor changes to the shape of the event icon, letting you see what is being dragged. When you “drop” the icon into the Event Inspector, information about that event appears. Figure 3-27 shows an example of what might appear in the Event Inspector window when a sigwrapper icon is dropped in it.
When you drag a new icon into the window, it overwrites the previous event's information. You can also move the cursor into the window and type the letter C to clear the Event Inspector.
Another way to work with event data is with the View Control window (described briefly in “Selecting Data”). Clicking the V icon in the View Graph displays the View Control window; see Figure 3-22.
The View Control window contains commands that let you change how the event log is displayed. The following describes the elements of this window:
| Track Incoming Data Button |
| |
If the Track Incoming Data button is toggled on (the default), the View Graph displays the event log in real time as it arrives. In this mode, you cannot work with the event data until collection is stopped. | ||
If the button is toggled off, the View Graph is “frozen”: only the horizontal scrollbar is adjusted to show that more data has arrived. This mode allows you to examine something of interest while the raw event log continues to be imported. For example, you can examine a particular time interval, save it with the Push icon, then turn Track Incoming Data back on. When you find another time interval of interest, you can turn Track Incoming Data off again, then toggle between the two intervals with the Exchange icon. | ||
| From/To/Go To | | |
| Preserve (%)/Left and Right Arrow Buttons | | |
For example, if Preserve is set to 50, the arrows move the view forward or back one-half page at a time (where a page is the width of the current time interval). However, if Preserve is set to 90, they move forward and back just 10% of the current time interval at a time. If Preserve is set to 0, they act the same as the icons on the View Graph; if Preserve is 100, these arrows are disabled. | ||
| Zoom In/Out/Factor |
| |
For example, if Factor is set to 10, this Zoom In displays 1/10 of the current time interval and this Zoom Out displays 10 times the current time interval. If Factor is set to 2, they act the same as the zoom icons on the View Graph (Zoom In displays 1/2 the current time interval; Zoom Out displays 2 times the current interval). However, if Factor is set to less than 1, the actions of these zoom buttons are reversed. | ||
| Display Events Button | | |
Toggling these event types and state types on or off controls which elements are displayed. ISR entrances and exits (Interrupts), and vertical lines between process or interrupt contexts and ISRs (Interrupt Transitions) are not displayed by default. (For a description of the other events and states, see “Display Events Command”.) | ||
Note that this is different from the Target window, which controls event logging; see “Starting and Stopping Event Logging on the Target”. |
Once you know how to use the WindView tools to collect and examine data, the data in the View Graph can be analyzed. This section walks you through several example View Graph windows to show how to analyze a progression of events, as they are displayed in real time.
The first example shows the events leading up to the WindView program executing on a single processor. The second example shows WindView executing on a multiprocessor system. Examples 3 and 4 shows the REACT/Pro Frame Scheduler running on a Silicon Graphics multiprocessor system.
The callout numbers outside the figures point out important events that are described in the corresponding text listing. For example, step 1 in the text describes what is happening at item 1 in the View Graph.
| Note: If scheduling actions are performed on an untraced processor, they will not display in the View Graph. You must trace every processor on which the process can run to completely follow the progress of the process. |
Figure 3-30 shows a trace where WindView starts executing on a single processor, labeled Proc2.
At the beginning of this trace (approximately 62.77 seconds), the processor is in the idle loop (Proc2 Idle). The WindView (windview.ex) process, and the pfslowtimo and routed daemons are suspended. The system controller (sysctlrd) and network daemons (rtnetd) are ready to run, waiting on the run queue.
Notice the activity at the Global Interrupt Entry Point (Proc2 INT 0), showing several interrupt qualifier user-events (actually user event 20005, but displaying as 5 in this example).
Additionally, the processor Tick Interrupt (Proc2 INT 6) occurs every 10 milliseconds, as you can see if you click two adjacent interrupt 6 events.
At approximately 62.80 seconds, WindView (windview.ex) receives the event that causes it to go from the suspended to the executing state.
At this point, we want to examine in more detail the events that caused Windview to start executing. Click on 62.80 seconds and then zoom in (click the Zoom In icon) to the sub-time interval, as displayed in Figure 3-31.
At approximately 62.80479 seconds, an interrupt occurs that enters the Global Interrupt Entry Point (Proc2 INT 0). The interrupt is further qualified (designated by the user event 5).
Once IRIX has further qualified the interrupt as an Interprocessor Interrupt, the interprocessor Interrupt Service Routine (ISR) is entered, as shown in the graph by the change in state to Proc2 INT 11.
After the completion of processing within the interprocessor interrupt ISR, the processor exits through the Global Interrupt Entry Point (Proc2 INT 0).
The processor returns to the idle state (Proc2 Idle) and the IRIX scheduler re-evaluates the run queue.
Since the processor is idle, a mode switch can occur. The WindView process (windview.ex), which was suspended on the run queue, now is ready to run and begins to execute.
Figure 3-32 shows a trace for a multiprocessor system, with processors labeled Proc2 and Proc3. This example shows how the WindView process migrates between the two processors as it executes.
At the start of the trace, both processors are executing the idle loop.
The WindView process (windview.ex) is in the ready state and begins to run on Processor 3. Processor 3 goes into idle mode and then continues running windview.ex three times, as it periodically blocks, waiting for an event or resource.
At approximately 6.630 seconds, Processor 2 receives an IRIX scheduling interrupt (Proc2 INT6). The interrupt is qualified through the Global Interrupt Entry Point (Proc2 INT 0).
WindView is shown executing (at approximately 6.6305 seconds) on Processor 2.
At approximately 6.633 seconds, Processor 3 receives an interprocessor interrupt. The interrupt is qualified through the Global Interrupt Entry Point (Proc3 INT 0).
WindView again executes on Processor 3.
Figure 3-33 shows the start of a Frame Scheduler (FRS) minor frame.
Processor 1 receives an interrupt transitioning from the idle state to the Global Interrupt Entry Point (Proc1 INT 0). The interrupt is further qualified (user event 5) as a CC Counter Interrupt.
Processor 1 transitions to the CC Counter Interrupt ISR (Proc 1 INT 7), signifying an IRIX timeout.
Note: The processor is interrupted only once; the other interrupts that follow in this figure are further qualifications of this same processor interrupt. Processor 1 further qualifies the interrupt as a Frame Scheduler Interrupt (Proc1 INT 1), signifying the FRS has interrupted the processor.
User event 20017 occurs in the Frame Scheduler ISR, signifying the start of an FRS minor frame.
Processor 1 receives user event 20002, an FRS Dispatch, signifying that FRS chooses a new process to run; in this example, the process multi.
The process multi begins executing.
A Frame Scheduler Yield event is registered (Proc1 INT 5, event 20003) indicating that the executing process has called the frs_yield function.
This is an example of the Frame Scheduler (FRS) recovery mechanism. Figure 3-34 show a minor frame being injected so processing can complete.
Processor 2 receives a Frame Scheduler Interrupt (Proc2 INT 1) further identified by event 20009, an FRS frame overrun, signifying that the process failed to yield a minor frame.
Processor 2 receives another Frame Scheduler Interrupt (Proc2 INT 1) for user event 20011, an FRS inject frame event, signifying that a minor frame has been injected to complete processing (the recovery mechanism).