Changes between Version 7 and Version 8 of Debugging/TickyTicky


Ignore:
Timestamp:
Mar 29, 2013 3:28:47 PM (13 months ago)
Author:
nfrisby
Comment:

--

Legend:

Unmodified
Added
Removed
Modified
  • Debugging/TickyTicky

    v7 v8  
     1[[PageOutline]] 
    12 
     3TODO document each active counter, especially regarding its accuracy. 
    24 
    3 = Ticky-ticky profiling = 
     5== Basic Idea and Quickstart Guide == 
    46 
    57Ticky-ticky profiling adds counters to every STG function.  It's very low-level, but it really tells you what is going on: 
    68 
    7  * Add the `-ticky` flag when compiling a Haskell module to enable "ticky-ticky" profiling of that module.  This makes GHC emit performance-counting instructions in every STG function.   
     9 * Add the `-ticky` flag when compiling a Haskell module to enable "ticky-ticky" profiling of that module.  This makes GHC emit performance-counting instructions in every STG function. 
    810 
    911 * Add `-ticky` to the command line when linking, so that you link against a version of the runtime system that allows you to display the results.  In fact, in the link phase `-ticky` implies `-debug`, so you get the debug version of the runtime system too. 
     
    1113 * Add `+RTS -rfoo.ticky` to the run-time command line, to put the ticky-ticky profile in the file `foo.ticky`. 
    1214 
    13 You need to use `-ddump-simpl -ddump-prep` when compiling the source files to see the functions that correspond to the performance counter report. 
     15You need to use `-ddump-prep` or `-ddump-stg` when compiling the source files to see the functions that correspond to the performance counter report. 
    1416 
    1517It's very low level stuff, but in exchange: 
    16   * It's guaranteed that adding `-ticky` doesn't affect optimisation or transformation.  It just adds the overhead of performance counters to the final code. 
     18  * It's guaranteed that adding `-ticky` doesn't affect optimisation or transformation.  It just adds the overhead of performance counters to the final code. (Any change these affect the CMM optimisations?) 
    1719 
    1820  * You can mix modules compiled with `-ticky` and modules compiled without. 
    1921 
    2022To ''really'' see everything you need to compile all the libraries with `-ticky`.  To do that in a standard build tree, here are some flag settings in `build.mk` that work: 
     23 
    2124{{{ 
    2225# Build all libraries with -ticky 
    2326GhcLibHcOpts += -ticky 
    2427 
    25 # Build the RTS in the ticky way 
    26 GhcRTSWays += t 
    27  
    2828# Currently ticky is incompatible with threading 
    2929GhcThreaded = NO 
    3030}}} 
     31 
     32== Ticky-ticky overview == 
     33 
     34It is possible to compile Haskell programs so that they will count several kinds of interesting things, e.g., number of updates, number of data constructors entered, etc.  We call this "ticky-ticky" profiling because that's the sound a CPU makes when it is running up all those counters (''slowly''). 
     35 
     36Ticky-ticky profiling is mainly intended for implementors; it is quite separate from the main "cost-centre" profiling system, intended for all users everywhere. 
     37 
     38You don't need to build GHC, the libraries, or the RTS a special way in order to use ticky-ticky profiling.  You can decide on a module-by-module basis which parts of a program have the counters compiled in, using the compile-time `-ticky` option.  Those modules that were not compiled with `-ticky` won't contribute to the ticky-ticky profiling results. That will normally include all the pre-compiled packages that your program links with. 
     39 
     40There are currently two coarse classes of ticky-ticky counters: name-specific counters and global counters. 
     41 
     42  * name-specific counters 
     43 
     44    Each "name-specific counter" is associated with a name that is defined in the result of !CorePrep. For each such name, there are three possible counters: entries, heap allocation by the named thing, and heap used to allocate that named thing. 
     45 
     46  * global counters 
     47 
     48    Each "global counter" describes some aspect of the entire program execution. For example, one global counter tracks total heap allocation; another tracks allocation for PAPs. 
     49 
     50== Enabling ticky-ticky and its extension flags == 
     51 
     52Ticky-ticky counters are enabled in two ways. 
     53 
     54  * A module compiled with `-ticky` will maintain name-specific counters for the names defined in that module's !CorePrep output. 
     55 
     56  * A program linked with the `-debug` RTS will include the RTS's effect on the global ticky-ticky counters. At link-time, `-ticky` implies `-debug`. 
     57 
     58Some global counters are synthetized from multiple other counters, including both name-specific as well as other global counters. For example, the `ALLOC_HEAP_tot` counter accumulates the total of all heap allocations that were tracked by ticky-ticky; it is influenced both by the name-specific counters for allocation as well as by the global counters for heap allocation by the RTS. 
     59 
     60''By default'', the name-specific counters are only tracked for functions. In particular, both let-no-escape (LNE) names and thunks are not tracked. Allocation by each is included in the nearest lexically enclosing ticky counter. Entries in to each are not tracked at all. 
     61 
     62Two flags enable LNE and dynamically allocated thunks to be tracked by name-specific ticky counters: `-ticky-LNE` and `-ticky-dyn-thunk`. Note well that these flags, especially for dynamic thunks, incur much higher instrumentation overhead and much larger ticky reports. 
     63 
     64''By default'', the name-specific counters track only entries-into and allocation-by the named thing. A flag `-ticky-allocd` additionally tracks the heap used to allocate that thing. Again, this flag increases the instrumentation overhead. 
     65 
     66== Generating the ticky report == 
     67 
     68Any GHC executable linked with `-rtsopts` will generate a ticky-ticky profiling report if provided the `-r` RTS option. This report includes all global counters as well as the name-specific counters for those names with at least one interesting counter value. If a named thing was never allocated and (hence) never entered, its counters will not be in the ticky report. 
     69 
     70Below is an excerpt from a ticky report. The executable was compiled with all of the extensions above. 
     71 
     72The first three columns show the three name-specific counters: entries, allocation-by, and allocation-of. The fourth column gives a short summary of the named things's non-void arguments: how many there are and a terse description of each, according to the following table. 
     73 
     74|| Classification || Description || 
     75|| `+` || dictionary || 
     76|| `>` || function || 
     77|| `{C,I,F,D,W}` ||  char, int, float, double, word || 
     78|| `{c,i,f,d,w}` || unboxed ditto || 
     79|| `T` || tuple || 
     80|| `P` || other primitive type || 
     81|| `p` || unboxed ditto || 
     82|| `L` || list || 
     83|| `E` || enumeration type || 
     84|| `S` || other single-constructor type || 
     85|| `M` || other multi-constructor data-con type || 
     86|| `.` || other type || 
     87|| `-` || reserved for others to mark as "uninteresting" || 
     88 
     89The final column is the !CorePrep/STG name to which the counters in this row refer. Each entry in this column uses an encoding that differentiations between exported names (`main:Main.puzzle`) and non-exported names (`go1{v r2Hj} (main:Main)`). Some non-exported names indicate that they are let-no-escape (`(LNE)`) or a dynamically allocated thunk (`(thk)`). All let-bound names also specify the unique of the parent (`in s2T4`). The "parent", here, is the innermost enclosing definition that has a ticky counter; the parent is affected by `-ticky-LNE` and `-ticky-dyn-thunk`). 
     90 
     91{{{ 
     92$ ghc ... -ticky -ticky-LNE -ticky-dyn-thunk -ticky-allocd ... -o foo 
     93$ ./foo +RTS -rticky -RTS 
     94$ cat ticky # I'm just showing an excerpt 
     95... 
     96    Entries      Alloc    Alloc'd  Non-void Arguments      STG Name 
     97-------------------------------------------------------------------------------- 
     98         10        240        240   0                      sat_s2T2{v} (main:Main) (thk) in s2T4 
     99         10        240        240   0                      sat_s2T4{v} (main:Main) (thk) in r2Hj 
     100         10          0        240   0                      sat_s4eb{v} (main:Main) (thk) in r2Hj 
     101         11        960          0   1 L                    go1{v r2Hj} (main:Main) 
     102          6         96        192   0                      sat_s4hz{v} (main:Main) (thk) in s2Ua 
     103          7        528         16   1 L                    go3{v s2Ua} (main:Main) in rj2 
     104         49          0         16   2 iL                   $wlgo{v s2TW} (main:Main) in rj2 
     105          0          0         24   0                      sat_s4ck{v} (main:Main) (thk) in r2Hi 
     106          1         48          0   1 L                    go{v r2Hi} (main:Main) 
     107          1         48          0   1 S                    a{v r2H9} (main:Main) 
     108       1070      11264      17232   1 L                    go5{v s2Sg} (main:Main) in s2Sm 
     109        718      17232      28920   0                      sat_s2Sm{v} (main:Main) (thk) in s2Pf 
     110       8465      78688     144168   1 L                    go5{v s2RO} (main:Main) in s2RV 
     111       6007     144168     240280   0                      sat_s2RV{v} (main:Main) (thk) in s2Pf 
     112       1035      33120     269200   3 TSL                  $sgo1{v s2R0} (main:Main) in s2Pf 
     113       1029          0     215360   1 L                    go4{v s2QX} (main:Main) in s2Pf 
     114       1035      16560     161520   0                      a2{v s2QO} (main:Main) (thk) in s2Pf 
     115       6730     107680     215360   0                      sat_s2Ov{v} (main:Main) (thk) in s2Oy 
     116      77223    4199520     590064   1 L                    go3{v s2NH} (main:Main) in s2NP 
     117      12644    1011520     303456   3 TSL                  $sgo1{v s2JG} (main:Main) in s2K4 
     118      12634          0     202304   1 L                    go4{v s2JD} (main:Main) in s2K4 
     119       4130      99120     404608   0                      sat_s2Kt{v} (main:Main) (thk) in s2Kw 
     120      16765    1416128      66096   1 L                    go5{v s2Kw} (main:Main) in s2KG 
     121      16765    1011520      66096   1 L                    go4{v s2Kg} (main:Main) in s2KG 
     122      16765    1820736      99144   1 L                    go3{v s2K4} (main:Main) in s2KG 
     123       4131     363528          0   3 SSL                  $sgo{v s2KG} (main:Main) (LNE) in r2H6 
     124       4121          0      66096   1 L                    go2{v s2KE} (main:Main) in r2H6 
     125       4131      66096          0   2 CS                   main:Main.permute1{v r2H6} 
     126      37907    2834272          0   3 SSL                  $sgo{v s2MG} (main:Main) (LNE) in r2H7 
     127      37865          0     606512   1 L                    go2{v s2MA} (main:Main) in r2H7 
     128      37907     606512          0   2 CS                   main:Main.select1{v r2H7} 
     129      68020    1770192     498832   1 L                    go2{v s2NP} (main:Main) in r2Ha 
     130      37907     821872          0   2 LS                   a1{v r2Ha} (main:Main) 
     131       7752    1130640      32896   1 L                    go3{v s2Pf} (main:Main) in r2H8 
     132        453          0      24672   0                      lvl7{v s2OF} (main:Main) (thk) in r2H8 
     133       7752     753760      16448   1 L                    go2{v s2Oy} (main:Main) in r2H8 
     134       1036      74016          0   4 LLIS                 main:Main.solve1{v r2H8} 
     135          1          0         24   0                      sat_s4hu{v} (main:Main) (thk) in rj2 
     136          7        192         16   1 L                    go2{v s2Tj} (main:Main) in rj2 
     137          1         72          0   2 LL                   main:Main.puzzle{v rj2} 
     138          1          0          0   0                      main:Main.main1{v r2GU} 
     139          1          0          0   0                      main:Main.main12{v r2H5} 
     140          1          0          0   0                      main::Main.main{v 01C} 
     141 
     142************************************************** 
     143     293586 ALLOC_HEAP_ctr 
     144   18391320 ALLOC_HEAP_tot 
     145         26 ALLOC_RTS_ctr 
     146        672 ALLOC_RTS_tot 
     147     170019 ALLOC_FUN_ctr 
     148    3193952 ALLOC_FUN_gds 
     149... 
     150}}} 
     151 
     152The formatting of the information above the row of asterisks is subject to change, but hopefully provides a useful human-readable summary.  Below the asterisks ''all counters'' maintained by the ticky-ticky system are dumped, in a format intended to be machine-readable: zero or more spaces, an integer, a space, the counter name, and a newline. 
     153 
     154In fact, not ''all'' counters are necessarily dumped; compile- or run-time flags can render certain counters invalid.  In this case, either the counter will simply not appear, or it will appear with a modified counter name, possibly along with an explanation for the omission. Software analysing this output should always check that it has the counters it expects.  Also, beware: some of the counters can have very large values. 
     155 
     156== History == 
     157 
     158Ticky has been around a long time, and its glory days seem to have 
     159passed: there are several bitrotted counters, now totally inactive or 
     160at least of dubious accuracy. 
     161 
     162As of March 2013, nfrisby added the extension flags and resurrected 
     163some global counters (including those in the RTS, esp the slow call 
     164counters), and standardized the enabled allocation counters on bytes. 
     165 
     166Prior history: 
     167 
     168  * tickets: #607 #2455 #3439 
     169 
     170  * there used to be a `t` "way", but it was folded into `debug` 
     171 
     172  * Tim's notes [wiki:Commentary/Profiling/TickyNotes] [wiki:Commentary/Compiler/StrictnessAnalysis/KirstenNotes] 
     173 
     174If some of the counters are zero when they shouldn't be, that means they're not implemented yet. If you want them to be, complain on a mailing list. 
     175 
     176== Implementation notes == 
     177 
     178When compiling with {{{-ticky}}}, the back-end emits the name-specific counters in the data section and generates instructions that tick them directly. 
     179 
     180The global counters are ''always'' statically allocated by the RTS [[GhcFile(includes/stg/Ticky.h)]] regardless of the compilation way. 
     181 
     182Some `TICK_...` C-- macros are sprinkled throughout the RTS. In the debug way (cf `ways.mk`) `TICKY_TICKY` is `defined`, so these macros expand to code that ticks the counters. The relevant compiler code is mostly in [[GhcFile(compiler/codeGen/StgCmmTicky.hs)]]. NB that some of these macros are expanded by [[GhcFile(compiler/cmm/CmmParse.y)]]! 
     183 
     184The C-- macros are defined in [[GhcFile(includes/Cmm.h)]]. Most of them (probably all of them, at the moment) just increment counters (variables in C) that are declared in [[GhcFile(includes/stg/Ticky.h)]]. The latter file is likely to get out of sync with the former, so it really should be automatically generated. 
     185 
     186The code in the RTS that prints out the ticky report is in [[GhcFile(rts/Ticky.c)]].