[profiler} Don't crash if a zero sampling frequency is given.
[mono.git] / man / mprof-report.1
1 .de Sp
2 .if t .sp .5v
3 .if n .sp
4 ..
5 .TH mprof-report 1 ""
6 .SH The Mono log profiler
7 .PP
8 The Mono \f[I]log\f[] profiler can be used to collect a lot of
9 information about a program running in the Mono runtime.
10 This data can be used (both while the process is running and later)
11 to do analyses of the program behaviour, determine resource usage,
12 performance issues or even look for particular execution patterns.
13 .PP
14 This is accomplished by logging the events provided by the Mono
15 runtime through the profiling interface and periodically writing
16 them to a file which can be later inspected with the command line
17 \f[I]mprof-report\f[] program or with a GUI (not developed yet).
18 .PP
19 The events collected include (among others):
20 .IP \[bu] 2
21 method enter and leave
22 .IP \[bu] 2
23 object allocation
24 .IP \[bu] 2
25 garbage collection
26 .IP \[bu] 2
27 JIT compilation
28 .IP \[bu] 2
29 metadata loading
30 .IP \[bu] 2
31 lock contention
32 .IP \[bu] 2
33 exceptions
34 .PP
35 In addition, the profiler can periodically collect info about all
36 the objects present in the heap at the end of a garbage collection
37 (this is called heap shot and currently implemented only for the
38 sgen garbage collector).
39 Another available profiler mode is the \f[I]sampling\f[] or
40 \f[I]statistical\f[] mode: periodically the program is sampled and
41 the information about what the program was busy with is saved.
42 This allows to get information about the program behaviour without
43 degrading its performance too much (usually less than 10%).
44 .SS Basic profiler usage
45 .PP
46 The simpler way to use the profiler is the following:
47 .PP
48 \f[B]mono\ --profile=log\ program.exe\f[]
49 .PP
50 At the end of the execution the file \f[I]output.mlpd\f[] will be
51 found in the current directory.
52 A summary report of the data can be printed by running:
53 .PP
54 \f[B]mprof-report\ output.mlpd\f[]
55 .PP
56 With this invocation a huge amount of data is collected about the
57 program execution and collecting and saving this data can
58 significantly slow down program execution.
59 If saving the profiling data is not needed, a report can be
60 generated directly with:
61 .PP
62 \f[B]mono\ --profile=log:report\ program.exe\f[]
63 .PP
64 If the information about allocations is not of interest, it can be
65 excluded:
66 .PP
67 \f[B]mono\ --profile=log:noalloc\ program.exe\f[]
68 .PP
69 On the other hand, if method call timing is not important, while
70 allocations are, the needed info can be gathered with:
71 .PP
72 \f[B]mono\ --profile=log:nocalls\ program.exe\f[]
73 .PP
74 You will still be able to inspect information about the sequence of
75 calls that lead to each allocation because at each object
76 allocation a stack trace is collected if full enter/leave
77 information is not available.
78 .PP
79 To periodically collect heap shots (and exclude method and
80 allocation events) use the following options (making sure you run
81 with the sgen garbage collector):
82 .PP
83 \f[B]mono\ --gc=sgen\ --profile=log:heapshot\ program.exe\f[]
84 .PP
85 To perform a sampling profiler run, use the \f[I]sample\f[] option:
86 .PP
87 \f[B]mono\ --profile=log:sample\ program.exe\f[]
88 .SS Profiler option documentation
89 .PP
90 By default the \f[I]log\f[] profiler will gather all the events
91 provided by the Mono runtime and write them to a file named
92 \f[I]output.mlpd\f[].
93 When no option is specified, it is equivalent to using:
94 .PP
95 \f[B]--profile=log:calls,alloc,output=output.mlpd,maxframes=8,calldepth=100\f[]
96 .PP
97 The following options can be used to modify this default behaviour.
98 Each option is separated from the next by a \f[B],\f[] character,
99 with no spaces and all the options are included after the
100 \f[I]log:\f[] profile module specifier.
101 .IP \[bu] 2
102 \f[I]help\f[]: display concise help info about each available
103 option
104 .IP \[bu] 2
105 \f[I][no]alloc\f[]: \f[I]noalloc\f[] disables collecting object
106 allocation info, \f[I]alloc\f[] enables it if it was disabled by
107 another option like \f[I]heapshot\f[].
108 .IP \[bu] 2
109 \f[I][no]calls\f[]: \f[I]nocalls\f[] disables collecting method
110 enter and leave events.
111 When this option is used at each object allocation and at some
112 other events (like lock contentions and exception throws) a stack
113 trace is collected by default.
114 See the \f[I]maxframes\f[] option to control this behaviour.
115 \f[I]calls\f[] enables method enter/leave events if they were
116 disabled by another option like \f[I]heapshot\f[].
117 .IP \[bu] 2
118 \f[I]heapshot[=MODE]\f[]: collect heap shot data at each major
119 collection.
120 The frequency of the heap shots can be changed with the
121 \f[I]MODE\f[] parameter.
122 When this option is used allocation events and method enter/leave
123 events are not recorded by default: if they are needed, they need
124 to be enabled explicitly.
125 The optional parameter \f[I]MODE\f[] can modify the default heap
126 shot frequency.
127 heapshot can be used multiple times with different modes: in that
128 case a heap shot is taken if either of the conditions are met.
129 MODE can be one of:
130 .RS 2
131 .IP \[bu] 2
132 \f[I]NUM\f[]ms: perform a heap shot if at least \f[I]NUM\f[]
133 milliseconds passed since the last one.
134 .IP \[bu] 2
135 \f[I]NUM\f[]gc: perform a heap shot every \f[I]NUM\f[] major
136 garbage collections
137 .IP \[bu] 2
138 \f[I]ondemand\f[]: perform a heap shot when such a command is sent
139 to the control port
140 .RE
141 .IP \[bu] 2
142 \f[I]sample[=TYPE[/FREQ]]\f[]: collect statistical samples of the
143 program behaviour.
144 The default is to collect a 100 times per second (100 Hz) the
145 instruction pointer.
146 This is equivalent to the value \[lq]cycles/100\[rq].
147 A value of zero for \f[I]FREQ\f[] effectively disables sampling.
148 On some systems, like with recent Linux kernels, it is possible to
149 cause the sampling to happen for other events provided by the
150 performance counters of the cpu.
151 In this case, \f[I]TYPE\f[] can be one of:
152 .RS 2
153 .IP \[bu] 2
154 \f[I]cycles\f[]: processor cycles
155 .IP \[bu] 2
156 \f[I]instr\f[]: executed instructions
157 .IP \[bu] 2
158 \f[I]cacherefs\f[]: cache references
159 .IP \[bu] 2
160 \f[I]cachemiss\f[]: cache misses
161 .IP \[bu] 2
162 \f[I]branches\f[]: executed branches
163 .IP \[bu] 2
164 \f[I]branchmiss\f[]: mispredicted branches
165 .RE
166 .IP \[bu] 2
167 \f[I]time=TIMER\f[]: use the TIMER timestamp mode.
168 TIMER can have the following values:
169 .RS 2
170 .IP \[bu] 2
171 \f[I]fast\f[]: a usually faster but possibly more inaccurate timer
172 .RE
173 .IP \[bu] 2
174 \f[I]maxframes=NUM\f[]: when a stack trace needs to be performed,
175 collect \f[I]NUM\f[] frames at the most.
176 The default is 8.
177 .IP \[bu] 2
178 \f[I]maxsamples=NUM\f[]: stop allocating reusable sample events
179 once \f[I]NUM\f[] events have been allocated (a value of zero for
180 all intents and purposes means unlimited). By default, the value
181 of this setting is the number of CPU cores multiplied by 1000. This
182 is usually a good enough value for typical desktop and mobile apps.
183 If you're losing too many samples due to this default (which is
184 possible in apps with an unusually high amount of threads), you
185 may want to tinker with this value to find a good balance between
186 sample hit rate and performance impact on the app. The way it works
187 is that sample events are enqueued for reuse after they're flushed
188 to the output file; if a thread gets a sampling signal but there are
189 no sample events in the reuse queue and the profiler has reached the
190 maximum number of sample allocations, the sample gets dropped. So a
191 higher number for this setting will increase the chance that a
192 thread is able to collect a sample, but also necessarily means that
193 there will be more work done by the profiler. You can run Mono with
194 the \f[I]--stats\f[] option to see statistics about sample events.
195 .IP \[bu] 2
196 \f[I]calldepth=NUM\f[]: ignore method enter/leave events when the
197 call chain depth is bigger than NUM.
198 .IP \[bu] 2
199 \f[I]zip\f[]: automatically compress the output data in gzip
200 format.
201 .IP \[bu] 2
202 \f[I]output=OUTSPEC\f[]: instead of writing the profiling data to
203 the output.mlpd file, substitute \f[I]%p\f[] in \f[I]OUTSPEC\f[]
204 with the current process id and \f[I]%t\f[] with the current date
205 and time, then do according to \f[I]OUTSPEC\f[]:
206 .RS 2
207 .IP \[bu] 2
208 if \f[I]OUTSPEC\f[] begins with a \f[I]|\f[] character, execute the
209 rest as a program and feed the data to its standard input
210 .IP \[bu] 2
211 if \f[I]OUTSPEC\f[] begins with a \f[I]-\f[] character, use the
212 rest of OUTSPEC as the filename, but force overwrite any existing
213 file by that name
214 .IP \[bu] 2
215 otherwise write the data the the named file: note that is a file by
216 that name already exists, a warning is issued and profiling is
217 disabled.
218 .RE
219 .IP \[bu] 2
220 \f[I]report\f[]: the profiling data is sent to mprof-report, which
221 will print a summary report.
222 This is equivalent to the option: \f[B]output=mprof-report\ -\f[].
223 If the \f[I]output\f[] option is specified as well, the report will
224 be written to the output file instead of the console.
225 .IP \[bu] 2
226 \f[I]port=PORT\f[]: specify the tcp/ip port to use for the
227 listening command server.
228 Currently not available for windows.
229 This server is started for example when heapshot=ondemand is used:
230 it will read commands line by line.
231 The following commands are available:
232 .RS 2
233 .IP \[bu] 2
234 \f[I]heapshot\f[]: perform a heapshot as soon as possible
235 .RE
236 .IP \[bu] 2
237 \f[I]counters\f[]: sample counters values every 1 second. This allow
238 a really lightweight way to have insight in some of the runtime key
239 metrics. Counters displayed in non verbose mode are : Methods from AOT,
240 Methods JITted using mono JIT, Methods JITted using LLVM, Total time
241 spent JITting (sec), User Time, System Time, Total Time, Working Set,
242 Private Bytes, Virtual Bytes, Page Faults and CPU Load Average (1min,
243 5min and 15min).
244 .IP \[bu] 2
245 \f[I]coverage\f[]: collect code coverage data. This implies enabling
246 the \f[I]calls\f[] option.
247 .RE
248 .SS Analyzing the profile data
249 .PP
250 Currently there is a command line program (\f[I]mprof-report\f[])
251 to analyze the data produced by the profiler.
252 This is ran automatically when the \f[I]report\f[] profiler option
253 is used.
254 Simply run:
255 .PP
256 \f[B]mprof-report\ output.mlpd\f[]
257 .PP
258 to see a summary report of the data included in the file.
259 .SS Trace information for events
260 .PP
261 Often it is important for some events, like allocations, lock
262 contention and exception throws to know where they happened.
263 Or we may want to see what sequence of calls leads to a particular
264 method invocation.
265 To see this info invoke mprof-report as follows:
266 .PP
267 \f[B]mprof-report\ --traces\ output.mlpd\f[]
268 .PP
269 The maximum number of methods in each stack trace can be specified
270 with the \f[I]--maxframes=NUM\f[] option:
271 .PP
272 \f[B]mprof-report\ --traces\ --maxframes=4\ output.mlpd\f[]
273 .PP
274 The stack trace info will be available if method enter/leave events
275 have been recorded or if stack trace collection wasn't explicitly
276 disabled with the \f[I]maxframes=0\f[] profiler option.
277 Note that the profiler will collect up to 8 frames by default at
278 specific events when the \f[I]nocalls\f[] option is used, so in
279 that case, if more stack frames are required in mprof-report, a
280 bigger value for maxframes when profiling must be used, too.
281 .PP
282 The \f[I]--traces\f[] option also controls the reverse reference
283 feature in the heapshot report: for each class it reports how many
284 references to objects of that class come from other classes.
285 .SS Sort order for methods and allocations
286 .PP
287 When a list of methods is printed the default sort order is based
288 on the total time spent in the method.
289 This time is wall clock time (that is, it includes the time spent,
290 for example, in a sleep call, even if actual cpu time would be
291 basically 0).
292 Also, if the method has been ran on different threads, the time
293 will be a sum of the time used in each thread.
294 .PP
295 To change the sort order, use the option:
296 .PP
297 \f[B]--method-sort=MODE\f[]
298 .PP
299 where \f[I]MODE\f[] can be:
300 .IP \[bu] 2
301 \f[I]self\f[]: amount of time spent in the method itself and not in
302 its callees
303 .IP \[bu] 2
304 \f[I]calls\f[]: the number of method invocations
305 .IP \[bu] 2
306 \f[I]total\f[]: the total time spent in the method.
307 .PP
308 Object allocation lists are sorted by default depending on the
309 total amount of bytes used by each type.
310 .PP
311 To change the sort order of object allocations, use the option:
312 .PP
313 \f[B]--alloc-sort=MODE\f[]
314 .PP
315 where \f[I]MODE\f[] can be:
316 .IP \[bu] 2
317 \f[I]count\f[]: the number of allocated objects of the given type
318 .IP \[bu] 2
319 \f[I]bytes\f[]: the total number of bytes used by objects of the
320 given type
321 .PP
322 To change the sort order of counters, use the option:
323 .PP
324 \f[B]--counters-sort=MODE\f[]
325 .PP
326 where \f[I]MODE\f[] can be:
327 .IP \[bu] 2
328 \f[I]time\f[]: sort values by time then category
329 .IP \[bu] 2
330 \f[I]category\f[]: sort values by category then time
331 .SS Selecting what data to report
332 .PP
333 The profiler by default collects data about many runtime subsystems
334 and mprof-report prints a summary of all the subsystems that are
335 found in the data file.
336 It is possible to tell mprof-report to only show information about
337 some of them with the following option:
338 .PP
339 \f[B]--reports=R1[,R2...]\f[]
340 .PP
341 where the report names R1, R2 etc.
342 can be:
343 .IP \[bu] 2
344 \f[I]header\f[]: information about program startup and profiler
345 version
346 .IP \[bu] 2
347 \f[I]jit\f[]: JIT compiler information
348 .IP \[bu] 2
349 \f[I]sample\f[]: statistical sampling information
350 .IP \[bu] 2
351 \f[I]gc\f[]: garbage collection information
352 .IP \[bu] 2
353 \f[I]alloc\f[]: object allocation information
354 .IP \[bu] 2
355 \f[I]call\f[]: method profiling information
356 .IP \[bu] 2
357 \f[I]metadata\f[]: metadata events like image loads
358 .IP \[bu] 2
359 \f[I]exception\f[]: exception throw and handling information
360 .IP \[bu] 2
361 \f[I]monitor\f[]: lock contention information
362 .IP \[bu] 2
363 \f[I]thread\f[]: thread information
364 .IP \[bu] 2
365 \f[I]domain\f[]: app domain information
366 .IP \[bu] 2
367 \f[I]context\f[]: remoting context information
368 .IP \[bu] 2
369 \f[I]heapshot\f[]: live heap usage at heap shots
370 .IP \[bu] 2
371 \f[I]counters\f[]: counters samples
372 .IP \[bu] 2
373 \f[I]coverage\f[]: code coverage data
374 .IP \[bu] 2
375 \f[I]stats\f[]: event statistics
376 .PP
377 It is possible to limit some of the data displayed to a timeframe
378 of the program execution with the option:
379 .PP
380 \f[B]--time=FROM-TO\f[]
381 .PP
382 where \f[I]FROM\f[] and \f[I]TO\f[] are seconds since application
383 startup (they can be floating point numbers).
384 .PP
385 Another interesting option is to consider only events happening on
386 a particular thread with the following option:
387 .PP
388 \f[B]--thread=THREADID\f[]
389 .PP
390 where \f[I]THREADID\f[] is one of the numbers listed in the thread
391 summary report (or a thread name when present).
392 .PP
393 By default long lists of methods or other information like object
394 allocations are limited to the most important data.
395 To increase the amount of information printed you can use the
396 option:
397 .PP
398 \f[B]--verbose\f[]
399 .SS Track individual objects
400 .PP
401 Instead of printing the usual reports from the profiler data, it is
402 possible to track some interesting information about some specific
403 object addresses.
404 The objects are selected based on their address with the
405 \f[I]--track\f[] option as follows:
406 .PP
407 \f[B]--track=0xaddr1[,0xaddr2,...]\f[]
408 .PP
409 The reported info (if available in the data file), will be class
410 name, size, creation time, stack trace of creation (with the
411 \f[I]--traces\f[] option), etc.
412 If heapshot data is available it will be possible to also track
413 what other objects reference one of the listed addresses.
414 .PP
415 The object addresses can be gathered either from the profiler
416 report in some cases (like in the monitor lock report), from the
417 live application or they can be selected with the
418 \f[I]--find=FINDSPEC\f[] option.
419 FINDSPEC can be one of the following:
420 .IP \[bu] 2
421 \f[I]S:SIZE\f[]: where the object is selected if its size is at
422 least \f[I]SIZE\f[]
423 .IP \[bu] 2
424 \f[I]T:NAME\f[]: where the object is selected if \f[I]NAME\f[]
425 partially matches its class name
426 .PP
427 This option can be specified multiple times with one of the
428 different kinds of FINDSPEC.
429 For example, the following:
430 .PP
431 \f[B]--find=S:10000\ --find=T:Byte[]\f[]
432 .PP
433 will find all the byte arrays that are at least 10000 bytes in
434 size.
435 .PP
436 Note that with a moving garbage collector the object address can
437 change, so you may need to track the changed address manually.
438 It can also happen that multiple objects are allocated at the same
439 address, so the output from this option can become large.
440 .SS Saving a profiler report
441 .PP
442 By default mprof-report will print the summary data to the console.
443 To print it to a file, instead, use the option:
444 .PP
445 \f[B]--out=FILENAME\f[]
446 .SS Processing code coverage data
447 .PP
448 If you ran the profiler with the \f[I]coverage\f[] option, you can
449 process the collected coverage data into an XML file by running
450 mprof-report like this:
451 .PP
452 \f[B]mprof-report --coverage-out=coverage.xml output.mlpd\f[]
453 .SS Dealing with profiler slowness
454 .PP
455 If the profiler needs to collect lots of data, the execution of the
456 program will slow down significantly, usually 10 to 20 times
457 slower.
458 There are several ways to reduce the impact of the profiler on the
459 program execution.
460 .IP "\f[I]Use the statistical sampling mode\f[]" 4
461 .Sp
462 Statistical sampling allows executing a program under the profiler
463 with minimal performance overhead (usually less than 10%).
464 This mode allows checking where the program is spending most of
465 its execution time without significantly perturbing its behaviour.
466 .IP "\f[I]Collect less data\f[]" 4
467 .Sp
468 Collecting method enter/leave events can be very expensive,
469 especially in programs that perform many millions of tiny calls.
470 The profiler option \f[I]nocalls\f[] can be used to avoid
471 collecting this data or it can be limited to only a few call levels
472 with the \f[I]calldepth\f[] option.
473 .Sp
474 Object allocation information is expensive as well, though much
475 less than method enter/leave events.
476 If it's not needed, it can be skipped with the \f[I]noalloc\f[]
477 profiler option.
478 Note that when method enter/leave events are discarded, by default
479 stack traces are collected at each allocation and this can be
480 expensive as well.
481 The impact of stack trace information can be reduced by setting a
482 low value with the \f[I]maxframes\f[] option or by eliminating them
483 completely, by setting it to 0.
484 .Sp
485 The other major source of data is the \f[I]heapshot\f[] profiler
486 option: especially if the managed heap is big, since every object
487 needs to be inspected.
488 The \f[I]MODE\f[] parameter of the \f[I]heapshot\f[] option can be
489 used to reduce the frequency of the heap shots.
490 .IP "\f[I]Reduce the timestamp overhead\f[]" 4
491 .Sp
492 On many operating systems or architectures what actually slows down
493 profiling is the function provided by the system to get timestamp
494 information.
495 The \f[I]time=fast\f[] profiler option can be usually used to speed
496 up this operation, but, depending on the system, time accounting
497 may have some level of approximation (though statistically the data
498 should be still fairly valuable).
499 .SS Dealing with the size of the data files
500 .PP
501 When collecting a lot of information about a profiled program, huge
502 data files can be generated.
503 There are a few ways to minimize the amount of data, for example by
504 not collecting some of the more space-consuming information or by
505 compressing the information on the fly or by just generating a
506 summary report.
507 .IP "\f[I]Reducing the amount of data\f[]" 4
508 .Sp
509 Method enter/leave events can be excluded completely with the
510 \f[I]nocalls\f[] option or they can be limited to just a few levels
511 of calls with the \f[I]calldepth\f[] option.
512 For example, the option:
513 .Sp
514 \f[B]calldepth=10\f[]
515 .Sp
516 will ignore the method events when there are more than 10 managed
517 stack frames.
518 This is very useful for programs that have deep recursion or for
519 programs that perform many millions of tiny calls deep enough in
520 the call stack.
521 The optimal number for the calldepth option depends on the program
522 and it needs to be balanced between providing enough profiling
523 information and allowing fast execution speed.
524 .Sp
525 Note that by default, if method events are not recorded at all, the
526 profiler will collect stack trace information at events like
527 allocations.
528 To avoid gathering this data, use the \f[I]maxframes=0\f[] profiler
529 option.
530 .Sp
531 Allocation events can be eliminated with the \f[I]noalloc\f[]
532 option.
533 .Sp
534 Heap shot data can also be huge: by default it is collected at each
535 major collection.
536 To reduce the frequency, you can specify a heapshot mode: for
537 example to collect every 5 collections (including major and minor):
538 .Sp
539 \f[B]heapshot=5gc\f[]
540 .Sp
541 or when at least 5 seconds passed since the last heap shot:
542 .Sp
543 \f[B]heapshot=5000ms\f[]
544 .IP "\f[I]Compressing the data\f[]" 4
545 .Sp
546 To reduce the amout of disk space used by the data, the data can be
547 compressed either after it has been generated with the gzip
548 command:
549 .Sp
550 \f[B]gzip\ -9\ output.mlpd\f[]
551 .Sp
552 or it can be compressed automatically by using the \f[I]zip\f[]
553 profiler option.
554 Note that in this case there could be a significant slowdown of the
555 profiled program.
556 .Sp
557 The mprof-report program will tranparently deal with either
558 compressed or uncompressed data files.
559 .IP "\f[I]Generating only a summary report\f[]" 4
560 .Sp
561 Often it's enough to look at the profiler summary report to
562 diagnose an issue and in this case it's possible to avoid saving
563 the profiler data file to disk.
564 This can be accomplished with the \f[I]report\f[] profiler option,
565 which will basically send the data to the mprof-report program for
566 display.
567 .Sp
568 To have more control of what summary information is reported (or to
569 use a completely different program to decode the profiler data),
570 the \f[I]output\f[] profiler option can be used, with \f[B]|\f[] as
571 the first character: the rest of the output name will be executed
572 as a program with the data fed in on the standard input.
573 .Sp
574 For example, to print only the Monitor summary with stack trace
575 information, you could use it like this:
576 .Sp
577 \f[B]output=|mprof-report\ --reports=monitor\ --traces\ -\f[]
578 .SH WEB SITE
579 http://www.mono-project.com/docs/debug+profile/profile/profiler/
580 .SH SEE ALSO
581 .PP
582 mono(1)
583 .SH AUTHORS
584 Paolo Molaro, Alex Rønne Petersen