Commit | Line | Data |
---|---|---|
58c4a39d AW |
1 | @c -*-texinfo-*- |
2 | @c This is part of the GNU Guile Reference Manual. | |
3 | @c Copyright (C) 2013 Free Software Foundation, Inc. | |
4 | @c See the file guile.texi for copying conditions. | |
5 | ||
6 | @node Statprof | |
7 | @section Statprof | |
8 | ||
9 | @code{(statprof)} is a fairly simple statistical profiler for Guile. | |
10 | ||
11 | A simple use of statprof would look like this: | |
12 | ||
13 | @example | |
14 | (statprof-reset 0 50000 #t) | |
15 | (statprof-start) | |
16 | (do-something) | |
17 | (statprof-stop) | |
18 | (statprof-display) | |
19 | @end example | |
20 | ||
21 | This would reset statprof, clearing all accumulated statistics, then | |
22 | start profiling, run some code, stop profiling, and finally display a | |
23 | gprof flat-style table of statistics which will look something like | |
24 | this: | |
25 | ||
26 | @example | |
27 | % cumulative self self total | |
28 | time seconds seconds calls ms/call ms/call name | |
29 | 35.29 0.23 0.23 2002 0.11 0.11 - | |
30 | 23.53 0.15 0.15 2001 0.08 0.08 positive? | |
31 | 23.53 0.15 0.15 2000 0.08 0.08 + | |
32 | 11.76 0.23 0.08 2000 0.04 0.11 do-nothing | |
33 | 5.88 0.64 0.04 2001 0.02 0.32 loop | |
34 | 0.00 0.15 0.00 1 0.00 150.59 do-something | |
35 | ... | |
36 | @end example | |
37 | ||
38 | All of the numerical data with the exception of the calls column is | |
39 | statistically approximate. In the following column descriptions, and in | |
40 | all of statprof, "time" refers to execution time (both user and system), | |
41 | not wall clock time. | |
42 | ||
43 | @table @asis | |
44 | @item % time | |
45 | The percent of the time spent inside the procedure itself (not counting | |
46 | children). | |
47 | ||
48 | @item cumulative seconds | |
49 | The total number of seconds spent in the procedure, including children. | |
50 | ||
51 | @item self seconds | |
52 | The total number of seconds spent in the procedure itself (not counting | |
53 | children). | |
54 | ||
55 | @item calls | |
56 | The total number of times the procedure was called. | |
57 | ||
58 | @item self ms/call | |
59 | The average time taken by the procedure itself on each call, in ms. | |
60 | ||
61 | @item total ms/call | |
62 | The average time taken by each call to the procedure, including time | |
63 | spent in child functions. | |
64 | ||
65 | @item name | |
66 | The name of the procedure. | |
67 | ||
68 | @end table | |
69 | ||
70 | The profiler uses @code{eq?} and the procedure object itself to identify | |
71 | the procedures, so it won't confuse different procedures with the same | |
72 | name. They will show up as two different rows in the output. | |
73 | ||
74 | Right now the profiler is quite simplistic. I cannot provide call-graphs | |
75 | or other higher level information. What you see in the table is pretty | |
76 | much all there is. Patches are welcome :-) | |
77 | ||
78 | @section Implementation notes | |
79 | The profiler works by setting the unix profiling signal | |
80 | @code{ITIMER_PROF} to go off after the interval you define in the call | |
81 | to @code{statprof-reset}. When the signal fires, a sampling routine is | |
82 | run which looks at the current procedure that's executing, and then | |
83 | crawls up the stack, and for each procedure encountered, increments that | |
84 | procedure's sample count. Note that if a procedure is encountered | |
85 | multiple times on a given stack, it is only counted once. After the | |
86 | sampling is complete, the profiler resets profiling timer to fire again | |
87 | after the appropriate interval. | |
88 | ||
89 | Meanwhile, the profiler keeps track, via @code{get-internal-run-time}, | |
90 | how much CPU time (system and user -- which is also what | |
91 | @code{ITIMER_PROF} tracks), has elapsed while code has been executing | |
92 | within a statprof-start/stop block. | |
93 | ||
94 | The profiler also tries to avoid counting or timing its own code as much | |
95 | as possible. | |
96 | ||
97 | @section Usage | |
98 | @anchor{statprof statprof-active?}@defun statprof-active? | |
99 | Returns @code{#t} if @code{statprof-start} has been called more times | |
100 | than @code{statprof-stop}, @code{#f} otherwise. | |
101 | ||
102 | @end defun | |
103 | ||
104 | @anchor{statprof statprof-start}@defun statprof-start | |
105 | Start the profiler.@code{} | |
106 | ||
107 | @end defun | |
108 | ||
109 | @anchor{statprof statprof-stop}@defun statprof-stop | |
110 | Stop the profiler.@code{} | |
111 | ||
112 | @end defun | |
113 | ||
114 | @anchor{statprof statprof-reset}@defun statprof-reset sample-seconds sample-microseconds count-calls? [full-stacks?] | |
115 | Reset the statprof sampler interval to @var{sample-seconds} and | |
116 | @var{sample-microseconds}. If @var{count-calls?} is true, arrange to | |
117 | instrument procedure calls as well as collecting statistical profiling | |
118 | data. If @var{full-stacks?} is true, collect all sampled stacks into a | |
119 | list for later analysis. | |
120 | ||
121 | Enables traps and debugging as necessary. | |
122 | ||
123 | @end defun | |
124 | ||
125 | @anchor{statprof statprof-accumulated-time}@defun statprof-accumulated-time | |
126 | Returns the time accumulated during the last statprof run.@code{} | |
127 | ||
128 | @end defun | |
129 | ||
130 | @anchor{statprof statprof-sample-count}@defun statprof-sample-count | |
131 | Returns the number of samples taken during the last statprof run.@code{} | |
132 | ||
133 | @end defun | |
134 | ||
135 | @anchor{statprof statprof-fold-call-data}@defun statprof-fold-call-data proc init | |
136 | Fold @var{proc} over the call-data accumulated by statprof. Cannot be | |
137 | called while statprof is active. @var{proc} should take two arguments, | |
138 | @code{(@var{call-data} @var{prior-result})}. | |
139 | ||
140 | Note that a given proc-name may appear multiple times, but if it does, | |
141 | it represents different functions with the same name. | |
142 | ||
143 | @end defun | |
144 | ||
145 | @anchor{statprof statprof-proc-call-data}@defun statprof-proc-call-data proc | |
146 | Returns the call-data associated with @var{proc}, or @code{#f} if none | |
147 | is available. | |
148 | ||
149 | @end defun | |
150 | ||
151 | @anchor{statprof statprof-call-data-name}@defun statprof-call-data-name cd | |
152 | @end defun | |
153 | ||
154 | @anchor{statprof statprof-call-data-calls}@defun statprof-call-data-calls cd | |
155 | @end defun | |
156 | ||
157 | @anchor{statprof statprof-call-data-cum-samples}@defun statprof-call-data-cum-samples cd | |
158 | @end defun | |
159 | ||
160 | @anchor{statprof statprof-call-data-self-samples}@defun statprof-call-data-self-samples cd | |
161 | @end defun | |
162 | ||
163 | @anchor{statprof statprof-call-data->stats}@defun statprof-call-data->stats call-data | |
164 | Returns an object of type @code{statprof-stats}. | |
165 | ||
166 | @end defun | |
167 | ||
168 | @anchor{statprof statprof-stats-proc-name}@defun statprof-stats-proc-name stats | |
169 | @end defun | |
170 | ||
171 | @anchor{statprof statprof-stats-%-time-in-proc}@defun statprof-stats-%-time-in-proc stats | |
172 | @end defun | |
173 | ||
174 | @anchor{statprof statprof-stats-cum-secs-in-proc}@defun statprof-stats-cum-secs-in-proc stats | |
175 | @end defun | |
176 | ||
177 | @anchor{statprof statprof-stats-self-secs-in-proc}@defun statprof-stats-self-secs-in-proc stats | |
178 | @end defun | |
179 | ||
180 | @anchor{statprof statprof-stats-calls}@defun statprof-stats-calls stats | |
181 | @end defun | |
182 | ||
183 | @anchor{statprof statprof-stats-self-secs-per-call}@defun statprof-stats-self-secs-per-call stats | |
184 | @end defun | |
185 | ||
186 | @anchor{statprof statprof-stats-cum-secs-per-call}@defun statprof-stats-cum-secs-per-call stats | |
187 | @end defun | |
188 | ||
189 | @anchor{statprof statprof-display}@defun statprof-display . _ | |
190 | Displays a gprof-like summary of the statistics collected. Unless an | |
191 | optional @var{port} argument is passed, uses the current output port. | |
192 | ||
193 | @end defun | |
194 | ||
195 | @anchor{statprof statprof-display-anomolies}@defun statprof-display-anomolies | |
196 | A sanity check that attempts to detect anomolies in statprof's | |
197 | statistics.@code{} | |
198 | ||
199 | @end defun | |
200 | ||
201 | @anchor{statprof statprof-fetch-stacks}@defun statprof-fetch-stacks | |
202 | Returns a list of stacks, as they were captured since the last call to | |
203 | @code{statprof-reset}. | |
204 | ||
205 | Note that stacks are only collected if the @var{full-stacks?} argument | |
206 | to @code{statprof-reset} is true. | |
207 | ||
208 | @end defun | |
209 | ||
210 | @anchor{statprof statprof-fetch-call-tree}@defun statprof-fetch-call-tree | |
211 | @verbatim | |
212 | Return a call tree for the previous statprof run. | |
213 | ||
214 | The return value is a list of nodes, each of which is of the type: | |
215 | @@code | |
216 | node ::= (@@var@{proc@} @@var@{count@} . @@var@{nodes@}) | |
217 | @@end code | |
218 | @end verbatim | |
219 | ||
220 | @end defun | |
221 | ||
222 | @anchor{statprof statprof}@defun statprof thunk [#:loop] [#:hz] [#:count-calls?] [#:full-stacks?] | |
223 | Profiles the execution of @var{thunk}. | |
224 | ||
225 | The stack will be sampled @var{hz} times per second, and the thunk | |
226 | itself will be called @var{loop} times. | |
227 | ||
228 | If @var{count-calls?} is true, all procedure calls will be recorded. | |
229 | This operation is somewhat expensive. | |
230 | ||
231 | If @var{full-stacks?} is true, at each sample, statprof will store away | |
232 | the whole call tree, for later analysis. Use | |
233 | @code{statprof-fetch-stacks} or @code{statprof-fetch-call-tree} to | |
234 | retrieve the last-stored stacks. | |
235 | ||
236 | @end defun | |
237 | ||
238 | @anchor{statprof with-statprof}@defspec with-statprof args | |
239 | Profiles the expressions in its body. | |
240 | ||
241 | Keyword arguments: | |
242 | ||
243 | @table @code | |
244 | @item #:loop | |
245 | Execute the body @var{loop} number of times, or @code{#f} for no looping | |
246 | ||
247 | default: @code{#f} | |
248 | ||
249 | @item #:hz | |
250 | Sampling rate | |
251 | ||
252 | default: @code{20} | |
253 | ||
254 | @item #:count-calls? | |
255 | Whether to instrument each function call (expensive) | |
256 | ||
257 | default: @code{#f} | |
258 | ||
259 | @item #:full-stacks? | |
260 | Whether to collect away all sampled stacks into a list | |
261 | ||
262 | default: @code{#f} | |
263 | ||
264 | @end table | |
265 | ||
266 | @end defspec | |
267 | ||
268 | @anchor{statprof gcprof}@defun gcprof thunk [#:loop] [#:full-stacks?] | |
269 | Do an allocation profile of the execution of @var{thunk}. | |
270 | ||
271 | The stack will be sampled soon after every garbage collection, yielding | |
272 | an approximate idea of what is causing allocation in your program. | |
273 | ||
274 | Since GC does not occur very frequently, you may need to use the | |
275 | @var{loop} parameter, to cause @var{thunk} to be called @var{loop} | |
276 | times. | |
277 | ||
278 | If @var{full-stacks?} is true, at each sample, statprof will store away | |
279 | the whole call tree, for later analysis. Use | |
280 | @code{statprof-fetch-stacks} or @code{statprof-fetch-call-tree} to | |
281 | retrieve the last-stored stacks. | |
282 | ||
283 | @end defun |