fprof(1)
fprof --
configure, start, control or analyze the results of a flow-profile experiment
Synopsis
fprof -C [Logging=on|off,] [StartState=on|off,] [Accuracy=best|accurate|normal,]
[LogPrefix=pathname]
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
fprof is the controlling program for the flow profiling features. Flow
profiling is a form of tracing used to analyze performance and locality of
reference of text.
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
fprof may present time as either real time or compensated time. Real time
is the physical time that has elapsed as the experiment is run. Compensated
time is real time minus the overhead of the profiling code added to the user
code. All statistics are calculated using compensated time. Time may be
printed with the output command as either compensated time
or real time.
Real time is denoted by an 'r' suffix. The mode to be used when printing
time may be changed using the timescale command.
Due to precision limitations, the maximum time interval representable in
fprof is about 70 minutes. Therefore experiments should be limited to that
interval.
Positions
An analysis session consists of reading a log file or multiple log files
using the idea of the current position. Initially this position is the
the beginning of the file. As the position is moved forward or backward
through the file, activities can be proformed with these records as
they are passed. The current position always points between two records.
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.
If a file is being traversed in a backwards direction, the "later" position
will occur "before" the "earlier" position
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
A label describes some absolute position in the log file for the purpose of
returning to that position later. Labels are not identifiers, but are
tokens of an unpublished format and specific to the version of fprof
being used and the set of files being analyzed. These tokens may be
assigned as values to shell variables for use as a position later in
the analysis process, for example, X=`label`.
Specifying positions
Positions in the log may be described as absolute positions or relative to
the current position in the log. Positions may be expressed in 4 possible
formats. A negative value indicates a backwards direction.
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
The available commands are:
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.
The term compile is often associated with flow-profile logs. Compiling
a log is analogous to compiling a program. It means that the log is converted
to a format that can be read faster. As a log is read for the first time by
either fprof or
lrt_scan(1)
(which analyzes the results of a
flow-profiling experiment for locality of reference tuning),
the log is compiled so that it can be
read faster the next time. During that time, the log file(s) may exist
in a partially compiled state and should not be processed by multiple
fprof sessions. To fully compile a log file, use the final form of the
command shown above.
Files
/usr/ccs/lib/fprof.cfg system-wide configuration file
References
CC(1C++),
cc(1),
ksh(1),
lprof(1),
lrt_scan(1)
prof(1),
regcmp(3G)
© 2004 The SCO Group, Inc. All rights reserved.
UnixWare 7 Release 7.1.4 - 25 April 2004