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

Some selective #:when (not ...)' -> #:unless ...'.

Browse Source 
original commit: 623c7493ed2bbf7c89caea877a7b94a5f4c42c73
This commit is contained in:
Eli Barzilay 2011-09-14 16:53:45 -04:00
commit 60dd49df61
12 changed files with 165 additions and 164 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

25
collects/profile/analyzer.rkt
View File

@ -1,10 +1,10 @@
#lang scheme/base
#lang racket/base
;; Analyzer for the sampler results
(provide analyze-samples)
(require "structs.rkt" "utils.rkt" racket/list)
(require "structs.rkt" "utils.rkt" scheme/list)
(provide analyze-samples (all-from-out "structs.rkt"))
(define-syntax-rule (with-hash <hash> <key> <expr>)
(hash-ref! <hash> <key> (lambda () <expr>)))
@ -25,14 +25,14 @@
(define id+src->node-hash (make-hasheq))
(define (id+src->node id+src)
(with-hash id+src->node-hash id+src
(make-node (car id+src) (cdr id+src) '() 0 0 '() '())))
(node (car id+src) (cdr id+src) '() 0 0 '() '())))
;; special node that is the caller of toplevels and callee of leaves
(define *-node (id+src->node '(#f . #f)))
(define call->edge
(let ([t (make-hasheq)])
(lambda (ler lee)
(with-hash (with-hash t ler (make-hasheq)) lee
(let ([e (make-edge 0 ler 0 lee 0)])
(let ([e (edge 0 ler 0 lee 0)])
(set-node-callers! lee (cons e (node-callers lee)))
(set-node-callees! ler (cons e (node-callees ler)))
e)))))
@ -84,14 +84,13 @@
(for ([n (in-list nodes)])
(set-node-callees! n (sort (node-callees n) > #:key edge-callee-time))
(set-node-callers! n (sort (node-callers n) > #:key edge-caller-time)))
(make-profile
total-time
cpu-time
(length samples)
(for/list ([time (in-vector thread-times)] [n (in-naturals 0)])
(cons n time))
nodes
*-node)))
(profile total-time
cpu-time
(length samples)
(for/list ([time (in-vector thread-times)] [n (in-naturals 0)])
(cons n time))
nodes
*-node)))
;; Groups raw samples by their thread-id, returns a vector with a field for
;; each thread id holding the sample data for that thread. The samples in

6
collects/profile/main.rkt
View File

@ -1,10 +1,10 @@
#lang scheme/base
#lang racket/base
(provide profile-thunk profile)
(require "sampler.rkt" "analyzer.rkt"
(require "sampler.rkt" (except-in "analyzer.rkt" profile)
(prefix-in text: "render-text.rkt")
(for-syntax scheme/base))
(for-syntax racket/base))
(define (profile-thunk thunk
#:delay [delay 0.05]

4
collects/profile/render-graphviz.rkt
View File

@ -1,8 +1,8 @@
#lang scheme/base
#lang racket/base
(provide render)
(require "structs.rkt" "analyzer.rkt" "utils.rkt")
(require "analyzer.rkt" "utils.rkt")
(define (render profile
#:hide-self [hide-self% 1/100]

8
collects/profile/render-text.rkt
View File

@ -1,8 +1,8 @@
#lang at-exp scheme/base
#lang at-exp racket/base
(provide render)
(require "structs.rkt" "analyzer.rkt" "utils.rkt" scheme/list)
(require "analyzer.rkt" "utils.rkt" racket/list)
(define (f:msec msec)
(number->string (round (inexact->exact msec))))
@ -122,8 +122,8 @@
(define (sub get-edges get-node get-node-time)
(for*/list ([edge (in-list (get-edges node))]
[sub (in-list (list (get-node edge)))] ; <-- hack...
#:when (not (or (eq? *-node sub) ; <-- ...for this
(memq sub hidden))))
#:unless (or (eq? *-node sub) ; <-- ...for this
(memq sub hidden)))
(define name (node-> 'sub-label sub))
(define local% (format-percent (get-node-time edge) total))
`("" "" "" "" "" "" "" ""

2
collects/profile/sampler.rkt
View File

@ -1,4 +1,4 @@
#lang scheme/base
#lang racket/base
;; The core profiler sample collector
;; (This module is a private tool for collecting profiling data, and should not

115
collects/profile/scribblings/analyzer.scrbl
View File

@ -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.

12
collects/profile/scribblings/profile.scrbl
View File

@ -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

31
collects/profile/scribblings/renderers.scrbl
View File

@ -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

32
collects/profile/scribblings/sampler.scrbl
View File

@ -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

86
collects/profile/scribblings/toplevel.scrbl
View File

@ -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.}

4
collects/profile/structs.rkt
View File

@ -1,4 +1,4 @@
#lang scheme/base
#lang racket/base
;; Struct definitions for the profiler
@ -14,7 +14,7 @@
;; identifiable by having both id and src fields being #f. Can be used to
;; start a graph traversal from the top or the bottom.
(provide (struct-out profile))
(define-struct profile
(struct profile
(total-time cpu-time sample-number thread-times nodes *-node))
;; An entry for a single profiled function:

4
collects/profile/utils.rkt
View File

@ -1,6 +1,6 @@
#lang scheme/base
#lang racket/base
(require "structs.rkt" scheme/list scheme/nest)
(require "structs.rkt" racket/list)
;; Format a percent number, possibly doing the division too. If we do the
;; division, then be careful: if we're dividing by zero, then make the result