Scheduler Summary

The Scheduler Summary tab, shown in Figure 3-4, summarizes the overall scheduling behavior of the threads running in the system during the trace. Each thread is listed in the outline underneath its owning process, as shown at (1). To the left of each thread’s name, Shark displays the number of run intervals of that thread (or all threads within a process) that it recorded in the course of this session.

The Total, Avg, Min and Max columns list the total, average, minimum, and maximum values for the selected metric. A popup button below the outline (2) lists the supported metrics:

• Busy Time— Total time spent running, including both user and non-idle system time

• User Time— Total time spent running in user space

• System Time— Total time spent running in supervisor space (kernel and driver code)

• Priority— Dynamic thread priority used by the scheduler

Information about how your application’s threads are being scheduled can be used to verify that what is actually happening on the system matches your expectations. Because the maximum time that a thread can run before it is suspended to run something else (the maximum quantum or time slice) is 10ms on Mac OS X, you can expect that a CPU-bound thread will generally be scheduled for several milliseconds per thread tenure. If you rewrite your CPU-bound, performance-critical code with multiple threads, and System Trace shows that these threads are only running for very short intervals (on the order of microseconds), this may indicate that the amount of work given to any worker thread is too small to amortize the overhead of creating and synchronizing your threads, or that there is a significant amount of serialization between these threads.

System Calls Summary

The System Calls Summary tab, shown in Figure 3-5, allows you to see the breakdown of system call time for each specific system call. Because System Trace normally records the user callstack for each system call, you can use this view to correlate system call time (and other metrics) directly to the locations in your application’s code that make system calls. This view is quite similar to Time Profile’s standard profile view, described in Profile Browser. In fact, many of the same tools are available. For example, the system call profile can be viewed as either a heavy or tree view (selected using the popup menu at the bottom). Similarly, data mining can be used to simplify complex system call callstacks (see Data Mining).

More settings for modifying this display are available in the Advanced Settings drawer, and are described in Summary View Advanced Settings.

Virtual Memory (VM) Faults Summary

The VM Faults Summary tab, depicted in Figure 3-6, allows you to see what code is causing virtual memory faults to occur. The purpose of this view is to help you find behavior that is normally transparent to software, and is obscured in a statistical time profile. Functionally, it acts just like the System Calls Summary tab.

By default, virtual memory faults are broken down by type:

• Page In— A page was brought back into memory from disk.

• Page Out— A page was pushed out to disk, to make room for other pages.

• Zero Fill— A previously unused page marked “zero fill on demand” was touched for the first time.

• Non-Zero Fill— A previously unused page not marked “zero fill on demand” was touched for the first time. Generally, this is only used in situations when the OS knows that page being allocated will immediately be overwritten with new data, such as when it allocates I/O buffers.

• Copy on Write (COW)— A shared, read-only page was modified, so the OS made a private, read-write copy for this process.

• Page Cache Hit— A memory-resident but unmapped page was touched.

• Guard Fault— A page fault to a “guard” page. These pages are inserted just past the end of memory buffers allocated using the special MacOS X “guard malloc” routines, which can be used in place of normal memory allocations during debugging to test for buffer overrun errors. One of these faults is generated when the buffer overruns.

• Failed Fault— Any page fault (regardless of type) that started and could not be completed. User processes will usually die when these occur, but the kernel usually handles them more gracefully in order to avoid a panic.

In some cases, virtual memory faults can represent a significant amount of overhead. For example, if you see a large amount of time being spent in zero fill faults, and correlate it to repeated allocation and subsequent deallocation of temporary memory in your code, you may be able to instead reuse a single buffer for the entire loop, reallocating it only when more space is needed. This type of optimization is especially useful in the case of very large (multiple page) allocations.

More settings for modifying this display are available in the Advanced Settings drawer, and are described in Summary View Advanced Settings.

Summary View Advanced Settings

When you are viewing the System Calls Summary and VM Faults Summary tabs, several options are available in the Advanced Settings drawer (see Advanced Settings Drawer), as seen in Figure 3-7:

1. Weight By Popup— the summary can construct the profile of system calls using several metrics. The following metrics can be selected:

   • CPU Time— Total system call or fault time spent actively running on a processor

   • Wait Time— Total system call or fault time spent blocked waiting on a resource or event

   • Total Time— Total system call or fault time, including both CPU and waiting time

   • Count— Total system call or fault count

   • Size— (VM fault tab only) Total number of bytes faulted, since a single fault can sometimes affect more than one page

2. Display Popup— This lets you choose between having the Self and Total columns display the raw Value for the selected metric or the percent of total system call or fault time. You can also change the columns between these modes individually by double clicking on either column.

3. Group by System Call/VM Fault Type— By default, the metrics are listed for each of the different types of system calls or faults in the trace. You can see summary statistics for all system calls or faults by deselecting this.

4. Callstack Data Mining— The System Call and VM Fault summaries support Shark’s data mining options, described in Data Mining, which can also be used to customize the presentation of the data.

Scheduler Trace

The Scheduler Trace Tab, shown in Figure 3-8, lists the intervals that threads were running on the system. The meanings of the columns are as follows:

• Index— A unique index for the thread interval, assigned by Shark

• Process— Shows the process to which the scheduled thread belongs. The process’ PID is in brackets after the name, which can be helpful if you have multiple copies of a process running simultaneously.

• Thread— The kernel’s identifier for the thread

• Time— Total time (the sum of user and system time) that the thread ran

• User Time— Time that the thread spent executing user code during the interval

• Sys Time— Time that the thread spent executing system (kernel) code during the interval

• Δt Prev— Time since this thread was previously scheduled

• Reason— Reason that the thread tenure ended (described in Thread Run Intervals)

• Priority— Dynamic scheduling priority of the thread

System Call Trace

The System Call Trace Tab, shown in Figure 3-9, lists the system call events that occurred during the trace. In most respects, this Tab behaves much like the scheduler tab described previously, but it does have a couple of new features.

You can inspect the first five integer arguments to each system call by selecting an entry in the table and looking at the arg fields near the bottom of the window.

The current user callstack is recorded for each system call. You can toggle the display of the Callstack Table by clicking the button in the lower right corner of the trace table. When visible, the Callstack Table displays the user callstack for the currently selected system call entry.

The meanings of the columns are as follows:

• Index— A unique index for the system call event, assigned by Shark

• Interval— Displays thread run interval(s) in which the system call occurred. Each system call occurs over one or more thread run intervals . If the system call begins and ends in the same thread interval, the Interval Column for that event lists only a single number: the index of the thread interval in which the event occurred. Otherwise, the beginning and ending thread interval indices are listed. Because it is possible for an event to start before the beginning of a trace session, or end after a trace session is stopped, event records may be incomplete. Incomplete events are listed with “?” for the unknown thread run interval index, and have a gray background in the event lists.

• Process— Shows the process in which the system call occurred. The process’ PID is in brackets after the name, which can be helpful if you have multiple copies of a process running simultaneously.

• Thread— Thread in which the system call occurred

• Name— Name of the system call

• Return— Shows the return value from the system call. Many system calls return zero for success, and non-zero for failure, so you can often spot useless system calls by looking for multiple failures. Eliminating streams of these can reduce the amount of time an application spends in wasted system call overhead.

• CPU Time— Time spent actively running on a processor

• Wait Time— Time spent blocked waiting on a resource or event

VM Fault Trace

The VM Fault Trace Tab, illustrated in Figure 3-10, lists the virtual memory faults that occurred. The current user callstack, if any, is recorded for each VM fault.

You can toggle the display of the Callstack Table, which displays the user callstack for the currently selected VM fault entry, by clicking the button in the lower right corner of the trace table.

The columns in the trace view have the following meanings in this tab:

• Index— A unique index for the VM fault event, assigned by Shark

• Interval— Displays thread run interval(s) in which the VM fault occurred. Each fault occurs over one or more thread run intervals. If the fault begins and ends in the same thread interval, the Interval Column for that event lists only a single number: the index of the thread interval in which the event occurred. Otherwise, the beginning and ending thread interval indices are listed. Because it is possible for an event to start before the beginning of a trace session, or end after a trace session is stopped, event records may be incomplete. Incomplete events are listed with “?” for the unknown thread run interval index, and have a gray background in the event lists.

• Process— Shows the process in which the VM fault occurred. The process’ PID is in brackets after the name, which can be helpful if you have multiple copies of a process running simultaneously.

• Thread— Thread in which the VM fault occurred

• Type— Fault type (see Virtual Memory (VM) Faults Summary for descriptions)

• CPU Time— Time spent actively running on a processor

• Wait Time— Time spent blocked waiting on a resource or event

• Library— In the case of a code fault, this lists the framework, library, or executable containing the faulted address. In contrast, it is blank for faults to data regions, such as the heap or stack.

• Address— Address in memory that triggered the fault

• Size— Number of bytes affected by the fault, an integral multiple of the 4096-byte system page size

Thread Run Intervals

Each time interval that a thread is actively running on a CPU is a thread run interval. Thread run intervals are depicted as solid rectangles in the Timeline View, as is shown in Figure 3-12, with lines depicting context switches joining the ends of the two threads running before and after each context switch.

Thread interval lines can be colored according to several metrics, including the CPU on which the thread ran, its dynamic priority, and the reason the thread was switched out. See Timeline View Advanced Settings for more information on how to control this.

You can inspect any thread run interval in the Timeline View by clicking on it. The inspector (see Figure 3-13) will indicate the amount of time spent running in user mode and supervisor mode, the reason the thread was switched out, and its dynamic priority.

There are five basic reasons a thread will be switched out by the system to run another thread:

• Blocked— The thread is waiting on a resource and has voluntarily released the processor while it waits.

• Explicit Yield— The thread voluntarily released its processor, even though it is not waiting on any particular resource.

• Quantum Expired— The thread ran for the maximum allowed time slice, normally 10ms, and was therefore interrupted and descheduled by the kernel.

• Preemption— A higher priority thread was made runnable, and the thread was interrupted in order to switch to that thread. It is also possible to be “urgently” preempted by some real-time threads.

• Urgent Preemption— Same as previous, except that the thread preempting us must have the processor immediately, usually due to real-time constraints.

System Calls

System calls represent explicit work done on behalf of the calling process. They are a secure way for user-space applications to employ kernel APIs. On Mac OS X, these APIs can be divided into four groups:

• BSD— Syscall, ioctl, sysctl APIs

• Mach— Basic services and abstractions (ports, locks, etc.)

• Locks— pthread mutex calls that trap to the kernel. These are a subset of Mach system calls.

• MIG Message— Mach interface generator routines, which are usually only used within the kernel

Calls from all of these groups are visible in Figure 3-14. Clicking on the icon for a system call will bring up the System Call Inspector, as seen in Figure 3-15. The resulting inspector displays many useful pieces of information which you can use to correlate the system call to you application’s code. The listed information includes:

• Type— The system call icon and a textual description

• Name— The system call name

• Number— The system call’s event index number (its number in the Trace View)

• Callstack— A backtrace of user space function calls that caused the system call

• Time — Total, CPU, and wait time

• Result— The return value from the call

• Arguments— The first four integer arguments

VM Faults

As is the case with almost all modern operating systems, Mac OS X implements a virtual memory system. Virtual memory works by dividing up the addressable space (typically 4GB on a 32-bit machine, currently 256 TB on 64-bit machines) into pages (typically 4 KB in size). Pages are brought into available physical memory from a backing store (typically a hard disk) on demand through the page fault mechanism. In addition to efficiently managing a system’s available physical memory, this added level of indirection provided by the virtual to physical address mapping allows for memory protection, shared memory, and other modern operating system capabilities. There are five virtual memory events on Mac OS X, all of which are faults (running code is interrupted to handle them the first time the page is touched) except for page outs, which are completed asynchronously.

• Page In— A page was brought back into memory from disk.

• Page Out— A page was pushed out to disk, to make room for other pages.

• Zero Fill— A previously unused page marked “zero fill on demand” was touched for the first time.

• Non-Zero Fill— A previously unused page not marked “zero fill on demand” was touched for the first time. Generally, this is only used in situations when the OS knows that page being allocated will immediately be overwritten with new data, such as when it allocates I/O buffers.

• Copy on Write (COW)— A shared, read-only page was modified, so the OS made a private, read-write copy for this process.

• Page Cache Hit— A memory-resident but unmapped page was touched.

• Guard Fault— A page fault to a “guard” page. These pages are inserted just past the end of memory buffers allocated using the special MacOS X “guard malloc” routines, which can be used in place of normal memory allocations during debugging to test for buffer overrun errors. One of these faults is generated when the buffer overruns.

• Failed Fault— Any page fault (regardless of type) that started and could not be completed. User processes will usually die when these occur, but the kernel usually handles them more gracefully in order to avoid a panic.

Three of these types of faults are visible in Figure 3-16. A zero-fill fault is circled to highlight it. Clicking on a VM Fault Icon will bring up the VM Fault Inspector, as seen in Figure 3-17. This inspector functions much like the System Call Inspector, except instead of listing arguments and return values, the VM Fault Inspector lists the fault address, size, and — for code faults — the library in which it occurred.

Interrupts

Interrupts are asynchronous signals that external hardware devices use to communicate to the processor that they require servicing. Most are associated with I/O devices, and signal either that new data has been received by an input device or that an output device needs more data to send. However, there are also other sources of interrupts inside of the computer system, such as DMA controllers and clock timers.

Here is an interrupt icon:

Because interrupts occur asynchronously, there is no correlation between the source of the interrupt and the thread being interrupted. As a result, and because most users of System Trace are primarily interested in examining the threading behavior of their own programs, the display of interrupt events in the Timeline View is disabled by default. See Timeline View Advanced Settings for instructions on how to enable these.

Clicking on an Interrupt icon will bring up the Interrupt Inspector. This inspector lists the amount of time the interrupt consumed, broken down by CPU and wait time.

Sign Posts

You can often get a good idea of your application’s current state by inspecting the user callstacks associated with the built-in VM fault and system call events that occur in your application. But an even more precise technique is to instrument your application with Sign Post events at critical points in your code (see Sign Posts for instructions as to how you can do this). For example, if you are developing an application that operates on video frames, you can insert a sign post marker whenever the processing of a new frame starts.

Here is a sign post icon:

Sign posts are displayed in the timeline alongside the other events. You can inspect each sign post by clicking its icon in the timeline. The inspector will indicate which thread it came from, its event name, the 4 user-specified ancillary data values for both the begin and the end point, and the associated user callstack (if any). If the sign post is an “interval” sign post, an under-bar will indicate its duration on the timeline, and the inspector will list the amount of time spent on the CPU and time spent Waiting between the begin and end event. Since you can supply different arguments to the start and end points of an interval sign post, the inspector supplies “Begin” and “End” tabs that display the arguments supplied to the start and end points, respectively.

Timeline View Advanced Settings

While you are in Timeline View, several options are available in the Advanced Settings drawer (see Advanced Settings Drawer), as seen in Figure 3-20.

1. Enable Thread Coloring— When enabled (the default), Shark attempts to color-code the threads in the timeline display using one of the algorithms selected below.

2. Color By— Assuming that you do choose to use thread coloring, this menu allows you to choose from among several different color schemes that allow you to see different trends:

   • CPU— Each CPU is assigned a different color, so you can see both how a processor is bouncing from one thread to another or, alternately, how a thread is bouncing from one processor to another. This is the default, and usually the most useful coloration.

   • Priority— Thread priority is assigned a color on a gradient from deep blue-violet colors (low priority) to bright, hot yellows and oranges (high priority). Mac OS X changes thread priority dynamically, depending upon how much CPU time each thread gets, so this color scheme is useful to see the effects of these dynamic changes over time.

   • Reason— Colors each thread run tenure based on the reason that it ended. See Thread Run Intervals for a list of the possible reasons that are used to color-code thread tenures.

3. Color Key— Displays the colors that Shark is currently using to display your threads.

4. Draw Context Switch Lines— Check this to enable (default) or disable the thin gray lines that show context switches, linking the thread tenures before and after the switch that ran on the same CPU core.

5. Detailed Event Icons— Deselecting this instructs Shark turn off the icons that identify the various types of VM faults and system calls and just replace them with generic “plain page” VM fault and “gray phone” system call icons.

6. Label Events— These checkboxes allow you to enable or disable the display of event icons either entirely, by type group, or on an individual, type-by-type basis. For example, you can use them to enable interrupt icons or to remove icons for events, such as VM faults, that you may not be interested in at the present time.