summaryrefslogtreecommitdiff
path: root/rts/Ticky.c
blob: f82cd27104538f85209c615c69f3f682613fdca4 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
/* -----------------------------------------------------------------------------
 *
 * (c) The AQUA project, Glasgow University, 1992-1997
 * (c) The GHC Team, 1998-1999
 *
 * Ticky-ticky profiling
 *-------------------------------------------------------------------------- */

#define TICKY_C                 /* define those variables */
#include "rts/PosixSource.h"
#include "Rts.h"

#include "eventlog/EventLog.h"

/* Catch-all top-level counter struct.  Allocations from CAFs will go
 * here.
 */
StgEntCounter top_ct
        = { 0, 0, 0,
            "TOP", "", NULL,
            0, 0, NULL };

/* Data structure used in ``registering'' one of these counters. */

StgEntCounter *ticky_entry_ctrs = NULL; /* root of list of them */

/* We want Haskell code compiled with -ticky to be linkable with any
 * version of the RTS, so we have to make sure all the symbols that
 * ticky-compiled code may refer to are defined by every RTS. (#3439)
 * Hence the #if defined(is) here, rather than up above.
 */
#if defined(TICKY_TICKY)

#include "Ticky.h"

/* -----------------------------------------------------------------------------
   Print out all the counters
   -------------------------------------------------------------------------- */

static void printRegisteredCounterInfo (FILE *); /* fwd decl */

#define INTAVG(a,b) ((b == 0) ? 0.0 : ((double) (a) / (double) (b)))
#define PC(a)       (100.0 * a)

#define AVG(thing) \
        StgDouble avg##thing  = INTAVG(tot##thing,ctr##thing)

void
PrintTickyInfo(void)
{
  if (RtsFlags.TraceFlags.ticky) {
      barf("Ticky eventlog output can't be used with +RTS -r<file>");
  }

  unsigned long i;

  unsigned long tot_thk_enters = ENT_STATIC_THK_MANY_ctr + ENT_DYN_THK_MANY_ctr
                               + ENT_STATIC_THK_SINGLE_ctr + ENT_DYN_THK_SINGLE_ctr;
  unsigned long tot_con_enters = ENT_STATIC_CON_ctr + ENT_DYN_CON_ctr;

  unsigned long tot_fun_direct_enters = ENT_STATIC_FUN_DIRECT_ctr + ENT_DYN_FUN_DIRECT_ctr;
  unsigned long tot_ind_enters = ENT_STATIC_IND_ctr + ENT_DYN_IND_ctr;

  unsigned long tot_known_calls =
      KNOWN_CALL_ctr + KNOWN_CALL_TOO_FEW_ARGS_ctr +
      + KNOWN_CALL_EXTRA_ARGS_ctr;
  unsigned long tot_tail_calls =
      UNKNOWN_CALL_ctr + tot_known_calls;

  unsigned long tot_enters =
      tot_con_enters + tot_fun_direct_enters +
        tot_ind_enters + ENT_PERM_IND_ctr + ENT_PAP_ctr + tot_thk_enters;
  unsigned long jump_direct_enters =
        tot_enters - ENT_VIA_NODE_ctr;


  unsigned long tot_returns =
      RET_NEW_ctr + RET_OLD_ctr + RET_UNBOXED_TUP_ctr;

  unsigned long tot_returns_of_new = RET_NEW_ctr;

  unsigned long con_updates = UPD_CON_IN_NEW_ctr + UPD_CON_IN_PLACE_ctr;
  unsigned long pap_updates = UPD_PAP_IN_NEW_ctr + UPD_PAP_IN_PLACE_ctr;

  unsigned long tot_updates = UPD_SQUEEZED_ctr + pap_updates + con_updates;

  unsigned long tot_new_updates   = UPD_NEW_IND_ctr + UPD_NEW_PERM_IND_ctr;
  unsigned long tot_old_updates   = UPD_OLD_IND_ctr + UPD_OLD_PERM_IND_ctr;
  unsigned long tot_gengc_updates = tot_new_updates + tot_old_updates;

  // Number of times tag inference predicted tagged/untagged correctly
  // allowing us to skip a tag check (when ticky is disabled)
  unsigned long tot_tag_preds = TAG_UNTAGGED_pred + TAG_TAGGED_pred;

  FILE *tf = RtsFlags.TickyFlags.tickyFile;

  /* If tf = NULL, that means the user passed in stderr for the ticky stats
     file. According to a comment in RtsFlags.c, this means to use
     debugBelch to print out messages. But this function prints out a lot
     of stuff so in order to avoid changing a lot of code, we just dump
     the same output to stderr (for now). */
  if( tf == NULL )
    tf = stderr;

  fprintf(tf,"\nSTACK USAGE:\n"); /* NB: some bits are direction sensitive */


  fprintf(tf,"\nENTERS: %lu  of which %lu (%.1f%%) direct to the entry code\n\t\t  [the rest indirected via Node's info ptr]\n",
        tot_enters,
        jump_direct_enters,
        PC(INTAVG(jump_direct_enters,tot_enters)));
  fprintf(tf,"%11lu (%5.1f%%) thunks\n",
        tot_thk_enters,
        PC(INTAVG(tot_thk_enters,tot_enters)));
  fprintf(tf, "%11lu (%5.1f%%) data values\n",
        tot_con_enters,
        PC(INTAVG(tot_con_enters,tot_enters)));
  fprintf(tf, "%11lu (%5.1f%%) normal indirections\n",
        tot_ind_enters,
        PC(INTAVG(tot_ind_enters,tot_enters)));
  fprintf(tf,"%11" FMT_Int " (%5.1f%%) permanent indirections\n",
        ENT_PERM_IND_ctr,
        PC(INTAVG(ENT_PERM_IND_ctr,tot_enters)));


  fprintf(tf, "\nFUNCTION ENTRIES: %lu\n", tot_fun_direct_enters);

  fprintf(tf, "\nTAIL CALLS: %lu, of which %lu (%.lf%%) were to known functions\n",
          tot_tail_calls, tot_known_calls,
          PC(INTAVG(tot_known_calls,tot_tail_calls)));

  fprintf(tf, "\nSLOW APPLICATIONS: %" FMT_Int " evaluated, %" FMT_Int " unevaluated\n",
          SLOW_CALL_ctr, SLOW_CALL_UNEVALD_ctr);
  fprintf(tf, "\n");
  fprintf(tf, "         Too few args   Correct args   Too many args\n");
  fprintf(tf, "   FUN     %8" FMT_Int "       %8" FMT_Int "        %8" FMT_Int "\n",
          SLOW_CALL_FUN_TOO_FEW_ctr, SLOW_CALL_FUN_CORRECT_ctr, SLOW_CALL_FUN_TOO_MANY_ctr);
  fprintf(tf, "   PAP     %8" FMT_Int "       %8" FMT_Int "        %8" FMT_Int "\n",
          SLOW_CALL_PAP_TOO_FEW_ctr, SLOW_CALL_PAP_CORRECT_ctr, SLOW_CALL_PAP_TOO_MANY_ctr);
  fprintf(tf, "\n");

  fprintf(tf, "\nRETURNS: %lu\n", tot_returns);
  fprintf(tf, "%11lu (%5.1f%%) from entering a new constructor\n\t\t  [the rest from entering an existing constructor]\n",
        tot_returns_of_new,
        PC(INTAVG(tot_returns_of_new,tot_returns)));


  fprintf(tf, "\nRET_NEW:         %11" FMT_Int ": ", RET_NEW_ctr);
  for (i = 0; i < TICKY_BIN_COUNT; i++) {
    fprintf(tf, "%5.1f%%", PC(INTAVG(RET_NEW_hst[i], RET_NEW_ctr)));
  }
  fprintf(tf, "\n");

  fprintf(tf, "RET_OLD:         %11" FMT_Int ": ", RET_OLD_ctr);
  for (i = 0; i < TICKY_BIN_COUNT; i++) {
    fprintf(tf, "%5.1f%%", PC(INTAVG(RET_OLD_hst[i], RET_OLD_ctr)));
  }
  fprintf(tf, "\n");

  fprintf(tf, "RET_UNBOXED_TUP: %11" FMT_Int ": ", RET_UNBOXED_TUP_ctr);
  for (i = 0; i < TICKY_BIN_COUNT; i++) {
    fprintf(tf, "%5.1f%%", PC(INTAVG(RET_UNBOXED_TUP_hst[i],
                           RET_UNBOXED_TUP_ctr)));
  }
  fprintf(tf, "\n");

  fprintf(tf,"\nUPDATE FRAMES: %" FMT_Int " (%" FMT_Int " omitted from thunks)",
        UPDF_PUSHED_ctr,
        UPDF_OMITTED_ctr);

  fprintf(tf,"\nCATCH FRAMES:  %" FMT_Int "", CATCHF_PUSHED_ctr);

  if (UPDF_RCC_PUSHED_ctr != 0) {
     fprintf(tf,"%11" FMT_Int " restore cost centre frames (%" FMT_Int " omitted)\n",
        UPDF_RCC_PUSHED_ctr,
        UPDF_RCC_OMITTED_ctr);
  }

  fprintf(tf,"\nUPDATES: %ld\n", tot_updates);
  fprintf(tf, "%11lu (%5.1f%%) data values\n\t\t  [%" FMT_Int " in place, %" FMT_Int " allocated new space]\n",
        con_updates,
        PC(INTAVG(con_updates,tot_updates)),
        UPD_CON_IN_PLACE_ctr, UPD_CON_IN_NEW_ctr);

  fprintf(tf, "%11lu (%5.1f%%) partial applications\n\t\t  [%" FMT_Int " in place, %" FMT_Int " allocated new space]\n",
        pap_updates,
        PC(INTAVG(pap_updates,tot_updates)),
        UPD_PAP_IN_PLACE_ctr, UPD_PAP_IN_NEW_ctr);

  fprintf(tf,"%11" FMT_Int " (%5.1f%%) updates by squeezing\n",
        UPD_SQUEEZED_ctr,
        PC(INTAVG(UPD_SQUEEZED_ctr, tot_updates)));

  if (tot_gengc_updates != 0) {
      fprintf(tf, "\nNEW GEN UPDATES: %9lu (%5.1f%%)\n",
              tot_new_updates,
              PC(INTAVG(tot_new_updates,tot_gengc_updates)));
      fprintf(tf, "OLD GEN UPDATES: %9lu (%5.1f%%)\n",
              tot_old_updates,
              PC(INTAVG(tot_old_updates,tot_gengc_updates)));
  }

  if (tot_tag_preds != 0) {
      fprintf(tf, "\nTOTAL TAG PREDICTIONS MADE: %9" FMT_Word64 " \n",
              (StgWord64) tot_tag_preds);
      fprintf(tf, "TAGGED PREDICTIONS HIT:     %9" FMT_Word64 " \n",
              (StgWord64) TAG_TAGGED_pred);
      fprintf(tf, "UNTAGGED PREDICTIONS HIT:   %9" FMT_Word64 " \n",
              (StgWord64) (TAG_UNTAGGED_pred - TAG_UNTAGGED_miss));
      fprintf(tf, "UNTAGGED PREDICTIONS MISS:  %9" FMT_Word64 " \n",
              (StgWord64) TAG_UNTAGGED_miss);
  }

  printRegisteredCounterInfo(tf);

  fprintf(tf,"\n**************************************************\n");

  /* here, we print out all the raw numbers; these are really
    more useful when we want to snag them for subsequent
    rdb-etc processing. WDP 95/11
  */

#define PR_CTR(ctr) \
  do { fprintf(tf,"%11" FMT_Int " " #ctr "\n", ctr); } while(0)

/* COND_PR_CTR takes a boolean; if false then msg is the printname rather than ctr */
#define COND_PR_CTR(ctr,b,msg) \
    if (b) { fprintf(tf,"%11" FMT_Int " " #ctr "\n", ctr); } else { fprintf(tf,"%11" FMT_Int " " msg "\n", ctr); }

#define PR_HST(hst,i) \
  do { fprintf(tf,"%11" FMT_Int " " #hst "_" #i "\n", hst[i]); } while(0)

  ALLOC_HEAP_ctr = (StgInt)ALLOC_HEAP_ctr + (StgInt)ALLOC_RTS_ctr;
  ALLOC_HEAP_tot = (StgInt)ALLOC_HEAP_tot + (StgInt)ALLOC_RTS_tot;

  PR_CTR(ALLOC_HEAP_ctr);
  PR_CTR(ALLOC_HEAP_tot);

  PR_CTR(HEAP_CHK_ctr);
  PR_CTR(STK_CHK_ctr);

  PR_CTR(ALLOC_RTS_ctr);
  PR_CTR(ALLOC_RTS_tot);

  PR_CTR(ALLOC_FUN_ctr);
  PR_CTR(ALLOC_FUN_gds);

  PR_CTR(ALLOC_PAP_ctr);
  PR_CTR(ALLOC_PAP_adm);
  PR_CTR(ALLOC_PAP_gds);

  PR_CTR(ALLOC_UP_THK_ctr);
  PR_CTR(ALLOC_SE_THK_ctr);
  PR_CTR(ALLOC_THK_gds);

  PR_CTR(ALLOC_CON_ctr);
  PR_CTR(ALLOC_CON_gds);

  PR_CTR(ALLOC_PRIM_ctr);
  PR_CTR(ALLOC_PRIM_gds);
  PR_CTR(ALLOC_PRIM_slp);

  PR_CTR(ENT_VIA_NODE_ctr);
  PR_CTR(ENT_STATIC_CON_ctr);
  PR_CTR(ENT_DYN_CON_ctr);
  PR_CTR(ENT_STATIC_FUN_DIRECT_ctr);
  PR_CTR(ENT_DYN_FUN_DIRECT_ctr);
  PR_CTR(ENT_LNE_ctr);
  PR_CTR(ENT_STATIC_IND_ctr);
  PR_CTR(ENT_DYN_IND_ctr);

/* The counters ENT_PERM_IND and UPD_{NEW,OLD}_PERM_IND are not dumped
 * at the end of execution unless update squeezing is turned off (+RTS
 * -Z =RtsFlags.GcFlags.squeezeUpdFrames), as they will be wrong
 * otherwise.  Why?  Because for each update frame squeezed out, we
 * count an UPD_NEW_PERM_IND *at GC time* (i.e., too early).  And
 * further, when we enter the closure that has been updated, we count
 * the ENT_PERM_IND, but we then enter the PERM_IND that was built for
 * the next update frame below, and so on down the chain until we
 * finally reach the value.  Thus we count many new ENT_PERM_INDs too
 * early.
 *
 * This of course refers to the -ticky version that uses PERM_INDs to
 * determine the number of closures entered 0/1/>1.  KSW 1999-04.  */
  COND_PR_CTR(ENT_PERM_IND_ctr,RtsFlags.GcFlags.squeezeUpdFrames == false,"ENT_PERM_IND_ctr requires +RTS -Z");

  PR_CTR(ENT_AP_ctr);
  PR_CTR(ENT_PAP_ctr);
  PR_CTR(ENT_AP_STACK_ctr);
  PR_CTR(ENT_BH_ctr);
  PR_CTR(ENT_STATIC_THK_SINGLE_ctr);
  PR_CTR(ENT_STATIC_THK_MANY_ctr);
  PR_CTR(ENT_DYN_THK_SINGLE_ctr);
  PR_CTR(ENT_DYN_THK_MANY_ctr);
  PR_CTR(UPD_CAF_BH_UPDATABLE_ctr);
  PR_CTR(UPD_CAF_BH_SINGLE_ENTRY_ctr);

  PR_CTR(SLOW_CALL_fast_v16_ctr);
  PR_CTR(SLOW_CALL_fast_v_ctr);
  PR_CTR(SLOW_CALL_fast_f_ctr);
  PR_CTR(SLOW_CALL_fast_d_ctr);
  PR_CTR(SLOW_CALL_fast_l_ctr);
  PR_CTR(SLOW_CALL_fast_n_ctr);
  PR_CTR(SLOW_CALL_fast_p_ctr);
  PR_CTR(SLOW_CALL_fast_pv_ctr);
  PR_CTR(SLOW_CALL_fast_pp_ctr);
  PR_CTR(SLOW_CALL_fast_ppv_ctr);
  PR_CTR(SLOW_CALL_fast_ppp_ctr);
  PR_CTR(SLOW_CALL_fast_pppv_ctr);
  PR_CTR(SLOW_CALL_fast_pppp_ctr);
  PR_CTR(SLOW_CALL_fast_ppppp_ctr);
  PR_CTR(SLOW_CALL_fast_pppppp_ctr);
  PR_CTR(VERY_SLOW_CALL_ctr);

  PR_CTR(UNKNOWN_CALL_ctr);
  PR_CTR(KNOWN_CALL_ctr);
  PR_CTR(KNOWN_CALL_TOO_FEW_ARGS_ctr);
  PR_CTR(KNOWN_CALL_EXTRA_ARGS_ctr);
  PR_CTR(MULTI_CHUNK_SLOW_CALL_ctr);
  PR_CTR(MULTI_CHUNK_SLOW_CALL_CHUNKS_ctr);
  PR_CTR(SLOW_CALL_ctr);
  PR_CTR(SLOW_CALL_FUN_TOO_FEW_ctr);
  PR_CTR(SLOW_CALL_FUN_CORRECT_ctr);
  PR_CTR(SLOW_CALL_FUN_TOO_MANY_ctr);
  PR_CTR(SLOW_CALL_PAP_TOO_FEW_ctr);
  PR_CTR(SLOW_CALL_PAP_CORRECT_ctr);
  PR_CTR(SLOW_CALL_PAP_TOO_MANY_ctr);
  PR_CTR(SLOW_CALL_UNEVALD_ctr);

  PR_CTR(RET_NEW_ctr);
  PR_CTR(RET_OLD_ctr);
  PR_CTR(RET_UNBOXED_TUP_ctr);

#define PR_HST_BINS(hst) for (i = 0; i < TICKY_BIN_COUNT; i++) \
  { fprintf(tf,"%11" FMT_Int " " #hst "_%lu\n", hst[i], i); }

  PR_HST_BINS(RET_NEW_hst);
  PR_HST_BINS(RET_OLD_hst);
  PR_HST_BINS(RET_UNBOXED_TUP_hst);

#undef PR_HST_BINS

  PR_CTR(UPDF_OMITTED_ctr);
  PR_CTR(UPDF_PUSHED_ctr);
  PR_CTR(CATCHF_PUSHED_ctr);

  PR_CTR(UPDF_RCC_PUSHED_ctr);
  PR_CTR(UPDF_RCC_OMITTED_ctr);

  PR_CTR(UPD_SQUEEZED_ctr);
  PR_CTR(UPD_CON_IN_NEW_ctr);
  PR_CTR(UPD_CON_IN_PLACE_ctr);
  PR_CTR(UPD_PAP_IN_NEW_ctr);
  PR_CTR(UPD_PAP_IN_PLACE_ctr);

  PR_CTR(UPD_NEW_IND_ctr);
  /* see comment on ENT_PERM_IND_ctr */
  COND_PR_CTR(UPD_NEW_PERM_IND_ctr,RtsFlags.GcFlags.squeezeUpdFrames == false,"UPD_NEW_PERM_IND_ctr requires +RTS -Z");
  PR_CTR(UPD_OLD_IND_ctr);
  /* see comment on ENT_PERM_IND_ctr */
  COND_PR_CTR(UPD_OLD_PERM_IND_ctr,RtsFlags.GcFlags.squeezeUpdFrames == false,"UPD_OLD_PERM_IND_ctr requires +RTS -Z");

  PR_CTR(GC_SEL_ABANDONED_ctr);
  PR_CTR(GC_SEL_MINOR_ctr);
  PR_CTR(GC_SEL_MAJOR_ctr);
  PR_CTR(GC_FAILED_PROMOTION_ctr);
}

/* To print out all the registered-counter info: */

static void
printRegisteredCounterInfo (FILE *tf)
{
    StgEntCounter *p;

    if ( ticky_entry_ctrs != NULL ) {
      fprintf(tf,"\nThe following table is explained by https://gitlab.haskell.org/ghc/ghc/wikis/debugging/ticky-ticky\nAll allocation numbers are in bytes.\n");
      fprintf(tf,"\n**************************************************\n\n");
    }
    fprintf(tf, "%11s%12s%12s  %-63s %s\n",
            "Entries", "Alloc", "Alloc'd", "Non-void Arguments", "STG Name");
    fprintf(tf, "--------------------------------------------------------------------------------\n");
    /* Function name at the end so it doesn't mess up the tabulation */

    for (p = ticky_entry_ctrs; p != NULL; p = p->link) {
        fprintf(tf, "%11" FMT_Int "%12" FMT_Int "%12" FMT_Int " %3lu %-60.60s %s",
                p->entry_count,
                p->allocs,
                p->allocd,
                (unsigned long)p->arity,
                p->arg_kinds,
                p->str);

        fprintf(tf, "\n");

    }
}

void emitTickyCounterDefs()
{
#if defined(TRACING)
    postTickyCounterDefs(ticky_entry_ctrs);
#endif
}

void emitTickyCounterSamples()
{
#if defined(TRACING)
    postTickyCounterSamples(ticky_entry_ctrs);
#endif
}

#endif /* TICKY_TICKY */