From 6790af558efad6467b9ec0fc40f7a2e43d437fc7 Mon Sep 17 00:00:00 2001 From: Ian Lynagh Date: Fri, 26 Sep 2008 20:02:03 +0000 Subject: [PATCH] Add some description of the +RTS -t/-s/-S output --- docs/users_guide/runtime_control.xml | 210 ++++++++++++++++++++++++++++++++++ 1 file changed, 210 insertions(+) diff --git a/docs/users_guide/runtime_control.xml b/docs/users_guide/runtime_control.xml index 725ee88..7cfc655 100644 --- a/docs/users_guide/runtime_control.xml +++ b/docs/users_guide/runtime_control.xml @@ -465,6 +465,216 @@ file. If file is omitted, then the output is sent to stderr. + + + If you use the -t flag then, when your + program finishes, you will see something like this: + + + +<<ghc: 36169392 bytes, 69 GCs, 603392/1065272 avg/max bytes residency (2 samples), 3M in use, 0.00 INIT (0.00 elapsed), 0.02 MUT (0.02 elapsed), 0.07 GC (0.07 elapsed) :ghc>> + + + + This tells you: + + + + + + The total bytes allocated by the program. This may be less + than the peak memory use, as some may be freed. + + + + + The total number of garbage collections that occurred. + + + + + The average and maximum space used by your program. + This is only checked during major garbage collections, so it + is only an approximation; the number of samples tells you how + many times it is checked. + + + + + The peak memory the RTS has allocated from the OS. + + + + + The amount of CPU time and elapsed wall clock time while + initialising the runtime system (INIT), running the program + itself (MUT, the mutator), and garbage collecting (GC). + + + + + + If you use the -s flag then, when your + program finishes, you will see something like this (the exact + details will vary depending on what sort of RTS you have, e.g. + you will only see profiling data if your RTS is compiled for + profiling): + + + + 36,169,392 bytes allocated in the heap + 4,057,632 bytes copied during GC + 1,065,272 bytes maximum residency (2 sample(s)) + 54,312 bytes maximum slop + 3 MB total memory in use (0 MB lost due to fragmentation) + + Generation 0: 67 collections, 0 parallel, 0.04s, 0.03s elapsed + Generation 1: 2 collections, 0 parallel, 0.03s, 0.04s elapsed + + INIT time 0.00s ( 0.00s elapsed) + MUT time 0.01s ( 0.02s elapsed) + GC time 0.07s ( 0.07s elapsed) + EXIT time 0.00s ( 0.00s elapsed) + Total time 0.08s ( 0.09s elapsed) + + %GC time 89.5% (75.3% elapsed) + + Alloc rate 4,520,608,923 bytes per MUT second + + Productivity 10.5% of total user, 9.1% of total elapsed + + + + + + The "bytes allocated in the heap" is the total bytes allocated + by the program. This may be less than the peak memory use, as + some may be freed. + + + + + GHC uses a copying garbage collector. "bytes copied during GC" + tells you how many bytes it had to copy during garbage collection. + + + + + The maximum space actually used by your program is the + "bytes maximum residency" figure. This is only checked during + major garbage collections, so it is only an approximation; + the number of samples tells you how many times it is checked. + + + + + The "bytes maximum slop" tells you the most space that is ever + wasted due to the way GHC packs data into so-called "megablocks". + + + + + The "total memory in use" tells you the peak memory the RTS has + allocated from the OS. + + + + + Next there is information about the garbage collections done. + For each generation it says how many garbage collections were + done, how many of those collections used multiple threads, + the total CPU time used for garbage collecting that generation, + and the total wall clock time elapsed while garbage collecting + that generation. + + + + + Next there is the CPU time and wall clock time elapsedm broken + down by what the runtiem system was doing at the time. + INIT is the runtime system initialisation. + MUT is the mutator time, i.e. the time spent actually running + your code. + GC is the time spent doing garbage collection. + RP is the time spent doing retainer profiling. + PROF is the time spent doing other profiling. + EXIT is the runtime system shutdown time. + And finally, Total is, of course, the total. + + + %GC time tells you what percentage GC is of Total. + "Alloc rate" tells you the "bytes allocated in the heap" divided + by the MUT CPU time. + "Productivity" tells you what percentage of the Total CPU and wall + clock elapsed times are spent in the mutator (MUT). + + + + + + The -S flag, as well as giving the same + output as the -s flag, prints information + about each GC as it happens: + + + + Alloc Copied Live GC GC TOT TOT Page Flts + bytes bytes bytes user elap user elap + 528496 47728 141512 0.01 0.02 0.02 0.02 0 0 (Gen: 1) +[...] + 524944 175944 1726384 0.00 0.00 0.08 0.11 0 0 (Gen: 0) + + + + For each garbage collection, we print: + + + + + + How many bytes we allocated this garbage collection. + + + + + How many bytes we copied this garbage collection. + + + + + How many bytes are currently live. + + + + + How long this garbage collection took (CPU time and elapsed + wall clock time). + + + + + How long the program has been running (CPU time and elapsed + wall clock time). + + + + + How many page faults occured this garbage collection. + + + + + How many page faults occured since the end of the last garbage + collection. + + + + + Which generation is being garbage collected. + + + + -- 1.7.10.4