1 # The Mono log profiler
3 The Mono *log* profiler can be used to collect a lot of information about
4 a program running in the Mono runtime. This data can be used (both while the process
5 is running and later) to do analyses of the program behaviour, determine
6 resource usage, performance issues or even look for particular execution patterns.
8 This is accomplished by logging the events provided by the Mono runtime through the
9 profiling interface and periodically writing them to a file which can be later
10 inspected with the command line *mprof-report* program or with a GUI (not developed yet).
12 The events collected include (among others):
14 * method enter and leave
22 In addition, the profiler can periodically collect info about all the objects
23 present in the heap at the end of a garbage collection (this is called heap shot
24 and currently implemented only for the sgen garbage collector).
26 ## Basic profiler usage
28 The simpler way to use the profiler is the following:
30 `mono --profile=log program.exe`
32 At the end of the execution the file *output.mlpd* will be found in the current
33 directory. A summary report of the data can be printed by running:
35 `mprof-report output.mlpd`
37 With this invocation a huge amount of data is collected about the program execution
38 and collecting and saving this data can significantly slow down program execution.
39 If saving the profiling data is not needed, a report can be generated directly with:
41 `mono --profile=log:report program.exe`
43 If the information about allocations is not of interest, it can be excluded:
45 `mono --profile=log:noalloc program.exe`
47 On the other hand, if method call timing is not important, while allocations are,
48 the needed info can be gathered with:
50 `mono --profile=log:nocalls program.exe`
52 You will still be able to inspect information about the sequence of calls that lead
53 to each allocation because at each object allocation a stack trace is collected as well.
55 To periodically collect heap shots (and exclude method and allocation events) use the
56 following options (making sure you run with the sgen garbage collector):
58 `mono --gc=sgen --profile=log:heapshot program.exe`
60 ## Profiler option documentation
62 By default the *log* profiler will gather all the events provided by the Mono runtime
63 and write them to a file named *output.mlpd*. When no option is specified, it
64 is equivalent to using:
66 `--profile=log:calls,alloc,output=output.mlpd,maxframes=8,calldepth=100`
68 The following options can be used to modify this default behaviour. Each option
69 is separated from the next by a `,` character, with no spaces and all the options
70 are included after the *log:* profile module specifier.
72 * *help*: display concise help info about each available option
74 * *[no]alloc*: *noalloc* disables collecting object allocation info, *alloc* enables
75 it if it was disabled by another option like *heapshot*.
77 * *[no]calls*: *nocalls* disables collecting method enter and leave events. When this
78 option is used at each object allocation and at some other events (like lock contentions
79 and exception throws) a stack trace is collected by default. See the *maxframes* option to
80 control this behaviour. *calls* enables method enter/leave events if they were disabled
81 by another option like *heapshot*.
83 * *heapshot*: collect heap shot data at each major collection. The frequency of the
84 heap shots can be changed with the *hsmode* option below. When this option is used
85 allocation events and method enter/leave events are not recorded by default: if they
86 are needed, they need to be enabled explicitly.
88 * *hsmode=MODE*: modify the default heap shot frequency according to MODE.
89 hsmode can be used multiple times with different modes: in that case a heap shot is
90 taken if either of the conditions are met.
92 * *NUM*ms: perform a heap shot if at least *NUM* milliseconds passed since
94 * *NUM*gc: perform a heap shot every *NUM* garbage collections (either
98 * *time=TIMER*: use the TIMER timestamp mode. TIMER can have the following values:
99 * *fast*: a usually faster but possibly more inaccurate timer
101 * *maxframes=NUM*: when a stack trace needs to be performed, collect *NUM* frames
102 at the most. The default is 8.
104 * *calldepth=NUM*: ignore method enter/leave events when the call chain depth is
107 * *zip*: automatically compress the output data in gzip format.
109 * *output=OUTSPEC*: instead of writing the profiling data to the output.mlpd file,
110 do according to *OUTSPEC*:
111 * if *OUTSPEC* begins with a *|* character, execute the rest as a program
112 and feed the data to its standard input
113 * otherwise write the data the the named file
115 * *report*: the profiling data is sent to mprof-report, which will print a summary
116 report. This is equivalent to the option: `output=mprof-report -`.
118 ## Analyzing the profile data
120 Currently there is a command line program (*mprof-report*) to analyze the
121 data produced by the profiler. This is ran automatically when the *report*
122 profiler option is used.
125 `mprof-report output.mlpd`
127 to see a summary report of the data included in the file.
129 ### Trace information for events
131 Often it is important for some events, like allocations, lock contention
132 and exception throws to know where they happened. Or we may want to see
133 what sequence of calls leads to a particular method invocation. To see this
134 info invoke mprof-report as follows:
136 `mprof-report --traces output.mlpd`
138 The maximum number of methods in each stack trace can be specified with the
139 *--maxframes=NUM* option:
141 `mprof-report --traces --maxframes=4 output.mlpd`
143 The stack trace info will be available if method enter/leave events have been
144 recorded or if stack trace collection wasn't explicitly disabled with the
145 *maxframes=0* profiler option. Note that the profiler will collect up to 8
146 frames by default at specific events when the *nocalls* option is used, so
147 in that case, if more stack frames are required in mprof-report, a bigger
148 value for maxframes when profiling must be used, too.
150 ### Sort order for methods and allocations
152 When a list of methods is printed the default sort order is based on the total time
153 spent in the method. This time is wall clock time (that is, it includes the time
154 spent, for example, in a sleep call, even if actual cpu time would be basically 0).
155 Also, if the method has been ran on different threads, the time will be a sum
156 of the time used in each thread.
158 To change the sort order, use the option:
164 * *self*: amount of time spent in the method itself and not in its callees
165 * *calls*: the number of method invocations
166 * *total*: the total time spent in the method.
168 Object allocation lists are sorted by default depending on the total amount
169 of bytes used by each type.
171 To change the sort order of object allocations, use the option:
177 * *count*: the number of allocated objects of the given type
178 * *bytes*: the total number of bytes used by objects of the given type
180 ### Selecting what data to report
182 The profiler by default collects data about many runtime subsystems and mprof-report
183 prints a summary of all the subsystems that are found in the data file. It is possible
184 to tell mprof-report to only show information about some of them with the following
187 `--reports=R1[,R2...]`
189 where the report names R1, R2 etc. can be:
191 * *gc*: garbage collection information
192 * *alloc*: object allocation information
193 * *call*: method profiling information
194 * *metadata*: metadata events like image loads
195 * *exception*: exception throw and handling information
196 * *monitor*: lock contention information
197 * *thread*: thread information
198 * *heapshot*: live heap usage at heap shots
200 It is possible to limit some of the data displayed to a timeframe of the
201 program execution with the option:
205 where *FROM* and *TO* are seconds since application startup (they can be
206 floating point numbers).
208 Another interesting option is to consider only events happening on a particular
209 thread with the following option:
213 where *THREADID* is one of the numbers listed in the thread summary report
214 (or a thread name when present).
216 By default long lists of methods or other information like object allocations
217 are limited to the most important data. To increase the amount of information
218 printed you can use the option:
222 ### Track individual objects
224 Instead of printing the usual reports from the profiler data, it is possible
225 to track some interesting information about some specific object addresses.
226 The objects are selected based on their address with the *--track* option as follows:
228 `--track=0xaddr1[,0xaddr2,...]`
230 The reported info (if available in the data file), will be class name, size,
231 creation time, stack trace of creation (with the *--traces* option), etc.
232 If heapshot data is available it will be possible to also track what other objects
233 reference one of the listed addresses.
235 The object addresses can be gathered either from the profiler report in some
236 cases (like in the monitor lock report), from the live application or they can
237 be selected with the *--find=FINDSPEC* option. FINDSPEC can be one of the
240 * *S:SIZE*: where the object is selected if it's size is at least *SIZE*
241 * *T:NAME*: where the object is selected if *NAME* partially matches its class name
243 This option can be specified multiple times with one of the different kinds
244 of FINDSPEC. For example, the following:
246 `--find=S:10000 --find=T:Byte[]`
248 will find all the byte arrays that are at least 10000 bytes in size.
250 ### Saving a profiler report
252 By default mprof-report will print the summary data to the console.
253 To print it to a file, instead, use the option:
257 ## Dealing with profiler slowness
259 If the profiler needs to collect lots of data, the execution of the program will
260 slow down significantly, usually 10 to 20 times slower. There are several
261 ways to reduce the impact of the profiler on the program execution.
263 ### Collect less data
265 Collecting method enter/leave events can be very expensive, especially in programs
266 that perform many millions of tiny calls. The profiler option *nocalls* can be
267 used to avoid collecting this data or it can be limited to only a few call levels
268 with the *calldepth* option.
270 Object allocation information is expensive as well, though much less than
271 method enter/leave events. If it's not needed, it can be skipped with the
272 *noalloc* profiler option. Note that when method enter/leave events are
273 discarded, by default stack traces are collected at each allocation and this
274 can be expensive as well. The impact of stack trace information can be reduced
275 by setting a low value with the *maxframes* option or by eliminating them
276 completely, by setting it to 0.
278 The other major source of data is the heapshot profiler option: especially
279 if the managed heap is big, since every object needs to be inspected. The *hsmode*
280 option can be used to reduce the frequency of the heap shots.
282 ### Reduce the timestamp overhead
284 On many operating systems or architectures what actually slows down profiling
285 is the function provided by the system to get timestamp information.
286 The *time=fast* profiler option can be usually used to speed up this operation,
287 but, depending on the system, time accounting may have some level of approximation
288 (though statistically the data should be still fairly valuable).
290 ### Use a statistical profiler instead
292 See the mono manpage for the use of a statistical (sampling) profiler.
293 The *log* profiler will be enhanced to provide sampling info in the future.
295 ## Dealing with the size of the data files
297 When collecting a lot of information about a profiled program, huge data
298 files can be generated. There are a few ways to minimize the amount of data,
299 for example by not collecting some of the more space-consuming information
300 or by compressing the information on the fly or by just generating a summary
303 ### Reducing the amount of data
305 Method enter/leave events can be excluded completely with the *nocalls* option
306 or they can be limited to just a few levels of calls with the *calldepth* option.
307 For example, the option:
311 will ignore the method events when there are more than 10 managed stack frames.
312 This is very useful for programs that have deep recursion or for programs that
313 perform many millions of tiny calls deep enough in the call stack. The optimal
314 number for the calldepth option depends on the program and it needs to be balanced
315 between providing enough profiling information and allowing fast execution speed.
317 Note that by default, if method events are not recorded at all, the profiler will
318 collect stack trace information at events like allocations. To avoid gathering this
319 data, use the *maxframes=0* profiler option.
321 Allocation events can be eliminated with the *noalloc* option.
323 Heap shot data can also be huge: by default it is collected at each major collection.
324 To reduce the frequency, you can use the *hsmode* profiler option to collect for example
325 every 5 collections (including major and minor):
329 or when at least 5 seconds passed since the last heap shot:
333 ### Compressing the data
335 To reduce the amout of disk space used by the data, the data can be compressed
336 either after it has been generated with the gzip command:
338 `gzip -9 output.mlpd`
340 or it can be compressed automatically by using the *zip* profiler option. Note
341 that in this case there could be a significant slowdown of the profiled program.
343 The mprof-report program will tranparently deal with either compressed or
344 uncompressed data files.
346 ### Generating only a summary report
348 Often it's enough to look at the profiler summary report to diagnose an issue and in this
349 case it's possible to avoid saving the profiler data file to disk. This can be
350 accomplished with the *report* profiler option, which will basically send the data
351 to the mprof-report program for display.
353 To have more control of what summary information is reported (or to use a completely
354 different program to decode the profiler data), the *output* profiler option can be
355 used, with `|` as the first character: the rest of the output name will be
356 executed as a program with the data fed in on the standard input.
358 For example, to print only the Monitor summary with stack trace information, you
359 could use it like this:
361 `output=|mprof-report --reports=monitor --traces -`