Update and revise docs.
original commit: 3cc51f20ac787c87b3d337d96e2afa0eecd5452d
This commit is contained in:
Eli Barzilay
parent
71b66bbf9f
commit
9f36d5a2cb
|
|
@ -1,45 +1,45 @@
|
|||
#lang scribble/doc
|
||||
|
||||
@(require scribble/manual
|
||||
(for-label scheme profile/analyzer))
|
||||
(for-label racket/base profile/analyzer))
|
||||
|
||||
@title[#:tag "analyzer"]{Analyzing Profile Data}
|
||||
|
||||
@defmodule[profile/analyzer]
|
||||
|
||||
Once a profile run is done, and the results are collected, the next
|
||||
step is to analyze the data. In this step the sample time are
|
||||
computed and summed, a call-graph representing the observed function
|
||||
calls is built, and per-node and per-edge information is created.
|
||||
This is the job of the main function provided by
|
||||
@racket[profile/analyzer].
|
||||
Once a profile run is done and the results are collected, the next
|
||||
step is to analyze the data. In this step sample times are computed
|
||||
and summed, a call-graph representing observed function calls is
|
||||
built, and per-node and per-edge information is created. This is the
|
||||
job of the main function provided by @racket[profile/analyzer].
|
||||
|
||||
@defproc[(analyze-samples [raw-sample-data any/c])
|
||||
profile?]{
|
||||
|
||||
This function consumes the raw result of the
|
||||
@seclink["sampler"]{sampler} (which is given in an undocumented form),
|
||||
analyzes it, and returns a @racket[profile] value holding the analyzed
|
||||
results. Without this function, the results of the sampler are
|
||||
@seclink["sampler"]{sampler} (given in an undocumented form), analyzes
|
||||
it, and returns a @racket[profile] value holding the analyzed results.
|
||||
Without this function, the results of the sampler should be considered
|
||||
meaningless.}
|
||||
|
||||
|
||||
@defstruct[profile ([total-time exact-nonnegative-integer?]
|
||||
[cpu-time exact-nonnegative-integer?]
|
||||
[sample-number exact-nonnegative-integer?]
|
||||
[thread-times (listof (cons exact-nonnegative-integer?
|
||||
exact-nonnegative-integer?))]
|
||||
[nodes (listof node?)]
|
||||
[*-node node?])]{
|
||||
@defstruct*[profile ([total-time exact-nonnegative-integer?]
|
||||
[cpu-time exact-nonnegative-integer?]
|
||||
[sample-number exact-nonnegative-integer?]
|
||||
[thread-times (listof (cons exact-nonnegative-integer?
|
||||
exact-nonnegative-integer?))]
|
||||
[nodes (listof node?)]
|
||||
[*-node node?])]{
|
||||
|
||||
Represents the analyzed profile result.
|
||||
Represents an analyzed profile result.
|
||||
|
||||
@itemize[
|
||||
|
||||
@item{@racket[total-time] is the total observed time (in milliseconds)
|
||||
included in the profile. This is different than the actual time the
|
||||
profiling took, due to unaccounted-for time spent in untracked
|
||||
threads. (E.g., the sampler thread itself.)}
|
||||
included in the profile run. This can be different from the actual
|
||||
time the profiling took, due to unaccounted-for time spent in
|
||||
untracked threads. (E.g., time spent in the sampler thread
|
||||
itself.)}
|
||||
|
||||
@item{@racket[cpu-time] is the actual cpu time consumed by the process
|
||||
during the profiler's work.}
|
||||
|
|
@ -61,69 +61,70 @@ Represents the analyzed profile result.
|
|||
amount of time (time spent either in the function or in its callees)
|
||||
as a secondary key.}
|
||||
|
||||
@item{@racket[*-node] holds a ``special'' node value that is
|
||||
constructed for every graph. This node is used as the caller for
|
||||
all top-level function nodes and as the callee for all leaf nodes.
|
||||
It can therefore be used to start a scan of the call graph. In
|
||||
addition, the times associated with its "callers and callees"
|
||||
actually represent the time these functions spent being the root of
|
||||
the computation or its leaf. (This can be different from a node's
|
||||
``self'' time, since it is divided by the number of instances a
|
||||
function had on the stack for every sample --- so for recursive
|
||||
functions this value is different from.)}
|
||||
@item{@racket[*-node] holds a ``special'' root node value that is
|
||||
constructed for every call graph. This node is used as the caller
|
||||
for all top-level function nodes and as the callee for all leaf
|
||||
nodes. It can therefore be used to start a recursive scan of the
|
||||
call graph. In addition, the times associated with its ``callers''
|
||||
and ``callees'' actually represent the time these functions spent
|
||||
being the root of the computation or its leaf. (This can be
|
||||
different from a node's ``self'' time, since it is divided by the
|
||||
number of instances a function had on the stack in each sample---so
|
||||
for recursive functions this value is always different from the
|
||||
``self'' time.)}
|
||||
|
||||
]}
|
||||
|
||||
|
||||
@defstruct[node ([id (or/c #f symbol?)]
|
||||
[src (or/c #f srcloc?)]
|
||||
[thread-ids (listof exact-nonnegative-integer?)]
|
||||
[total exact-nonnegative-integer?]
|
||||
[self exact-nonnegative-integer?]
|
||||
[callers (listof edge?)]
|
||||
[callees (listof edge?)])]{
|
||||
@defstruct*[node ([id (or/c #f symbol?)]
|
||||
[src (or/c #f srcloc?)]
|
||||
[thread-ids (listof exact-nonnegative-integer?)]
|
||||
[total exact-nonnegative-integer?]
|
||||
[self exact-nonnegative-integer?]
|
||||
[callers (listof edge?)]
|
||||
[callees (listof edge?)])]{
|
||||
|
||||
Represents a function call node in the call graph of an analyzed
|
||||
profile result.
|
||||
|
||||
@itemize[
|
||||
|
||||
@item{The @racket[id] and @racket[src] field hold a symbol naming the
|
||||
@item{The @racket[id] and @racket[src] fields hold a symbol naming the
|
||||
function and/or its source location as a @racket[srcloc] value.
|
||||
This is the same as the results of
|
||||
@racket[continuation-mark-set->context], so at most of of these can
|
||||
@racket[continuation-mark-set->context], so at most one of these can
|
||||
be @racket[#f], except for the special @racket[*-node] (see the
|
||||
@racket[profile] struct) that can be identified by both of these
|
||||
being @racket[#f].}
|
||||
@racket[profile] struct) that can be identified by both being
|
||||
@racket[#f].}
|
||||
|
||||
@item{@racket[thread-ids] holds a list of thread identifiers that were
|
||||
observed executing this function.}
|
||||
|
||||
@item{@racket[total] holds the total time (in milliseconds) where this
|
||||
@item{@racket[total] holds the total time (in milliseconds) that this
|
||||
function was anywhere on the stack. It is common to see a few
|
||||
toplevel functions that have close to a 100% total time, but
|
||||
otherwise small @racket[self] times --- these functions are the ones
|
||||
that derive the work that was done, but they don't do any hard work
|
||||
otherwise small @racket[self] times---these functions are the ones
|
||||
that initiate the actual work, but they don't do any hard work
|
||||
directly.}
|
||||
|
||||
@item{@racket[self] holds the total time (in milliseconds) where this
|
||||
@item{@racket[self] holds the total time (in milliseconds) that this
|
||||
function was observed as the leaf of the stack. It represents the
|
||||
actual work done by this function, rather than @racket[total] that
|
||||
represents the work done by both the function and its callees.}
|
||||
actual work done by this function, rather than the @racket[total]
|
||||
time spent by both the function and its callees.}
|
||||
|
||||
@item{@racket[callers] and @racket[callees] hold the list of caller
|
||||
and callee nodes. The nodes are not actually held in these lists,
|
||||
instead, @racket[edge] values are used --- and provide information
|
||||
specific to an edge in the call-graph.}
|
||||
@item{@racket[callers] and @racket[callees] hold the list of callers
|
||||
and callees. The nodes are not actually held in these lists,
|
||||
instead, @racket[edge] values are used---and provide information
|
||||
specific to each edge in the call-graph.}
|
||||
|
||||
]}
|
||||
|
||||
|
||||
@defstruct[edge ([total exact-nonnegative-integer?]
|
||||
[caller node?]
|
||||
[caller-time exact-nonnegative-integer?]
|
||||
[callee node?]
|
||||
[callee-time exact-nonnegative-integer?])]{
|
||||
@defstruct*[edge ([total exact-nonnegative-integer?]
|
||||
[caller node?]
|
||||
[caller-time exact-nonnegative-integer?]
|
||||
[callee node?]
|
||||
[callee-time exact-nonnegative-integer?])]{
|
||||
|
||||
Represents an edge between two function call nodes in the call graph
|
||||
of an analyzed profile result.
|
||||
|
|
|
|||
|
|
@ -1,15 +1,15 @@
|
|||
#lang scribble/doc
|
||||
|
||||
@(require scribble/manual
|
||||
(for-label scheme))
|
||||
(for-label racket/base))
|
||||
|
||||
@title{Profile: Statistical Profiler}
|
||||
|
||||
The @racket[profile] collection implements a statistical profiler.
|
||||
The profiling is done by running a background thread that collects
|
||||
stack snapshots via @racket[continuation-mark-set->context], meaning
|
||||
that the result is an estimate of the execution costs and it is
|
||||
limited to the kind of information that
|
||||
The @racketmodname[profile] collection implements a statistical
|
||||
profiler. The profiling is done by running a background thread that
|
||||
collects stack snapshots via @racket[continuation-mark-set->context],
|
||||
meaning that the result is an estimate of the execution costs and it
|
||||
is limited to the kind of information that
|
||||
@racket[continuation-mark-set->context] produces (most notably being
|
||||
limited to functions calls, and subject to compiler optimizations);
|
||||
but the result is often useful. In practice, since this method does
|
||||
|
|
|
|||
|
|
@ -1,7 +1,7 @@
|
|||
#lang scribble/doc
|
||||
|
||||
@(require scribble/manual
|
||||
(for-label scheme
|
||||
(for-label racket/base
|
||||
profile/analyzer
|
||||
(prefix-in text: profile/render-text)
|
||||
(prefix-in graphviz: profile/render-graphviz)))
|
||||
|
|
@ -9,11 +9,11 @@
|
|||
@title[#:tag "renderers"]{Profile Renderers}
|
||||
|
||||
After collecting the profile samples and analyzing the data, the last
|
||||
aspect of profiling is to render the results. The profile collection
|
||||
provides several renderers, each providing a rendering function that
|
||||
consumes a @racket[profile] instance. See the
|
||||
step of the profiling process is to render the results. The profile
|
||||
collection provides several renderers, each providing a rendering
|
||||
function that consumes a @racket[profile] instance. See the
|
||||
@seclink["analyzer"]{analyzer} section for a description of the
|
||||
@racket[profile] struct if you want to implement your own renderer.
|
||||
@racket[profile] struct if you want to implement a new renderer.
|
||||
|
||||
@;--------------------------------------------------------------------
|
||||
@section{Textual Rendering}
|
||||
|
|
@ -29,7 +29,7 @@ consumes a @racket[profile] instance. See the
|
|||
|
||||
Prints the given @racket[profile] results as a textual table.
|
||||
|
||||
The printout begins with some general facts about the profile, and
|
||||
The printout begins with some general details about the profile, and
|
||||
then a table that represents the call-graph is printed. Each row in
|
||||
this table looks like:
|
||||
|
||||
|
|
@ -38,17 +38,17 @@ this table looks like:
|
|||
[N1] N2(N3%) N4(N5%) A ...path/to/source.rkt:12:34
|
||||
C [M3] M4%}
|
||||
|
||||
Where actual numbers appear in the printout. The meaning of the
|
||||
where actual numbers appear in the printout. The meaning of the
|
||||
numbers and labels is as follows:
|
||||
@itemize[
|
||||
@item{@tt{A} --- the name of the function that this node represents,
|
||||
followed by the source location for the function if it is known.
|
||||
The name can be ``???'' for functions with no identifier, but in
|
||||
this case the source location will identify them.}
|
||||
The name can be ``???'' for anonymous functions, but in this case
|
||||
the source location will identify them.}
|
||||
@item{@tt{N1} --- an index number associated with this node. This is
|
||||
important in references to this function, since the symbolic names
|
||||
are not unique (and some can be missing). The number itself has no
|
||||
significance, it simply goes from 1 up.}
|
||||
useful in references to this function, since the symbolic names are
|
||||
not unique (and some can be missing). The number itself has no
|
||||
significance.}
|
||||
@item{@tt{N2} --- the time (in milliseconds) that this function has
|
||||
been anywhere in a stack snapshot. This is the total time that the
|
||||
execution was somewhere in this function or in its callees.
|
||||
|
|
@ -59,13 +59,12 @@ numbers and labels is as follows:
|
|||
whole execution.}
|
||||
@item{@tt{N4} --- the time (in milliseconds) that this function has
|
||||
been at the top of the stack snapshot. This is the time that this
|
||||
function consumed doing work itself rather than calling other
|
||||
functions. (Corresponds to the @racket[node-self] field.)}
|
||||
function was itself doing work rather than calling other functions.
|
||||
(Corresponds to the @racket[node-self] field.)}
|
||||
@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
|
||||
be good candidates for optimization, But, of course, they can
|
||||
represent doing real work due to one of its callers that need 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
|
||||
callees of the function. Any number of callers and callees can
|
||||
appear here (including 0). The function itself can also appear in
|
||||
|
|
|
|||
|
|
@ -1,7 +1,7 @@
|
|||
#lang scribble/doc
|
||||
|
||||
@(require scribble/manual
|
||||
(for-label scheme profile/sampler profile/analyzer))
|
||||
(for-label racket/base profile/sampler profile/analyzer))
|
||||
|
||||
@title[#:tag "sampler"]{Collecting Profile Information}
|
||||
|
||||
|
|
@ -13,7 +13,7 @@
|
|||
[super-cust custodian? (current-custodian)])
|
||||
((symbol?) (any/c) . ->* . any/c)]{
|
||||
|
||||
Creates a sample collector thread, which tracks the given
|
||||
Creates a stack-snapshot collector thread, which tracks the given
|
||||
@racket[to-track] value every @racket[delay] seconds. The
|
||||
@racket[to-track] value can be either a thread (track just that
|
||||
thread), a custodian (track all threads managed by the custodian), or
|
||||
|
|
@ -26,33 +26,33 @@ consisting of a symbol and an optional argument, and can affect the
|
|||
sampler. The following messages are currently supported:
|
||||
@itemize[
|
||||
|
||||
@item{@racket['pause] and @racket['resume] will stop or resume data
|
||||
collection. These messages can be nested. Note that the thread will
|
||||
continue running it will just stop collecting snapshots.}
|
||||
@item{@racket['pause] and @racket['resume] will stop or resume
|
||||
snapshot collection. These messages can be nested. Note that the
|
||||
thread will continue running---it will just stop collecting
|
||||
snapshots.}
|
||||
|
||||
@item{@racket['stop] kills the controlled thread. It should be called
|
||||
@item{@racket['stop] kills the sampler thread. It should be called
|
||||
when no additional data should be collected. (This is currently
|
||||
irreversible: there is no message to start a new sampler thread.)}
|
||||
|
||||
@item{@racket['set-tracked!] with a value will change the tracked
|
||||
objects (initially specified as the @racket[to-track] argument) to
|
||||
the given value.}
|
||||
object(s) which were initially specified as the @racket[to-track]
|
||||
argument.}
|
||||
|
||||
@item{@racket['set-tracked!] with a value will change the delay that
|
||||
the sampler us taking between snapshots. Note that although
|
||||
changing this means that the snapshots are not uniformly
|
||||
distributed, the results will still be sensible --- this is because
|
||||
the cpu time between samples is taken into account when the
|
||||
resulting data is analyzed.}
|
||||
@item{@racket['set-tracked!] with a numeric value will change the
|
||||
delay that the sampler is taking between snapshots. Note that
|
||||
although changing this means that the snapshots are not uniformly
|
||||
distributed, the results will still be correct: the cpu time between
|
||||
samples is taken into account when the collected data is analyzed.}
|
||||
|
||||
@item{Finally, a @racket['get-snapshots] message will make the
|
||||
controller return the currently collected data. Note that this can
|
||||
be called multiple times, each call will return the data thatis
|
||||
be called multiple times, each call will return the data that is
|
||||
collected up to that point in time. In addition, it can be (and
|
||||
usually is) called after the sampler was stopped.
|
||||
|
||||
The value that is returned should be considered as an undocumented
|
||||
internal detail of the profiler, to be sent to
|
||||
internal detail of the profiler, intended to be sent to
|
||||
@racket[analyze-samples] for analysis. The reason this is not done
|
||||
automatically, is that a future extension might allow you to combine
|
||||
several sampler results, making it possible to combine a profile
|
||||
|
|
|
|||
|
|
@ -1,8 +1,8 @@
|
|||
#lang scribble/doc
|
||||
|
||||
@(require scribble/manual
|
||||
(for-label scheme profile profile/sampler
|
||||
(only-in profile/analyzer analyze-samples)
|
||||
(for-label racket/base profile profile/sampler
|
||||
(only-in profile/analyzer analyze-samples profile?)
|
||||
(prefix-in text: profile/render-text)))
|
||||
|
||||
@title{Toplevel Interface}
|
||||
|
|
@ -10,7 +10,7 @@
|
|||
@defmodule[profile]
|
||||
|
||||
This module provides one procedure and one macro that are convenient
|
||||
high-level entry points for timing expressions. This hides the
|
||||
high-level entry points for profiling expressions. It abstracts over
|
||||
details that are available through other parts of the library, and is
|
||||
intended as a convenient tool for profiling code.
|
||||
|
||||
|
|
@ -25,53 +25,55 @@ intended as a convenient tool for profiling code.
|
|||
#f])
|
||||
void?]{
|
||||
|
||||
Executes the given thunk while collecting profiling data, and render
|
||||
this data when done. Keyword arguments can customize the profiling:
|
||||
Executes the given @racket[thunk] and collect profiling data during
|
||||
execution, eventually analyzing and rendering this. Keyword arguments
|
||||
can customize the profiling:
|
||||
@itemize[
|
||||
|
||||
@item{The profiler works by @racket[create-sampler] starting a
|
||||
``sampler'' thread whose job is to collect stack samples
|
||||
periodically (using @racket[continuation-mark-set->context]).
|
||||
@racket[delay] determines the amount of time the sampler
|
||||
@racket[sleep]s for between samples. Note that this is will be
|
||||
close, but not identical to, the frequency in which data is actually
|
||||
sampled.}
|
||||
@item{The profiler works by starting a ``sampler'' thread to
|
||||
periodically collect stack snapshots (using
|
||||
@racket[continuation-mark-set->context]). To determine the
|
||||
frequency of these collections, the sampler thread sleeps
|
||||
@racket[delay] seconds between collections. Note that this is will
|
||||
be close, but not identical to, the frequency in which data is
|
||||
actually sampled. (The @racket[delay] value is passed on to
|
||||
@racket[create-sampler], which creates the sampler thread.)}
|
||||
|
||||
@item{When the profiled computation takes a short amount of time, the
|
||||
collected data will not be accurate. In this case, you can specify
|
||||
an @racket[iterations] argument to repeat the evaluation a number of
|
||||
times which will improve the accuracy of the resulting report.}
|
||||
@item{Due to the statistical nature of the profiler, longer executions
|
||||
result in more accurate analysis. You can specify a number of
|
||||
@racket[iterations] to repeat the @racket[thunk] to collect more
|
||||
data.}
|
||||
|
||||
@item{Normally, the sampler collects snapshots of the
|
||||
@racket[current-thread]'s stack. If there is some computation that
|
||||
happens on a different thread, that work will not be reflected in
|
||||
the results: the only effect will be suspiciously small value for
|
||||
the observed time, because the collected data is taking into account
|
||||
the cpu time that the thread actually performed (it uses
|
||||
@racket[current-process-milliseconds] with the running thread as an
|
||||
argument). Specifying a non-@racket[#f] value for the
|
||||
@racket[threads?] argument will arrange for all threads that are
|
||||
started during the evaluation to be tracked. Note that this means
|
||||
that the computation will actually run in a new sub-custodian, as
|
||||
this is the only way to be able to track such threads.}
|
||||
@item{Normally, the sampler collects only snapshots of the
|
||||
@racket[current-thread]'s stack. Profiling a computation that
|
||||
creates threads will therefore lead to bad analysis: the timing
|
||||
results will be correct, but because the profiler is unaware of
|
||||
other threads the observed time will be suspiciously small, and work
|
||||
done in other threads will not be included in the results. To track
|
||||
all threads, specify a non-@racket[#f] value for the
|
||||
@racket[threads?] argument---this will execute the computation in a
|
||||
fresh custodian, and keep track of all threads under this
|
||||
custodian.}
|
||||
|
||||
@item{Once the computation has finished, the sampler is stopped, and
|
||||
the accumulated data is collected. It is then analyzed by
|
||||
@racket[analyze-samples], and the analyzed profile data is fed into
|
||||
a renderer. Use an identity function (@racket[values]) to get the
|
||||
analyzed result, and render it yourself, or use one of the existing
|
||||
renderers (see @secref["renderers"]).}
|
||||
@item{Once the computation is done and the sampler is stopped, the
|
||||
accumulated data is analyzed (by @racket[analyze-samples]) and the
|
||||
resulting profile value is sent to the @racket[renderer] function.
|
||||
See @secref["renderers"] for available renderers. You can also use
|
||||
@racket[values] as a ``renderer''---in this case the
|
||||
@racket[profile-thunk] returns the analyzed information which can
|
||||
now be rendered multiple times, or saved for future rendering.}
|
||||
|
||||
@item{The @racket[periodic-renderer] argument can be set to a list
|
||||
holding a delay time and a renderer. In this case, the given
|
||||
renderer will be called periodically. This is useful for cases
|
||||
where you want a dynamically updated display of the results. This
|
||||
delay should be larger than the sampler delay.}
|
||||
@item{To provide feedback information during execution, specify a
|
||||
@racket[periodic-renderer]. This should be a list holding a delay
|
||||
time (in seconds) and a renderer function. The delay determines the
|
||||
frequency in which the renderer is called, and it should be larger
|
||||
than the sampler delay (usually much larger since it can involve
|
||||
more noticeable overhead, and it is intended for a human observer).}
|
||||
|
||||
]}
|
||||
|
||||
@defform[(profile expr keyword-arguments ...)]{
|
||||
|
||||
A macro version of @racket[profile-thunk]. The keyword arguments can
|
||||
be specified in the same was as for a function call: they can appear
|
||||
before and/or after the expression to be profiled.}
|
||||
A macro version of @racket[profile-thunk]. Keyword arguments can be
|
||||
specified as in a function call: they can appear before and/or after
|
||||
the expression to be profiled.}
|
||||
|
|
|
|||
Loading…
Reference in New Issue
Block a user