From 67580c1774e3f3a5304cdefcbc99d7d17f2609ef Mon Sep 17 00:00:00 2001 From: Vincent St-Amour Date: Thu, 7 Nov 2013 16:45:22 -0500 Subject: [PATCH] Update profile docs to be consistent with output of errortrace mode. original commit: 8683a2188b36e18f4ef7c9288f0cc06bd5d629a8 --- .../profile/scribblings/analyzer.scrbl | 66 +++++++++---------- .../profile/scribblings/profile.scrbl | 28 ++++---- .../profile/scribblings/renderers.scrbl | 31 ++++----- .../profile/scribblings/toplevel.scrbl | 14 ++-- 4 files changed, 73 insertions(+), 66 deletions(-) diff --git a/pkgs/profile-pkgs/profile-doc/profile/scribblings/analyzer.scrbl b/pkgs/profile-pkgs/profile-doc/profile/scribblings/analyzer.scrbl index ae3e54e..fd32499 100644 --- a/pkgs/profile-pkgs/profile-doc/profile/scribblings/analyzer.scrbl +++ b/pkgs/profile-pkgs/profile-doc/profile/scribblings/analyzer.scrbl @@ -54,13 +54,12 @@ Represents an analyzed profile result. integer identifier. These identifiers are listed for each function call, and the total time spent in each thread is in this field.} -@item{@racket[nodes] is a list of nodes representing all observed - functions. These nodes are the components of the call-graph that - the analyzer assembles (see the @racket[edge] field). The nodes are - sorted by a topological top-to-bottom sort, and by decreasing total - amount of time (time spent either in the function or in its callees) - as a secondary key. It does not include the special - @racket[*-node].} +@item{@racket[nodes] is a list of nodes representing all observed functions + (or, when using Errortrace, expressions). These nodes are the components of + the call-graph that the analyzer assembles (see the @racket[edge] field). + The nodes are sorted by a topological top-to-bottom sort, and by decreasing + total amount of time (time spent either in the function or in its callees) as + a secondary key. It does not include the special @racket[*-node].} @item{@racket[*-node] holds a ``special'' root node value that is 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?)] [thread-ids (listof exact-nonnegative-integer?)] [total exact-nonnegative-integer?] @@ -85,38 +84,38 @@ Represents an analyzed profile result. [callers (listof edge?)] [callees (listof edge?)])]{ -Represents a function call node in the call graph of an analyzed -profile result. +Represents a function call (or, when using Errortrace, expression) node in the +call graph of an analyzed profile result. @itemize[ -@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 one of these can - be @racket[#f], except for the special @racket[*-node] (see the - @racket[profile] struct) that can be identified by both being - @racket[#f].} +@item{The @racket[id] and @racket[src] fields hold a symbol naming the function + (in @racket[continuation-mark-set->context] mode) or an S-expression stub (in + Errortrace mode), 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 one of these can be @racket[#f], except for the special + @racket[*-node] (see the @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) 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 initiate the actual work, but they don't do any hard work - directly.} +@item{@racket[total] holds the total time (in milliseconds) that this function + (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 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) that this - function was observed as the leaf of the stack. It represents the - actual work done by this function, rather than the @racket[total] - time spent by both the function and its callees.} +@item{@racket[self] holds the total time (in milliseconds) that this function + (or expression) was observed as the leaf of the stack. It represents the + 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 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.} +@item{@racket[callers] and @racket[callees] hold the list of callers and + callees or, in Errortrace modes, expressions that step to or from the current + expression. 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.} ]} @@ -127,8 +126,9 @@ profile result. [callee node?] [callee-time exact-nonnegative-integer?])]{ -Represents an edge between two function call nodes in the call graph -of an analyzed profile result. +Represents an edge between two function call nodes in the call graph of an +analyzed profile result or, in Errortrace mode, an edge corresponding to an +evaluation step between two expressions. @itemize[ diff --git a/pkgs/profile-pkgs/profile-doc/profile/scribblings/profile.scrbl b/pkgs/profile-pkgs/profile-doc/profile/scribblings/profile.scrbl index e07a7b4..edf29b6 100644 --- a/pkgs/profile-pkgs/profile-doc/profile/scribblings/profile.scrbl +++ b/pkgs/profile-pkgs/profile-doc/profile/scribblings/profile.scrbl @@ -5,17 +5,23 @@ @title{Profile: Statistical Profiler} -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 -not require recompilation of your source and has very little runtime -overhead, it can be used for longer runs which compensates for these -limits. +The @racketmodname[profile] collection implements a statistical profiler. The +profiling is done by running a background thread that collects stack snapshots +either via @racket[continuation-mark-set->context] or via @seclink["top" #:doc +'(lib "errortrace/scribblings/errortrace.scrbl")]{Errortrace}, meaning that the +result is an estimate of the execution costs. + +When using @racket[continuation-mark-set->context], 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 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[] diff --git a/pkgs/profile-pkgs/profile-doc/profile/scribblings/renderers.scrbl b/pkgs/profile-pkgs/profile-doc/profile/scribblings/renderers.scrbl index d56e100..8f242c5 100644 --- a/pkgs/profile-pkgs/profile-doc/profile/scribblings/renderers.scrbl +++ b/pkgs/profile-pkgs/profile-doc/profile/scribblings/renderers.scrbl @@ -31,7 +31,7 @@ function that consumes a @racket[profile] instance. See the Prints the given @racket[profile] results as a textual table. 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 graph can have cycles). This means that it is usually easy to find 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 C [M3] M4%} with the following meaning of the numbers and labels: + @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 anonymous functions, which will be +@item{@tt{A} --- the name of the function (or a stub of the expression) that + this node represents, followed by the source location for the function if it + is known. The name can be ``???'' for anonymous functions, which will be identified with their source location.} @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 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 - 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.)} @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 - with a 100% refers to a function that was active throughout the - whole execution.} -@item{@tt{N4} --- the time (in milliseconds) that this function has + with a 100% refers to a function/expression that was active throughout + the whole execution.} +@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 - function was itself doing work rather than calling other functions. - (Corresponds to the @racket[node-self] field.)} + function/expression was itself doing work rather than calling other + functions/expressions. (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 + observed time of the profile. Functions/expressions with high values here can be good candidates for optimization, But, of course, they can 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 + callees of the function/expression. Any number of callers and callees can + appear here (including 0). The function/expression itself can also appear in both places if it is (non-tail) recursive.} @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 diff --git a/pkgs/profile-pkgs/profile-doc/profile/scribblings/toplevel.scrbl b/pkgs/profile-pkgs/profile-doc/profile/scribblings/toplevel.scrbl index 3f204f0..15dd7d6 100644 --- a/pkgs/profile-pkgs/profile-doc/profile/scribblings/toplevel.scrbl +++ b/pkgs/profile-pkgs/profile-doc/profile/scribblings/toplevel.scrbl @@ -42,13 +42,13 @@ can customize the profiling: actually sampled. (The @racket[delay] value is passed on to @racket[create-sampler], which creates the sampler thread.)} -@item{When @racket[use-errortrace?] is not @racket[#f], more accurate - stack snapshots are captured using - @other-doc['(lib "errortrace/scribblings/errortrace.scrbl")]. Note that - when this is provided, it will only profile uncompiled files and files - compiled while using @racket[errortrace-compile-handler], and the profiled program - must be run using @commandline{racket -l errortrace -t program.rkt} - Removing compiled files (with extension @tt{.zo}) is sufficient to enable this.} +@item{When @racket[use-errortrace?] is not @racket[#f], more accurate stack + snapshots are captured using @seclink["top" #:doc '(lib + "errortrace/scribblings/errortrace.scrbl")]{Errortrace}. Note that when this + is provided, it will only profile uncompiled files and files compiled while + using @racket[errortrace-compile-handler], and the profiled program must be + run using @commandline{racket -l errortrace -t program.rkt} Removing compiled + files (with extension @tt{.zo}) is sufficient to enable this.} @item{Due to the statistical nature of the profiler, longer executions result in more accurate analysis. You can specify a number of