2 .SH The Mono log profiler
4 The Mono \f[I]log\f[] profiler can be used to collect a lot of
5 information about a program running in the Mono runtime.
6 This data can be used (both while the process is running and later)
7 to do analyses of the program behaviour, determine resource usage,
8 performance issues or even look for particular execution patterns.
10 This is accomplished by logging the events provided by the Mono
11 runtime through the profiling interface and periodically writing
12 them to a file which can be later inspected with the command line
13 \f[I]mprof-report\f[] program or with a GUI (not developed yet).
15 The events collected include (among others):
17 method enter and leave
31 In addition, the profiler can periodically collect info about all
32 the objects present in the heap at the end of a garbage collection
33 (this is called heap shot and currently implemented only for the
34 sgen garbage collector).
35 Another available profiler mode is the \f[I]sampling\f[] or
36 \f[I]statistical\f[] mode: periodically the program is sampled and
37 the information about what the program was busy with is saved.
38 This allows to get information about the program behaviour without
39 degrading its performance too much (usually less than 10%).
40 .SS Basic profiler usage
42 The simpler way to use the profiler is the following:
44 \f[B]mono\ --profile=log\ program.exe\f[]
46 At the end of the execution the file \f[I]output.mlpd\f[] will be
47 found in the current directory.
48 A summary report of the data can be printed by running:
50 \f[B]mprof-report\ output.mlpd\f[]
52 With this invocation a huge amount of data is collected about the
53 program execution and collecting and saving this data can
54 significantly slow down program execution.
55 If saving the profiling data is not needed, a report can be
56 generated directly with:
58 \f[B]mono\ --profile=log:report\ program.exe\f[]
60 If the information about allocations is not of interest, it can be
63 \f[B]mono\ --profile=log:noalloc\ program.exe\f[]
65 On the other hand, if method call timing is not important, while
66 allocations are, the needed info can be gathered with:
68 \f[B]mono\ --profile=log:nocalls\ program.exe\f[]
70 You will still be able to inspect information about the sequence of
71 calls that lead to each allocation because at each object
72 allocation a stack trace is collected if full enter/leave
73 information is not available.
75 To periodically collect heap shots (and exclude method and
76 allocation events) use the following options (making sure you run
77 with the sgen garbage collector):
79 \f[B]mono\ --gc=sgen\ --profile=log:heapshot\ program.exe\f[]
81 To perform a sampling profiler run, use the \f[I]sample\f[] option:
83 \f[B]mono\ --profile=log:sample\ program.exe\f[]
84 .SS Profiler option documentation
86 By default the \f[I]log\f[] profiler will gather all the events
87 provided by the Mono runtime and write them to a file named
89 When no option is specified, it is equivalent to using:
91 \f[B]--profile=log:calls,alloc,output=output.mlpd,maxframes=8,calldepth=100\f[]
93 The following options can be used to modify this default behaviour.
94 Each option is separated from the next by a \f[B],\f[] character,
95 with no spaces and all the options are included after the
96 \f[I]log:\f[] profile module specifier.
98 \f[I]help\f[]: display concise help info about each available
101 \f[I][no]alloc\f[]: \f[I]noalloc\f[] disables collecting object
102 allocation info, \f[I]alloc\f[] enables it if it was disabled by
103 another option like \f[I]heapshot\f[].
105 \f[I][no]calls\f[]: \f[I]nocalls\f[] disables collecting method
106 enter and leave events.
107 When this option is used at each object allocation and at some
108 other events (like lock contentions and exception throws) a stack
109 trace is collected by default.
110 See the \f[I]maxframes\f[] option to control this behaviour.
111 \f[I]calls\f[] enables method enter/leave events if they were
112 disabled by another option like \f[I]heapshot\f[].
114 \f[I]heapshot[=MODE]\f[]: collect heap shot data at each major
116 The frequency of the heap shots can be changed with the
117 \f[I]MODE\f[] parameter.
118 When this option is used allocation events and method enter/leave
119 events are not recorded by default: if they are needed, they need
120 to be enabled explicitly.
121 The optional parameter \f[I]MODE\f[] can modify the default heap
123 heapshot can be used multiple times with different modes: in that
124 case a heap shot is taken if either of the conditions are met.
128 \f[I]NUM\f[]ms: perform a heap shot if at least \f[I]NUM\f[]
129 milliseconds passed since the last one.
131 \f[I]NUM\f[]gc: perform a heap shot every \f[I]NUM\f[] major
134 \f[I]ondemand\f[]: perform a heap shot when such a command is sent
138 \f[I]sample[=TYPE[/FREQ]]\f[]: collect statistical samples of the
140 The default is to collect a 1000 times per second the instruction
142 This is equivalent to the value \[lq]cycles/1000\[rq] for
144 On some systems, like with recent Linux kernels, it is possible to
145 cause the sampling to happen for other events provided by the
146 performance counters of the cpu.
147 In this case, \f[I]TYPE\f[] can be one of:
150 \f[I]cycles\f[]: processor cycles
152 \f[I]instr\f[]: executed instructions
154 \f[I]cacherefs\f[]: cache references
156 \f[I]cachemiss\f[]: cache misses
158 \f[I]branches\f[]: executed branches
160 \f[I]branchmiss\f[]: mispredicted branches
163 \f[I]time=TIMER\f[]: use the TIMER timestamp mode.
164 TIMER can have the following values:
167 \f[I]fast\f[]: a usually faster but possibly more inaccurate timer
170 \f[I]maxframes=NUM\f[]: when a stack trace needs to be performed,
171 collect \f[I]NUM\f[] frames at the most.
174 \f[I]calldepth=NUM\f[]: ignore method enter/leave events when the
175 call chain depth is bigger than NUM.
177 \f[I]zip\f[]: automatically compress the output data in gzip
180 \f[I]output=OUTSPEC\f[]: instead of writing the profiling data to
181 the output.mlpd file, substitute \f[I]%p\f[] in \f[I]OUTSPEC\f[]
182 with the current process id and \f[I]%t\f[] with the current date
183 and time, then do according to \f[I]OUTSPEC\f[]:
186 if \f[I]OUTSPEC\f[] begins with a \f[I]|\f[] character, execute the
187 rest as a program and feed the data to its standard input
189 if \f[I]OUTSPEC\f[] begins with a \f[I]-\f[] character, use the
190 rest of OUTSPEC as the filename, but force overwrite any existing
193 otherwise write the data the the named file: note that is a file by
194 that name already exists, a warning is issued and profiling is
198 \f[I]report\f[]: the profiling data is sent to mprof-report, which
199 will print a summary report.
200 This is equivalent to the option: \f[B]output=mprof-report\ -\f[].
201 If the \f[I]output\f[] option is specified as well, the report will
202 be written to the output file instead of the console.
204 \f[I]port=PORT\f[]: specify the tcp/ip port to use for the
205 listening command server.
206 Currently not available for windows.
207 This server is started for example when heapshot=ondemand is used:
208 it will read commands line by line.
209 The following commands are available:
212 \f[I]heapshot\f[]: perform a heapshot as soon as possible
215 \f[I]counters\f[]: sample counters values every 1 second. This allow
216 a really lightweight way to have insight in some of the runtime key
217 metrics. Counters displayed in non verbose mode are : Methods from AOT,
218 Methods JITted using mono JIT, Methods JITted using LLVM, Total time
219 spent JITting (sec), User Time, System Time, Total Time, Working Set,
220 Private Bytes, Virtual Bytes, Page Faults and CPU Load Average (1min,
223 .SS Analyzing the profile data
225 Currently there is a command line program (\f[I]mprof-report\f[])
226 to analyze the data produced by the profiler.
227 This is ran automatically when the \f[I]report\f[] profiler option
231 \f[B]mprof-report\ output.mlpd\f[]
233 to see a summary report of the data included in the file.
234 .SS Trace information for events
236 Often it is important for some events, like allocations, lock
237 contention and exception throws to know where they happened.
238 Or we may want to see what sequence of calls leads to a particular
240 To see this info invoke mprof-report as follows:
242 \f[B]mprof-report\ --traces\ output.mlpd\f[]
244 The maximum number of methods in each stack trace can be specified
245 with the \f[I]\[em]maxframes=NUM\f[] option:
247 \f[B]mprof-report\ --traces\ --maxframes=4\ output.mlpd\f[]
249 The stack trace info will be available if method enter/leave events
250 have been recorded or if stack trace collection wasn't explicitly
251 disabled with the \f[I]maxframes=0\f[] profiler option.
252 Note that the profiler will collect up to 8 frames by default at
253 specific events when the \f[I]nocalls\f[] option is used, so in
254 that case, if more stack frames are required in mprof-report, a
255 bigger value for maxframes when profiling must be used, too.
257 The \f[I]\[em]traces\f[] option also controls the reverse reference
258 feature in the heapshot report: for each class it reports how many
259 references to objects of that class come from other classes.
260 .SS Sort order for methods and allocations
262 When a list of methods is printed the default sort order is based
263 on the total time spent in the method.
264 This time is wall clock time (that is, it includes the time spent,
265 for example, in a sleep call, even if actual cpu time would be
267 Also, if the method has been ran on different threads, the time
268 will be a sum of the time used in each thread.
270 To change the sort order, use the option:
272 \f[B]--method-sort=MODE\f[]
274 where \f[I]MODE\f[] can be:
276 \f[I]self\f[]: amount of time spent in the method itself and not in
279 \f[I]calls\f[]: the number of method invocations
281 \f[I]total\f[]: the total time spent in the method.
283 Object allocation lists are sorted by default depending on the
284 total amount of bytes used by each type.
286 To change the sort order of object allocations, use the option:
288 \f[B]--alloc-sort=MODE\f[]
290 where \f[I]MODE\f[] can be:
292 \f[I]count\f[]: the number of allocated objects of the given type
294 \f[I]bytes\f[]: the total number of bytes used by objects of the
297 To change the sort order of counters, use the option:
299 \f[B]--counters-sort=MODE\f[]
301 where \f[I]MODE\f[] can be:
303 \f[I]time\f[]: sort values by time then category
305 \f[I]category\f[]: sort values by category then time
306 .SS Selecting what data to report
308 The profiler by default collects data about many runtime subsystems
309 and mprof-report prints a summary of all the subsystems that are
310 found in the data file.
311 It is possible to tell mprof-report to only show information about
312 some of them with the following option:
314 \f[B]--reports=R1[,R2...]\f[]
316 where the report names R1, R2 etc.
319 \f[I]header\f[]: information about program startup and profiler
322 \f[I]jit\f[]: JIT compiler information
324 \f[I]sample\f[]: statistical sampling information
326 \f[I]gc\f[]: garbage collection information
328 \f[I]alloc\f[]: object allocation information
330 \f[I]call\f[]: method profiling information
332 \f[I]metadata\f[]: metadata events like image loads
334 \f[I]exception\f[]: exception throw and handling information
336 \f[I]monitor\f[]: lock contention information
338 \f[I]thread\f[]: thread information
340 \f[I]domain\f[]: app domain information
342 \f[I]context\f[]: remoting context information
344 \f[I]heapshot\f[]: live heap usage at heap shots
346 \f[I]counters\f[]: counters samples
348 It is possible to limit some of the data displayed to a timeframe
349 of the program execution with the option:
351 \f[B]--time=FROM-TO\f[]
353 where \f[I]FROM\f[] and \f[I]TO\f[] are seconds since application
354 startup (they can be floating point numbers).
356 Another interesting option is to consider only events happening on
357 a particular thread with the following option:
359 \f[B]--thread=THREADID\f[]
361 where \f[I]THREADID\f[] is one of the numbers listed in the thread
362 summary report (or a thread name when present).
364 By default long lists of methods or other information like object
365 allocations are limited to the most important data.
366 To increase the amount of information printed you can use the
370 .SS Track individual objects
372 Instead of printing the usual reports from the profiler data, it is
373 possible to track some interesting information about some specific
375 The objects are selected based on their address with the
376 \f[I]\[em]track\f[] option as follows:
378 \f[B]--track=0xaddr1[,0xaddr2,...]\f[]
380 The reported info (if available in the data file), will be class
381 name, size, creation time, stack trace of creation (with the
382 \f[I]\[em]traces\f[] option), etc.
383 If heapshot data is available it will be possible to also track
384 what other objects reference one of the listed addresses.
386 The object addresses can be gathered either from the profiler
387 report in some cases (like in the monitor lock report), from the
388 live application or they can be selected with the
389 \f[I]\[em]find=FINDSPEC\f[] option.
390 FINDSPEC can be one of the following:
392 \f[I]S:SIZE\f[]: where the object is selected if it's size is at
395 \f[I]T:NAME\f[]: where the object is selected if \f[I]NAME\f[]
396 partially matches its class name
398 This option can be specified multiple times with one of the
399 different kinds of FINDSPEC.
400 For example, the following:
402 \f[B]--find=S:10000\ --find=T:Byte[]\f[]
404 will find all the byte arrays that are at least 10000 bytes in
407 Note that with a moving garbage collector the object address can
408 change, so you may need to track the changed address manually.
409 It can also happen that multiple objects are allocated at the same
410 address, so the output from this option can become large.
411 .SS Saving a profiler report
413 By default mprof-report will print the summary data to the console.
414 To print it to a file, instead, use the option:
416 \f[B]--out=FILENAME\f[]
417 .SS Dealing with profiler slowness
419 If the profiler needs to collect lots of data, the execution of the
420 program will slow down significantly, usually 10 to 20 times
422 There are several ways to reduce the impact of the profiler on the
424 .SS Use the statistical sampling mode
426 Statistical sampling allows executing a program under the profiler
427 with minimal performance overhead (usually less than 10%).
428 This mode allows checking where the program is spending most of
429 it's execution time without significantly perturbing its behaviour.
430 .SS Collect less data
432 Collecting method enter/leave events can be very expensive,
433 especially in programs that perform many millions of tiny calls.
434 The profiler option \f[I]nocalls\f[] can be used to avoid
435 collecting this data or it can be limited to only a few call levels
436 with the \f[I]calldepth\f[] option.
438 Object allocation information is expensive as well, though much
439 less than method enter/leave events.
440 If it's not needed, it can be skipped with the \f[I]noalloc\f[]
442 Note that when method enter/leave events are discarded, by default
443 stack traces are collected at each allocation and this can be
445 The impact of stack trace information can be reduced by setting a
446 low value with the \f[I]maxframes\f[] option or by eliminating them
447 completely, by setting it to 0.
449 The other major source of data is the heapshot profiler option:
450 especially if the managed heap is big, since every object needs to
452 The \f[I]MODE\f[] parameter of the \f[I]heapshot\f[] option can be
453 used to reduce the frequency of the heap shots.
454 .SS Reduce the timestamp overhead
456 On many operating systems or architectures what actually slows down
457 profiling is the function provided by the system to get timestamp
459 The \f[I]time=fast\f[] profiler option can be usually used to speed
460 up this operation, but, depending on the system, time accounting
461 may have some level of approximation (though statistically the data
462 should be still fairly valuable).
463 .SS Dealing with the size of the data files
465 When collecting a lot of information about a profiled program, huge
466 data files can be generated.
467 There are a few ways to minimize the amount of data, for example by
468 not collecting some of the more space-consuming information or by
469 compressing the information on the fly or by just generating a
471 .SS Reducing the amount of data
473 Method enter/leave events can be excluded completely with the
474 \f[I]nocalls\f[] option or they can be limited to just a few levels
475 of calls with the \f[I]calldepth\f[] option.
476 For example, the option:
478 \f[B]calldepth=10\f[]
480 will ignore the method events when there are more than 10 managed
482 This is very useful for programs that have deep recursion or for
483 programs that perform many millions of tiny calls deep enough in
485 The optimal number for the calldepth option depends on the program
486 and it needs to be balanced between providing enough profiling
487 information and allowing fast execution speed.
489 Note that by default, if method events are not recorded at all, the
490 profiler will collect stack trace information at events like
492 To avoid gathering this data, use the \f[I]maxframes=0\f[] profiler
495 Allocation events can be eliminated with the \f[I]noalloc\f[]
498 Heap shot data can also be huge: by default it is collected at each
500 To reduce the frequency, you can specify a heapshot mode: for
501 example to collect every 5 collections (including major and minor):
503 \f[B]heapshot=5gc\f[]
505 or when at least 5 seconds passed since the last heap shot:
507 \f[B]heapshot=5000ms\f[]
508 .SS Compressing the data
510 To reduce the amout of disk space used by the data, the data can be
511 compressed either after it has been generated with the gzip
514 \f[B]gzip\ -9\ output.mlpd\f[]
516 or it can be compressed automatically by using the \f[I]zip\f[]
518 Note that in this case there could be a significant slowdown of the
521 The mprof-report program will tranparently deal with either
522 compressed or uncompressed data files.
523 .SS Generating only a summary report
525 Often it's enough to look at the profiler summary report to
526 diagnose an issue and in this case it's possible to avoid saving
527 the profiler data file to disk.
528 This can be accomplished with the \f[I]report\f[] profiler option,
529 which will basically send the data to the mprof-report program for
532 To have more control of what summary information is reported (or to
533 use a completely different program to decode the profiler data),
534 the \f[I]output\f[] profiler option can be used, with \f[B]|\f[] as
535 the first character: the rest of the output name will be executed
536 as a program with the data fed in on the standard input.
538 For example, to print only the Monitor summary with stack trace
539 information, you could use it like this:
541 \f[B]output=|mprof-report\ --reports=monitor\ --traces\ -\f[]
543 http://www.mono-project.com/docs/debug+profile/profile/profiler/