fprof(1)

Synopsis

fprof -s [-C[Logging=on|off,] [StartState=on|off,] [Accuracy=best|accurate|normal,] [LogPrefix=pathname]] command-line

fprof [-o|-O] [-m] log [log] . . .

fprof [-i] [log] . . .

fprof [-c] [log] . . .

Description

Profiling revolves around running experiments. An experiment consists of running the program that you want to analyze with profiling compiled into the program. For flow profiling, the -qf option must be given to cc(1) or CC(1C++). When a program being profiled is running (i.e., a flow-profile experiment is running), the current time is recorded every time a function is called and every time it exits.

There are three different uses for fprof:

• Setting up flow-profile experiment parameters

• Controlling the activity of a running experiment

• Viewing the results of experiments

The first 2 uses are optional. If the default configuration is the way you want it and the experiment needs no fine control, you can just compile your program with flow profiling, run the program and analyze the results. If this is all you need, viewing the results of experiments is described below.

Setting up flow-profile experiment parameters is accomplished in one of three ways: system-wide configuration files, environment variables or per-experiment command-line arguments. There are four configuration parameters:

Logging

Controls whether any logging will be performed on programs that were compiled for flow-profiling. By default, logging is on.

StartState

Controls whether the logging state is on when the experiment is begun. (The logging state is on by default.) If StartState is set to off, logging may be turned on while the program is running. The only reason to use this parameter is to preclude start-up information from a flow-profile log.

Accuracy

Set to one of best, accurate or normal. Accurate logs use the hardware time stamp capabilities of the Pentium CPU to write time stamp information accurate to the microsecond (at least). Normal logs will contain timestamps that are accurate to 1/100 of a second. Note that typical or default system configurations restrict use of the accurate system timer to programs running with root privilege. To enable user mode access to the timer, set the kernel tunable USER_RDTSC to 1. The best accuracy option will attempt to use the accurate timer if it is available. If the RDTSC timer is not available, not supported in the hardware or not available in user mode, fprof will default to normal accuracy mode. Best accuracy is the default.

LogPrefix

Allows you to choose where you would like the logs to be stored. When a program is begun that has logging turned on, an output file is created with the name LogPrefix.pid (where pid is the process-id of the running program). By default, LogPrefix is set to /tmp/out. This means that for a process with a pid of 12, its log will be the file /tmp/out.12.

Setting up system-wide configuration parameters requires the root privilege and is done with fprof -C (with no -s option). Once this is accomplished all experiments will use these parameters. The configuration is stored in the file /usr/ccs/lib/fprof.cfg.

The system-wide configuration may be superseded through the environment variables _FprofLogging, _FprofStartState, _FprofAccuracy and _FprofLogPrefix.

A third way to specify the configuration for a flow-profile experiment is to start the experiment using fprof -s. This sets the four environment variables above and executes the command-line specified in its argument.

Controlling the activity of a running experiment is accomplished using the third form of the command shown above. Control, in this case, means starting and stopping logging or putting marks in the log.

To specify which running processes are to be controlled, a set of log files are given as arguments (each log file corresponds to a process). The -o option sets the logging state to on. The -O option sets the logging state to off. The -m option places a mark record into the log at its current point.

Viewing the results of experiments is done using the fourth form of fprof. This form sets up an interactive shell for the user. The interface is that of the ksh(1) command, but more commands are available. These commands can be used like any shell commands, that is, they can be piped, redirected, etc.

A set of logs may be specified on the command-line. This is equivalent to starting fprof with no arguments and giving an open command to the interpreter with those logs (see open below). The -i option requests that an info (see below) command be done on the specified logs. It is common practice to call fprof -i right after an experiment to make sure that the log turned out the way you expected it to.

Time representation

Due to precision limitations, the maximum time interval representable in fprof is about 70 minutes. Therefore experiments should be limited to that interval.

Positions

To avoid ambiguity, discussion of bidirectional traversal through the log will be expressed in the following terms:

• earlier / later - in time sequence order from the start of the log to the end of the log file

• before (backward) / after (forward) - in traversal order.

Marks

Marks are means to locate quickly some interesting positions in the log file. Marks can be added to a log file during an experiment by using fprof -m.

In addition to marks made by the user in the log file, fprof can detect some interesting situations and consider them as virtual marks. fprof recognizes long intervals between records and occurences of a specific symbol.

If multiple marks are at the same position, they are considered one mark.

Long intervals occur if the time difference between two consecutive records is not smaller than the specified value. The value may be given in real time or in compensated time. The default interval is set to 0.5s in compensated time. The interval can be changed later using timescale. Setting the interval to zero disables the marks on long intervals.

Virtual marks on symbols occur when the name of the symbol in a record matches the regular expression set by a command marksym. When log files are opened, the virtual marks on symbols are disabled.

Labels

Specifying positions

Count: [-|+]number

Count of records relative to the current position. Zero is not a valid number in this context.

Mark: m[-|+]number

The number of marks from the current position. If the current position is located at a mark, this mark is not counted.

Time: t[-|+]number[unit]

The position immediately earlier than the record with the specified real time. A time not preceded by a sign is an absolute time; a signed time is relative to the current time. The current time is the time of the last record traversed. A number without a unit specification designates microseconds. Time units may be specified with an 'm' for milleseconds or 's' for seconds.

Label: $<label_var>

The absolute position indicated by a label. Labels are an internal representation of an absolute position in a log file. This internal representation can be assigned as values of shell variables. The label of the current position may be obtained using the 'label' command.

Commands

open log [log]...

Takes a list of logs and opens them for reading. This also closes any previously opened log files.

info

Writes information about the open logs to the standard output.

close

Closes logs opened by an open command.

output [ [start-position] end-position]

Writes records from the start-position through end-position to the standard output. If only one position is specified, it is taken as the end-position and the start-position is the current position. If the end-position is specified as a relative position, it is calculated relative to the start-position. If no position is given, 10 records are written starting at the current position as if 'output 10' was the command.

output_until_mark

Writes records to the standard output until it reaches the end of all logs or until it sees a marked entry.

search [-] regular-expression

Searches for the next log entry whose function call matches the regular expression and writes the record to the standard output. The optional '-' specifies that the search is backwards, otherwise forwards.

bracket

Writes all records between the previous mark and the next mark to the standard output.

marksym regular-expression

Set to automatically mark symbols matching the regular expression. If used without an argument, automatic marks on symbols is disabled.

rewind

Returns to the beginning of the first log.

seek position

Seek to the given position.

label

Writes the label of the current position to standard output.

seekmark [-]

Seeks forward to the next (or backwards to the previous if the '-' is present) mark.

timescale [r|c]

Without options, prints the current timerepresentation mode, real or compensated. Option -r' sets the mode to real mode; option -c sets the mode to compensated.

count [start-position [end-position]]

Gathers statistics on any subset of the log (or the whole log); there is no output. Positions may be specified in any form. If only one position is specified, it is treated as the starting position and statistics are accumulated to to end of file. If no arguments are given, statistics are gathered for the entire file. The end position may not be earlier than the start-position. For example, count m-1 m+1 would gather statistics from the previous mark to the next; count t-1000 t+1000 would gather statistics from the previous millisecond to the next; count t1000 would gather statistics from one millisecond into the log until the end.

stats

Prints out call statistics gathered by count. It shows each function called, how many times it was called, how much time it spent running (time at top of stack) and how much time it or any function it called spent running (time on stack).

callers [-d] regular-expression [regular-expression]...

Prints out caller statistics gathered by count. The optional -d limits the output to only direct callers. For each function that matches any of the regular expressions, print out the:

• number of calls to the function that resulted from the execution of each other function,

• percentage of time spent in the function that resulted from the direct call by each other function,

• percentage time the function spent on the stack that resulted from the execution of each other function.

For example, assume there is a function x that is consuming a lot of time on the stack (not necessarily on top of the stack), callers will tell you in its 3rd column how much of that time was spent from a call from each other function.

callees [-d] regular-expression [regular-expression]...

Prints out callee statistics gathered by count. The optional -d limits the output to only the direct callees. This is similar to callers. Used when one notices that a certain function is spending a lot of time somewhere on the stack.

Files

References