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=32,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[=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]100\[rq].
 147 A value of zero for \f[I]FREQ\f[] effectively disables sampling.
 148 .IP \[bu] 2
 149 \f[I]heapshot-on-shutdown\f[]: collect heap shot data when the runtime
 150 shuts down.
 151 .IP \[bu] 2
 152 \f[I]maxframes=NUM\f[]: when a stack trace needs to be performed,
 153 collect \f[I]NUM\f[] frames at the most.
 154 The default is 32.
 155 .IP \[bu] 2
 156 \f[I]maxsamples=NUM\f[]: stop allocating reusable sample events
 157 once \f[I]NUM\f[] events have been allocated (a value of zero for
 158 all intents and purposes means unlimited). By default, the value
 159 of this setting is the number of CPU cores multiplied by 1000. This
 160 is usually a good enough value for typical desktop and mobile apps.
 161 If you're losing too many samples due to this default (which is
 162 possible in apps with an unusually high amount of threads), you
 163 may want to tinker with this value to find a good balance between
 164 sample hit rate and performance impact on the app. The way it works
 165 is that sample events are enqueued for reuse after they're flushed
 166 to the output file; if a thread gets a sampling signal but there are
 167 no sample events in the reuse queue and the profiler has reached the
 168 maximum number of sample allocations, the sample gets dropped. So a
 169 higher number for this setting will increase the chance that a
 170 thread is able to collect a sample, but also necessarily means that
 171 there will be more work done by the profiler. You can run Mono with
 172 the \f[I]--stats\f[] option to see statistics about sample events.
 173 .IP \[bu] 2
 174 \f[I]calldepth=NUM\f[]: ignore method enter/leave events when the
 175 call chain depth is bigger than NUM.
 176 .IP \[bu] 2
 177 \f[I]zip\f[]: automatically compress the output data in gzip
 178 format.
 179 .IP \[bu] 2
 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[]:
 184 .RS 2
 185 .IP \[bu] 2
 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.
 188 .IP \[bu] 2
 189 If \f[I]OUTSPEC\f[] begins with a \f[I]#\f[] character, parse the
 190 rest as a file descriptor number, and feed the data to this file
 191 descriptor.
 192 .IP \[bu] 2
 193 otherwise write the data the the named file: note that is a file by
 194 that name already exists, it is truncated.
 195 .RE
 196 .IP \[bu] 2
 197 \f[I]report\f[]: the profiling data is sent to mprof-report, which
 198 will print a summary report.
 199 This is equivalent to the option: \f[B]output=mprof-report\ -\f[].
 200 If the \f[I]output\f[] option is specified as well, the report will
 201 be written to the output file instead of the console.
 202 .IP \[bu] 2
 203 \f[I]port=PORT\f[]: specify the tcp/ip port to use for the
 204 listening command server.
 205 Currently not available for windows.
 206 This server is started for example when heapshot=ondemand is used:
 207 it will read commands line by line.
 208 The following commands are available:
 209 .RS 2
 210 .IP \[bu] 2
 211 \f[I]heapshot\f[]: perform a heapshot as soon as possible
 212 .RE
 213 .IP \[bu] 2
 214 \f[I]nocounters\f[]: disables sampling of runtime and performance
 215 counters, which is normally done every 1 second.
 216 .RE
 217 .SS Analyzing the profile data
 218 .PP
 219 Currently there is a command line program (\f[I]mprof-report\f[])
 220 to analyze the data produced by the profiler.
 221 This is ran automatically when the \f[I]report\f[] profiler option
 222 is used.
 223 Simply run:
 224 .PP
 225 \f[B]mprof-report\ output.mlpd\f[]
 226 .PP
 227 to see a summary report of the data included in the file.
 228 .SS Trace information for events
 229 .PP
 230 Often it is important for some events, like allocations, lock
 231 contention and exception throws to know where they happened.
 232 Or we may want to see what sequence of calls leads to a particular
 233 method invocation.
 234 To see this info invoke mprof-report as follows:
 235 .PP
 236 \f[B]mprof-report\ --traces\ output.mlpd\f[]
 237 .PP
 238 The maximum number of methods in each stack trace can be specified
 239 with the \f[I]--maxframes=NUM\f[] option:
 240 .PP
 241 \f[B]mprof-report\ --traces\ --maxframes=4\ output.mlpd\f[]
 242 .PP
 243 The stack trace info will be available if method enter/leave events
 244 have been recorded or if stack trace collection wasn't explicitly
 245 disabled with the \f[I]maxframes=0\f[] profiler option.
 246 .PP
 247 The \f[I]--traces\f[] option also controls the reverse reference
 248 feature in the heapshot report: for each class it reports how many
 249 references to objects of that class come from other classes.
 250 .SS Sort order for methods and allocations
 251 .PP
 252 When a list of methods is printed the default sort order is based
 253 on the total time spent in the method.
 254 This time is wall clock time (that is, it includes the time spent,
 255 for example, in a sleep call, even if actual cpu time would be
 256 basically 0).
 257 Also, if the method has been ran on different threads, the time
 258 will be a sum of the time used in each thread.
 259 .PP
 260 To change the sort order, use the option:
 261 .PP
 262 \f[B]--method-sort=MODE\f[]
 263 .PP
 264 where \f[I]MODE\f[] can be:
 265 .IP \[bu] 2
 266 \f[I]self\f[]: amount of time spent in the method itself and not in
 267 its callees
 268 .IP \[bu] 2
 269 \f[I]calls\f[]: the number of method invocations
 270 .IP \[bu] 2
 271 \f[I]total\f[]: the total time spent in the method.
 272 .PP
 273 Object allocation lists are sorted by default depending on the
 274 total amount of bytes used by each type.
 275 .PP
 276 To change the sort order of object allocations, use the option:
 277 .PP
 278 \f[B]--alloc-sort=MODE\f[]
 279 .PP
 280 where \f[I]MODE\f[] can be:
 281 .IP \[bu] 2
 282 \f[I]count\f[]: the number of allocated objects of the given type
 283 .IP \[bu] 2
 284 \f[I]bytes\f[]: the total number of bytes used by objects of the
 285 given type
 286 .PP
 287 To change the sort order of counters, use the option:
 288 .PP
 289 \f[B]--counters-sort=MODE\f[]
 290 .PP
 291 where \f[I]MODE\f[] can be:
 292 .IP \[bu] 2
 293 \f[I]time\f[]: sort values by time then category
 294 .IP \[bu] 2
 295 \f[I]category\f[]: sort values by category then time
 296 .SS Selecting what data to report
 297 .PP
 298 The profiler by default collects data about many runtime subsystems
 299 and mprof-report prints a summary of all the subsystems that are
 300 found in the data file.
 301 It is possible to tell mprof-report to only show information about
 302 some of them with the following option:
 303 .PP
 304 \f[B]--reports=R1[,R2...]\f[]
 305 .PP
 306 where the report names R1, R2 etc.
 307 can be:
 308 .IP \[bu] 2
 309 \f[I]header\f[]: information about program startup and profiler
 310 version
 311 .IP \[bu] 2
 312 \f[I]jit\f[]: JIT compiler information
 313 .IP \[bu] 2
 314 \f[I]sample\f[]: statistical sampling information
 315 .IP \[bu] 2
 316 \f[I]gc\f[]: garbage collection information
 317 .IP \[bu] 2
 318 \f[I]alloc\f[]: object allocation information
 319 .IP \[bu] 2
 320 \f[I]call\f[]: method profiling information
 321 .IP \[bu] 2
 322 \f[I]metadata\f[]: metadata events like image loads
 323 .IP \[bu] 2
 324 \f[I]exception\f[]: exception throw and handling information
 325 .IP \[bu] 2
 326 \f[I]monitor\f[]: lock contention information
 327 .IP \[bu] 2
 328 \f[I]thread\f[]: thread information
 329 .IP \[bu] 2
 330 \f[I]domain\f[]: app domain information
 331 .IP \[bu] 2
 332 \f[I]context\f[]: remoting context information
 333 .IP \[bu] 2
 334 \f[I]heapshot\f[]: live heap usage at heap shots
 335 .IP \[bu] 2
 336 \f[I]counters\f[]: counters samples
 337 .IP \[bu] 2
 338 \f[I]stats\f[]: event statistics
 339 .PP
 340 It is possible to limit some of the data displayed to a timeframe
 341 of the program execution with the option:
 342 .PP
 343 \f[B]--time=FROM-TO\f[]
 344 .PP
 345 where \f[I]FROM\f[] and \f[I]TO\f[] are seconds since application
 346 startup (they can be floating point numbers).
 347 .PP
 348 Another interesting option is to consider only events happening on
 349 a particular thread with the following option:
 350 .PP
 351 \f[B]--thread=THREADID\f[]
 352 .PP
 353 where \f[I]THREADID\f[] is one of the numbers listed in the thread
 354 summary report (or a thread name when present).
 355 .PP
 356 By default long lists of methods or other information like object
 357 allocations are limited to the most important data.
 358 To increase the amount of information printed you can use the
 359 option:
 360 .PP
 361 \f[B]--verbose\f[]
 362 .SS Track individual objects
 363 .PP
 364 Instead of printing the usual reports from the profiler data, it is
 365 possible to track some interesting information about some specific
 366 object addresses.
 367 The objects are selected based on their address with the
 368 \f[I]--track\f[] option as follows:
 369 .PP
 370 \f[B]--track=0xaddr1[,0xaddr2,...]\f[]
 371 .PP
 372 The reported info (if available in the data file), will be class
 373 name, size, creation time, stack trace of creation (with the
 374 \f[I]--traces\f[] option), etc.
 375 If heapshot data is available it will be possible to also track
 376 what other objects reference one of the listed addresses.
 377 .PP
 378 The object addresses can be gathered either from the profiler
 379 report in some cases (like in the monitor lock report), from the
 380 live application or they can be selected with the
 381 \f[I]--find=FINDSPEC\f[] option.
 382 FINDSPEC can be one of the following:
 383 .IP \[bu] 2
 384 \f[I]S:SIZE\f[]: where the object is selected if its size is at
 385 least \f[I]SIZE\f[]
 386 .IP \[bu] 2
 387 \f[I]T:NAME\f[]: where the object is selected if \f[I]NAME\f[]
 388 partially matches its class name
 389 .PP
 390 This option can be specified multiple times with one of the
 391 different kinds of FINDSPEC.
 392 For example, the following:
 393 .PP
 394 \f[B]--find=S:10000\ --find=T:Byte[]\f[]
 395 .PP
 396 will find all the byte arrays that are at least 10000 bytes in
 397 size.
 398 .PP
 399 Note that with a moving garbage collector the object address can
 400 change, so you may need to track the changed address manually.
 401 It can also happen that multiple objects are allocated at the same
 402 address, so the output from this option can become large.
 403 .SS Saving a profiler report
 404 .PP
 405 By default mprof-report will print the summary data to the console.
 406 To print it to a file, instead, use the option:
 407 .PP
 408 \f[B]--out=FILENAME\f[]
 409 .SS Dealing with profiler slowness
 410 .PP
 411 If the profiler needs to collect lots of data, the execution of the
 412 program will slow down significantly, usually 10 to 20 times
 413 slower.
 414 There are several ways to reduce the impact of the profiler on the
 415 program execution.
 416 .IP "\f[I]Use the statistical sampling mode\f[]" 4
 417 .Sp
 418 Statistical sampling allows executing a program under the profiler
 419 with minimal performance overhead (usually less than 10%).
 420 This mode allows checking where the program is spending most of
 421 its execution time without significantly perturbing its behaviour.
 422 .IP "\f[I]Collect less data\f[]" 4
 423 .Sp
 424 Collecting method enter/leave events can be very expensive,
 425 especially in programs that perform many millions of tiny calls.
 426 The profiler option \f[I]nocalls\f[] can be used to avoid
 427 collecting this data or it can be limited to only a few call levels
 428 with the \f[I]calldepth\f[] option.
 429 .Sp
 430 Object allocation information is expensive as well, though much
 431 less than method enter/leave events.
 432 If it's not needed, it can be skipped with the \f[I]noalloc\f[]
 433 profiler option.
 434 Note that when method enter/leave events are discarded, by default
 435 stack traces are collected at each allocation and this can be
 436 expensive as well.
 437 The impact of stack trace information can be reduced by setting a
 438 low value with the \f[I]maxframes\f[] option or by eliminating them
 439 completely, by setting it to 0.
 440 .Sp
 441 The other major source of data is the \f[I]heapshot\f[] profiler
 442 option: especially if the managed heap is big, since every object
 443 needs to be inspected.
 444 The \f[I]MODE\f[] parameter of the \f[I]heapshot\f[] option can be
 445 used to reduce the frequency of the heap shots.
 446 .SS Dealing with the size of the data files
 447 .PP
 448 When collecting a lot of information about a profiled program, huge
 449 data files can be generated.
 450 There are a few ways to minimize the amount of data, for example by
 451 not collecting some of the more space-consuming information or by
 452 compressing the information on the fly or by just generating a
 453 summary report.
 454 .IP "\f[I]Reducing the amount of data\f[]" 4
 455 .Sp
 456 Method enter/leave events can be excluded completely with the
 457 \f[I]nocalls\f[] option or they can be limited to just a few levels
 458 of calls with the \f[I]calldepth\f[] option.
 459 For example, the option:
 460 .Sp
 461 \f[B]calldepth=10\f[]
 462 .Sp
 463 will ignore the method events when there are more than 10 managed
 464 stack frames.
 465 This is very useful for programs that have deep recursion or for
 466 programs that perform many millions of tiny calls deep enough in
 467 the call stack.
 468 The optimal number for the calldepth option depends on the program
 469 and it needs to be balanced between providing enough profiling
 470 information and allowing fast execution speed.
 471 .Sp
 472 Note that by default, if method events are not recorded at all, the
 473 profiler will collect stack trace information at events like
 474 allocations.
 475 To avoid gathering this data, use the \f[I]maxframes=0\f[] profiler
 476 option.
 477 .Sp
 478 Allocation events can be eliminated with the \f[I]noalloc\f[]
 479 option.
 480 .Sp
 481 Heap shot data can also be huge: by default it is collected at each
 482 major collection.
 483 To reduce the frequency, you can specify a heapshot mode: for
 484 example to collect every 5 collections (including major and minor):
 485 .Sp
 486 \f[B]heapshot=5gc\f[]
 487 .Sp
 488 or when at least 5 seconds passed since the last heap shot:
 489 .Sp
 490 \f[B]heapshot=5000ms\f[]
 491 .IP "\f[I]Compressing the data\f[]" 4
 492 .Sp
 493 To reduce the amout of disk space used by the data, the data can be
 494 compressed either after it has been generated with the gzip
 495 command:
 496 .Sp
 497 \f[B]gzip\ -9\ output.mlpd\f[]
 498 .Sp
 499 or it can be compressed automatically by using the \f[I]zip\f[]
 500 profiler option.
 501 Note that in this case there could be a significant slowdown of the
 502 profiled program.
 503 .Sp
 504 The mprof-report program will tranparently deal with either
 505 compressed or uncompressed data files.
 506 .IP "\f[I]Generating only a summary report\f[]" 4
 507 .Sp
 508 Often it's enough to look at the profiler summary report to
 509 diagnose an issue and in this case it's possible to avoid saving
 510 the profiler data file to disk.
 511 This can be accomplished with the \f[I]report\f[] profiler option,
 512 which will basically send the data to the mprof-report program for
 513 display.
 514 .Sp
 515 To have more control of what summary information is reported (or to
 516 use a completely different program to decode the profiler data),
 517 the \f[I]output\f[] profiler option can be used, with \f[B]|\f[] as
 518 the first character: the rest of the output name will be executed
 519 as a program with the data fed in on the standard input.
 520 .Sp
 521 For example, to print only the Monitor summary with stack trace
 522 information, you could use it like this:
 523 .Sp
 524 \f[B]output=|mprof-report\ --reports=monitor\ --traces\ -\f[]
 525 .SH WEB SITE
 526 http://www.mono-project.com/docs/debug+profile/profile/profiler/
 527 .SH SEE ALSO
 528 .PP
 529 mono(1)
 530 .SH AUTHORS
 531 Paolo Molaro, Alex Rønne Petersen