suzanne.soy/profile
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Update profile docs to be consistent with output of errortrace mode.

Browse Source 
original commit: 8683a2188b36e18f4ef7c9288f0cc06bd5d629a8
This commit is contained in:
Vincent St-Amour 2013-11-07 16:45:22 -05:00
parent acd552e11d
commit 67580c1774
4 changed files with 73 additions and 66 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

66
pkgs/profile-pkgs/profile-doc/profile/scribblings/analyzer.scrbl
View File

@ -54,13 +54,12 @@ Represents an analyzed profile result.
integer identifier. These identifiers are listed for each function integer identifier. These identifiers are listed for each function
call, and the total time spent in each thread is in this field.} call, and the total time spent in each thread is in this field.}
@item{@racket[nodes] is a list of nodes representing all observed @item{@racket[nodes] is a list of nodes representing all observed functions
functions. These nodes are the components of the call-graph that (or, when using Errortrace, expressions). These nodes are the components of
the analyzer assembles (see the @racket[edge] field). The nodes are the call-graph that the analyzer assembles (see the @racket[edge] field).
sorted by a topological top-to-bottom sort, and by decreasing total The nodes are sorted by a topological top-to-bottom sort, and by decreasing
amount of time (time spent either in the function or in its callees) total amount of time (time spent either in the function or in its callees) as
as a secondary key. It does not include the special a secondary key. It does not include the special @racket[*-node].}
@racket[*-node].}
@item{@racket[*-node] holds a ``special'' root node value that is @item{@racket[*-node] holds a ``special'' root node value that is
constructed for every call graph. This node is used as the caller constructed for every call graph. This node is used as the caller
@ -77,7 +76,7 @@ Represents an analyzed profile result.
]} ]}
@defstruct*[node ([id (or/c #f symbol?)] @defstruct*[node ([id (or/c #f symbol? any/c)]
[src (or/c #f srcloc?)] [src (or/c #f srcloc?)]
[thread-ids (listof exact-nonnegative-integer?)] [thread-ids (listof exact-nonnegative-integer?)]
[total exact-nonnegative-integer?] [total exact-nonnegative-integer?]
@ -85,38 +84,38 @@ Represents an analyzed profile result.
[callers (listof edge?)] [callers (listof edge?)]
[callees (listof edge?)])]{ [callees (listof edge?)])]{
Represents a function call node in the call graph of an analyzed Represents a function call (or, when using Errortrace, expression) node in the
profile result. call graph of an analyzed profile result.
@itemize[ @itemize[
@item{The @racket[id] and @racket[src] fields hold a symbol naming the @item{The @racket[id] and @racket[src] fields hold a symbol naming the function
function and/or its source location as a @racket[srcloc] value. (in @racket[continuation-mark-set->context] mode) or an S-expression stub (in
This is the same as the results of Errortrace mode), and/or its source location as a @racket[srcloc] value.
@racket[continuation-mark-set->context], so at most one of these can This is the same as the results of @racket[continuation-mark-set->context],
be @racket[#f], except for the special @racket[*-node] (see the so at most one of these can be @racket[#f], except for the special
@racket[profile] struct) that can be identified by both being @racket[*-node] (see the @racket[profile] struct) that can be identified by
@racket[#f].} both being @racket[#f].}
@item{@racket[thread-ids] holds a list of thread identifiers that were @item{@racket[thread-ids] holds a list of thread identifiers that were
observed executing this function.} observed executing this function.}
@item{@racket[total] holds the total time (in milliseconds) that this @item{@racket[total] holds the total time (in milliseconds) that this function
function was anywhere on the stack. It is common to see a few (or expression) was anywhere on the stack. It is common to see a few
toplevel functions that have close to a 100% total time, but toplevel functions that have close to a 100% total time, but otherwise small
otherwise small @racket[self] times---these functions are the ones @racket[self] times---these functions are the ones that initiate the actual
that initiate the actual work, but they don't do any hard work work, but they don't do any hard work directly.}
directly.}
@item{@racket[self] holds the total time (in milliseconds) that this @item{@racket[self] holds the total time (in milliseconds) that this function
function was observed as the leaf of the stack. It represents the (or expression) was observed as the leaf of the stack. It represents the
actual work done by this function, rather than the @racket[total] actual work done by this function, rather than the @racket[total] time spent
time spent by both the function and its callees.} by both the function and its callees.}
@item{@racket[callers] and @racket[callees] hold the list of callers @item{@racket[callers] and @racket[callees] hold the list of callers and
and callees. The nodes are not actually held in these lists, callees or, in Errortrace modes, expressions that step to or from the current
instead, @racket[edge] values are used---and provide information expression. The nodes are not actually held in these lists, instead,
specific to each edge in the call-graph.} @racket[edge] values are used---and provide information specific to each edge
in the call-graph.}
]} ]}
@ -127,8 +126,9 @@ profile result.
[callee node?] [callee node?]
[callee-time exact-nonnegative-integer?])]{ [callee-time exact-nonnegative-integer?])]{
Represents an edge between two function call nodes in the call graph Represents an edge between two function call nodes in the call graph of an
of an analyzed profile result. analyzed profile result or, in Errortrace mode, an edge corresponding to an
evaluation step between two expressions.
@itemize[ @itemize[

28
pkgs/profile-pkgs/profile-doc/profile/scribblings/profile.scrbl
View File

@ -5,17 +5,23 @@
@title{Profile: Statistical Profiler} @title{Profile: Statistical Profiler}
The @racketmodname[profile] collection implements a statistical The @racketmodname[profile] collection implements a statistical profiler. The
profiler. The profiling is done by running a background thread that profiling is done by running a background thread that collects stack snapshots
collects stack snapshots via @racket[continuation-mark-set->context], either via @racket[continuation-mark-set->context] or via @seclink["top" #:doc
meaning that the result is an estimate of the execution costs and it '(lib "errortrace/scribblings/errortrace.scrbl")]{Errortrace}, meaning that the
is limited to the kind of information that result is an estimate of the execution costs.
@racket[continuation-mark-set->context] produces (most notably being
limited to functions calls, and subject to compiler optimizations); When using @racket[continuation-mark-set->context], it is limited to the kind
but the result is often useful. In practice, since this method does of information that @racket[continuation-mark-set->context] produces (most
not require recompilation of your source and has very little runtime notably being limited to functions calls, and subject to compiler
overhead, it can be used for longer runs which compensates for these optimizations); but the result is often useful. In practice, since this method
limits. does not require recompilation of your source and has very little runtime
overhead, it can be used for longer runs which compensates for these limits.
When using @seclink["top" #:doc '(lib
"errortrace/scribblings/errortrace.scrbl")]{Errortrace}, profiles are more
precise and more fine-grained (expression-level instead of function-level) but
profiling has higher overhead and recompilation may be necessary.
@table-of-contents[] @table-of-contents[]

31
pkgs/profile-pkgs/profile-doc/profile/scribblings/renderers.scrbl
View File

@ -31,7 +31,7 @@ function that consumes a @racket[profile] instance. See the
Prints the given @racket[profile] results as a textual table. Prints the given @racket[profile] results as a textual table.
The printout begins with general information about the profile, The printout begins with general information about the profile,
followed by a table with an entry for each function in the call graph. followed by a table with an entry for each node in the call graph.
The entries are displayed in a topological order (roughly, since the The entries are displayed in a topological order (roughly, since the
graph can have cycles). This means that it is usually easy to find graph can have cycles). This means that it is usually easy to find
the callers and callees of a function in its close environment. the callers and callees of a function in its close environment.
@ -42,34 +42,35 @@ Each row in the table has the following format:
[N1] N2(N3%) N4(N5%) A ...path/to/source.rkt:12:34 [N1] N2(N3%) N4(N5%) A ...path/to/source.rkt:12:34
C [M3] M4%} C [M3] M4%}
with the following meaning of the numbers and labels: with the following meaning of the numbers and labels:
@itemize[ @itemize[
@item{@tt{A} --- the name of the function that this node represents, @item{@tt{A} --- the name of the function (or a stub of the expression) that
followed by the source location for the function if it is known. this node represents, followed by the source location for the function if it
The name can be ``???'' for anonymous functions, which will be is known. The name can be ``???'' for anonymous functions, which will be
identified with their source location.} identified with their source location.}
@item{@tt{N1} --- an integer label associated with this node in the @item{@tt{N1} --- an integer label associated with this node in the
printout. This label is used to mark references to this function, printout. This label is used to mark references to this function/expression,
since symbolic names are not unique (and they can be missing or very since symbolic names are not unique (and they can be missing or very
long). The labels are assigned from the top.} long). The labels are assigned from the top.}
@item{@tt{N2} --- the time (in milliseconds) that this function has @item{@tt{N2} --- the time (in milliseconds) that this function/expression has
been anywhere in a stack snapshot. This is the total time that the been anywhere in a stack snapshot. This is the total time that the
execution was somewhere in this function or in its callees. execution was somewhere in this function/expression or in its callees.
(Corresponds to the @racket[node-total] field.)} (Corresponds to the @racket[node-total] field.)}
@item{@tt{N3} --- this is the percentage of the node's total time @item{@tt{N3} --- this is the percentage of the node's total time
(@tt{N2}) from the total observed time of the profile. An entry (@tt{N2}) from the total observed time of the profile. An entry
with a 100% refers to a function that was active throughout the with a 100% refers to a function/expression that was active throughout
whole execution.} the whole execution.}
@item{@tt{N4} --- the time (in milliseconds) that this function has @item{@tt{N4} --- the time (in milliseconds) that this function/expression has
been at the top of the stack snapshot. This is the time that this been at the top of the stack snapshot. This is the time that this
function was itself doing work rather than calling other functions. function/expression was itself doing work rather than calling other
(Corresponds to the @racket[node-self] field.)} functions/expressions. (Corresponds to the @racket[node-self] field.)}
@item{@tt{N5} --- this is the percentage of @tt{N4} out of the total @item{@tt{N5} --- this is the percentage of @tt{N4} out of the total
observed time of the profile. Functions with high values here can observed time of the profile. Functions/expressions with high values here can
be good candidates for optimization, But, of course, they can be good candidates for optimization, But, of course, they can
represent doing real work for a caller that needs to be optimized.} represent doing real work for a caller that needs to be optimized.}
@item{@tt{B} and @tt{C} --- these are labels for the callers and @item{@tt{B} and @tt{C} --- these are labels for the callers and
callees of the function. Any number of callers and callees can callees of the function/expression. Any number of callers and callees can
appear here (including 0). The function itself can also appear in appear here (including 0). The function/expression itself can also appear in
both places if it is (non-tail) recursive.} both places if it is (non-tail) recursive.}
@item{@tt{M1} and @tt{M3} --- the index numbers for @tt{B} and @item{@tt{M1} and @tt{M3} --- the index numbers for @tt{B} and
@tt{C}. They can be used to disambiguate functions with the same @tt{C}. They can be used to disambiguate functions with the same

14
pkgs/profile-pkgs/profile-doc/profile/scribblings/toplevel.scrbl
View File

@ -42,13 +42,13 @@ can customize the profiling:
actually sampled. (The @racket[delay] value is passed on to actually sampled. (The @racket[delay] value is passed on to
@racket[create-sampler], which creates the sampler thread.)} @racket[create-sampler], which creates the sampler thread.)}
@item{When @racket[use-errortrace?] is not @racket[#f], more accurate @item{When @racket[use-errortrace?] is not @racket[#f], more accurate stack
stack snapshots are captured using snapshots are captured using @seclink["top" #:doc '(lib
@other-doc['(lib "errortrace/scribblings/errortrace.scrbl")]. Note that "errortrace/scribblings/errortrace.scrbl")]{Errortrace}. Note that when this
when this is provided, it will only profile uncompiled files and files is provided, it will only profile uncompiled files and files compiled while
compiled while using @racket[errortrace-compile-handler], and the profiled program using @racket[errortrace-compile-handler], and the profiled program must be
must be run using @commandline{racket -l errortrace -t program.rkt} run using @commandline{racket -l errortrace -t program.rkt} Removing compiled
Removing compiled files (with extension @tt{.zo}) is sufficient to enable this.} files (with extension @tt{.zo}) is sufficient to enable this.}
@item{Due to the statistical nature of the profiler, longer executions @item{Due to the statistical nature of the profiler, longer executions
result in more accurate analysis. You can specify a number of result in more accurate analysis. You can specify a number of