Profiling.c 32.5 KB
Newer Older
1 2
/* -----------------------------------------------------------------------------
 *
3
 * (c) The GHC Team, 1998-2000
4 5 6 7 8 9 10
 *
 * Support for profiling
 *
 * ---------------------------------------------------------------------------*/

#ifdef PROFILING

11
#include "PosixSource.h"
12
#include "Rts.h"
Simon Marlow's avatar
Simon Marlow committed
13

14
#include "RtsUtils.h"
15
#include "Profiling.h"
16
#include "Proftimer.h"
17
#include "ProfHeap.h"
18
#include "Arena.h"
19
#include "RetainerProfile.h"
20
#include "Printer.h"
21
#include "Capability.h"
22

23 24
#include <string.h>

25 26 27 28
#ifdef DEBUG
#include "Trace.h"
#endif

29 30 31 32
/*
 * Profiling allocation arena.
 */
Arena *prof_arena;
33 34 35 36 37 38

/*
 * Global variables used to assign unique IDs to cc's, ccs's, and 
 * closure_cats
 */

39 40
unsigned int CC_ID  = 1;
unsigned int CCS_ID = 1;
41 42 43

/* figures for the profiling report.
 */
Ian Lynagh's avatar
Ian Lynagh committed
44
static StgWord64 total_alloc;
45
static W_      total_prof_ticks;
46

47
/* Globals for opening the profiling log file(s)
48 49
 */
static char *prof_filename; /* prof report file name = <program>.prof */
50
FILE *prof_file;
51

52 53 54
static char *hp_filename;	/* heap profile (hp2ps style) log file */
FILE *hp_file;

55
/* Linked lists to keep track of CCs and CCSs that haven't
56 57
 * been declared in the log file yet
 */
58 59
CostCentre      *CC_LIST  = NULL;
CostCentreStack *CCS_LIST = NULL;
60

61 62 63 64
#ifdef THREADED_RTS
Mutex ccs_mutex;
#endif

65 66 67 68
/*
 * Built-in cost centres and cost-centre stacks:
 *
 *    MAIN   is the root of the cost-centre stack tree.  If there are
69
 *           no {-# SCC #-}s in the program, all costs will be attributed
70 71 72 73 74 75 76 77 78 79 80 81 82 83
 *           to MAIN.
 *
 *    SYSTEM is the RTS in general (scheduler, etc.).  All costs for
 *           RTS operations apart from garbage collection are attributed
 *           to SYSTEM.
 *
 *    GC     is the storage manager / garbage collector.
 *
 *    OVERHEAD gets all costs generated by the profiling system
 *           itself.  These are costs that would not be incurred
 *           during non-profiled execution of the program.
 *
 *    DONT_CARE is a placeholder cost-centre we assign to static
 *           constructors.  It should *never* accumulate any costs.
84 85 86 87
 *
 *    PINNED accumulates memory allocated to pinned objects, which
 *           cannot be profiled separately because we cannot reliably
 *           traverse pinned memory.
88 89
 */

90 91 92 93 94 95 96
CC_DECLARE(CC_MAIN,      "MAIN",        "MAIN",      "<built-in>", CC_NOT_CAF, );
CC_DECLARE(CC_SYSTEM,    "SYSTEM",      "SYSTEM",    "<built-in>", CC_NOT_CAF, );
CC_DECLARE(CC_GC,        "GC",          "GC",        "<built-in>", CC_NOT_CAF, );
CC_DECLARE(CC_OVERHEAD,  "OVERHEAD_of", "PROFILING", "<built-in>", CC_NOT_CAF, );
CC_DECLARE(CC_DONT_CARE, "DONT_CARE",   "MAIN",      "<built-in>", CC_NOT_CAF, );
CC_DECLARE(CC_PINNED,    "PINNED",      "SYSTEM",    "<built-in>", CC_NOT_CAF, );
CC_DECLARE(CC_IDLE,      "IDLE",        "IDLE",      "<built-in>", CC_NOT_CAF, );
97

98 99 100 101
CCS_DECLARE(CCS_MAIN, 	    CC_MAIN,       );
CCS_DECLARE(CCS_SYSTEM,	    CC_SYSTEM,     );
CCS_DECLARE(CCS_GC,         CC_GC,         );
CCS_DECLARE(CCS_OVERHEAD,   CC_OVERHEAD,   );
102 103
CCS_DECLARE(CCS_DONT_CARE,  CC_DONT_CARE,  );
CCS_DECLARE(CCS_PINNED,     CC_PINNED,     );
104
CCS_DECLARE(CCS_IDLE,       CC_IDLE,       );
105

106
/*
107 108 109
 * Static Functions
 */

110 111 112 113 114 115 116 117 118 119 120 121 122 123 124
static  CostCentreStack * appendCCS       ( CostCentreStack *ccs1,
                                            CostCentreStack *ccs2 );
static  CostCentreStack * actualPush_     ( CostCentreStack *ccs, CostCentre *cc,
                                            CostCentreStack *new_ccs );
static  rtsBool           ignoreCCS       ( CostCentreStack *ccs );
static  void              countTickss     ( CostCentreStack *ccs );
static  void              inheritCosts    ( CostCentreStack *ccs );
static  void              findCCSMaxLens  ( CostCentreStack *ccs,
                                            nat indent,
                                            nat *max_label_len,
                                            nat *max_module_len );
static  void              logCCS          ( CostCentreStack *ccs,
                                            nat indent,
                                            nat max_label_len,
                                            nat max_module_len );
125
static  void              reportCCS       ( CostCentreStack *ccs );
126 127
static  CostCentreStack * checkLoop       ( CostCentreStack *ccs,
                                            CostCentre *cc );
128
static  CostCentreStack * pruneCCSTree    ( CostCentreStack *ccs );
129 130 131
static  CostCentreStack * actualPush      ( CostCentreStack *, CostCentre * );
static  CostCentreStack * isInIndexTable  ( IndexTable *, CostCentre * );
static  IndexTable *      addToIndexTable ( IndexTable *, CostCentreStack *,
132
					    CostCentre *, unsigned int );
133
static  void              ccsSetSelected  ( CostCentreStack *ccs );
134

135 136
static  void              initTimeProfiling    ( void );
static  void              initProfilingLogFile ( void );
137 138 139 140 141 142

/* -----------------------------------------------------------------------------
   Initialise the profiling environment
   -------------------------------------------------------------------------- */

void
143
initProfiling1 (void)
144
{
145 146
    // initialise our arena
    prof_arena = newArena();
147

148
    /* for the benefit of allocate()... */
149 150 151
    {
        nat n;
        for (n=0; n < n_capabilities; n++) {
152
            capabilities[n]->r.rCCCS = CCS_SYSTEM;
153 154
        }
    }
155 156 157 158

#ifdef THREADED_RTS
    initMutex(&ccs_mutex);
#endif
159 160
}

Ian Lynagh's avatar
Ian Lynagh committed
161
void
162
freeProfiling (void)
Ian Lynagh's avatar
Ian Lynagh committed
163 164 165 166
{
    arenaFree(prof_arena);
}

167 168 169
void
initProfiling2 (void)
{
170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185
    CostCentreStack *ccs, *next;

    /* Set up the log file, and dump the header and cost centre
     * information into it.
     */
    initProfilingLogFile();

    /* Register all the cost centres / stacks in the program
     * CC_MAIN gets link = 0, all others have non-zero link.
     */
    REGISTER_CC(CC_MAIN);
    REGISTER_CC(CC_SYSTEM);
    REGISTER_CC(CC_GC);
    REGISTER_CC(CC_OVERHEAD);
    REGISTER_CC(CC_DONT_CARE);
    REGISTER_CC(CC_PINNED);
186
    REGISTER_CC(CC_IDLE);
187 188 189 190 191 192

    REGISTER_CCS(CCS_SYSTEM);
    REGISTER_CCS(CCS_GC);
    REGISTER_CCS(CCS_OVERHEAD);
    REGISTER_CCS(CCS_DONT_CARE);
    REGISTER_CCS(CCS_PINNED);
193
    REGISTER_CCS(CCS_IDLE);
194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211
    REGISTER_CCS(CCS_MAIN);

    /* find all the registered cost centre stacks, and make them
     * children of CCS_MAIN.
     */
    ASSERT(CCS_LIST == CCS_MAIN);
    CCS_LIST = CCS_LIST->prevStack;
    CCS_MAIN->prevStack = NULL;
    CCS_MAIN->root = CCS_MAIN;
    ccsSetSelected(CCS_MAIN);

    // make CCS_MAIN the parent of all the pre-defined CCSs.
    for (ccs = CCS_LIST; ccs != NULL; ) {
        next = ccs->prevStack;
        ccs->prevStack = NULL;
        actualPush_(CCS_MAIN,ccs->cc,ccs);
        ccs->root = ccs;
        ccs = next;
212
    }
213 214 215

    if (RtsFlags.CcFlags.doCostCentres) {
        initTimeProfiling();
216 217
    }

218 219 220
    if (RtsFlags.ProfFlags.doHeapProfile) {
        initHeapProfiling();
    }
221 222 223
}


224 225
static void
initProfilingLogFile(void)
226
{
227 228 229 230 231 232 233 234 235 236 237 238 239 240 241
    char *prog;

    prog = arenaAlloc(prof_arena, strlen(prog_name) + 1);
    strcpy(prog, prog_name);
#ifdef mingw32_HOST_OS
    // on Windows, drop the .exe suffix if there is one
    {
        char *suff;
        suff = strrchr(prog,'.');
        if (suff != NULL && !strcmp(suff,".exe")) {
            *suff = '\0';
        }
    }
#endif

242
    if (RtsFlags.CcFlags.doCostCentres == 0 && 
243 244
        RtsFlags.ProfFlags.doHeapProfile != HEAP_BY_RETAINER &&
        RtsFlags.ProfFlags.retainerSelector == NULL)
245 246 247 248
    {
        /* No need for the <prog>.prof file */
        prof_filename = NULL;
        prof_file = NULL;
249
    }
250 251 252
    else
    {
        /* Initialise the log file name */
253 254
        prof_filename = arenaAlloc(prof_arena, strlen(prog) + 6);
        sprintf(prof_filename, "%s.prof", prog);
255 256 257 258 259 260 261 262 263 264 265

        /* open the log file */
        if ((prof_file = fopen(prof_filename, "w")) == NULL) {
            debugBelch("Can't open profiling report file %s\n", prof_filename);
            RtsFlags.CcFlags.doCostCentres = 0;
            // The following line was added by Sung; retainer/LDV profiling may need
            // two output files, i.e., <program>.prof/hp.
            if (RtsFlags.ProfFlags.doHeapProfile == HEAP_BY_RETAINER)
                RtsFlags.ProfFlags.doHeapProfile = 0;
            return;
        }
266
    }
267
    
268 269
    if (RtsFlags.ProfFlags.doHeapProfile) {
	/* Initialise the log file name */
270 271 272
	hp_filename = arenaAlloc(prof_arena, strlen(prog) + 6);
	sprintf(hp_filename, "%s.hp", prog);

273 274
	/* open the log file */
	if ((hp_file = fopen(hp_filename, "w")) == NULL) {
275
	    debugBelch("Can't open profiling report file %s\n", 
276 277 278 279
		    hp_filename);
	    RtsFlags.ProfFlags.doHeapProfile = 0;
	    return;
	}
280 281 282 283 284 285
    }
}

void
initTimeProfiling(void)
{
286 287
    /* Start ticking */
    startProfTimer();
288 289 290 291 292
};

void 
endProfiling ( void )
{
293 294 295 296 297 298
    if (RtsFlags.CcFlags.doCostCentres) {
        stopProfTimer();
    }
    if (RtsFlags.ProfFlags.doHeapProfile) {
        endHeapProfiling();
    }
299 300 301
}

/* -----------------------------------------------------------------------------
302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321
   Set CCCS when entering a function.

   The algorithm is as follows.

     ccs ++> ccsfn  =  ccs ++ dropCommonPrefix ccs ccsfn

   where

     dropCommonPrefix A B
        -- returns the suffix of B after removing any prefix common
        -- to both A and B.

   e.g.

     <a,b,c> ++> <>      = <a,b,c>
     <a,b,c> ++> <d>     = <a,b,c,d>
     <a,b,c> ++> <a,b>   = <a,b,c>
     <a,b>   ++> <a,b,c> = <a,b,c>
     <a,b,c> ++> <a,b,d> = <a,b,c,d>

322 323
   -------------------------------------------------------------------------- */

324 325
// implements  c1 ++> c2,  where c1 and c2 are equal depth
//
326 327 328 329
static CostCentreStack *
enterFunEqualStacks (CostCentreStack *ccs0,
                     CostCentreStack *ccsapp,
                     CostCentreStack *ccsfn)
330
{
331 332 333 334 335 336
    ASSERT(ccsapp->depth == ccsfn->depth);
    if (ccsapp == ccsfn) return ccs0;
    return pushCostCentre(enterFunEqualStacks(ccs0,
                                              ccsapp->prevStack,
                                              ccsfn->prevStack),
                          ccsfn->cc);
337 338 339 340 341 342 343
}

// implements  c1 ++> c2,  where c2 is deeper than c1.
// Drop elements of c2 until we have equal stacks, call
// enterFunEqualStacks(), and then push on the elements that we
// dropped in reverse order.
//
344 345
static CostCentreStack *
enterFunCurShorter (CostCentreStack *ccsapp, CostCentreStack *ccsfn, StgWord n)
346 347
{
    if (n == 0) {
348 349 350 351 352 353
        ASSERT(ccsfn->depth == ccsapp->depth);
        return enterFunEqualStacks(ccsapp,ccsapp,ccsfn);;
    } else {
        ASSERT(ccsfn->depth > ccsapp->depth);
        return pushCostCentre(enterFunCurShorter(ccsapp, ccsfn->prevStack, n-1),
                              ccsfn->cc);
354 355 356
    }
}

357
void enterFunCCS (StgRegTable *reg, CostCentreStack *ccsfn)
358
{
359 360
    CostCentreStack *ccsapp;

361
    // common case 1: both stacks are the same
362
    if (ccsfn == reg->rCCCS) {
363 364 365 366 367 368 369 370
        return;
    }

    // common case 2: the function stack is empty, or just CAF
    if (ccsfn->prevStack == CCS_MAIN) {
        return;
    }

371 372 373
    ccsapp = reg->rCCCS;
    reg->rCCCS = CCS_OVERHEAD;

374 375 376
    // common case 3: the stacks are completely different (e.g. one is a
    // descendent of MAIN and the other of a CAF): we append the whole
    // of the function stack to the current CCS.
377 378
    if (ccsfn->root != ccsapp->root) {
        reg->rCCCS = appendCCS(ccsapp,ccsfn);
379 380 381
        return;
    }

382 383
    // uncommon case 4: ccsapp is deeper than ccsfn
    if (ccsapp->depth > ccsfn->depth) {
384
        nat i, n;
385 386
        CostCentreStack *tmp = ccsapp;
        n = ccsapp->depth - ccsfn->depth;
387 388 389
        for (i = 0; i < n; i++) {
            tmp = tmp->prevStack;
        }
390
        reg->rCCCS = enterFunEqualStacks(ccsapp,tmp,ccsfn);
391 392 393 394
        return;
    }

    // uncommon case 5: ccsfn is deeper than CCCS
395 396 397
    if (ccsfn->depth > ccsapp->depth) {
        reg->rCCCS = enterFunCurShorter(ccsapp, ccsfn,
                                        ccsfn->depth - ccsapp->depth);
398 399
        return;
    }
400

401
    // uncommon case 6: stacks are equal depth, but different
402
    reg->rCCCS = enterFunEqualStacks(ccsapp,ccsapp,ccsfn);
403 404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426 427 428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443
}

/* -----------------------------------------------------------------------------
   Decide whether closures with this CCS should contribute to the heap
   profile.
   -------------------------------------------------------------------------- */

static void
ccsSetSelected (CostCentreStack *ccs)
{
    if (RtsFlags.ProfFlags.modSelector) {
        if (! strMatchesSelector (ccs->cc->module,
                                  RtsFlags.ProfFlags.modSelector) ) {
	    ccs->selected = 0;
            return;
        }
    }
    if (RtsFlags.ProfFlags.ccSelector) {
        if (! strMatchesSelector (ccs->cc->label,
                                  RtsFlags.ProfFlags.ccSelector) ) {
	    ccs->selected = 0;
            return;
        }
    }
    if (RtsFlags.ProfFlags.ccsSelector) {
	CostCentreStack *c;
        for (c = ccs; c != NULL; c = c->prevStack)
        {
            if ( strMatchesSelector (c->cc->label,
                                     RtsFlags.ProfFlags.ccsSelector) ) {
		break; 
	    }
	}
        if (c == NULL) {
            ccs->selected = 0;
            return;
        }
    }

    ccs->selected = 1;
    return;
444 445
}

446 447 448 449
/* -----------------------------------------------------------------------------
   Cost-centre stack manipulation
   -------------------------------------------------------------------------- */

450
#ifdef DEBUG
451
CostCentreStack * _pushCostCentre ( CostCentreStack *ccs, CostCentre *cc );
452
CostCentreStack *
453 454
pushCostCentre ( CostCentreStack *ccs, CostCentre *cc )
#define pushCostCentre _pushCostCentre
455
{
Simon Marlow's avatar
Simon Marlow committed
456 457 458 459 460
    IF_DEBUG(prof,
	     traceBegin("pushing %s on ", cc->label);
	     debugCCS(ccs);
	     traceEnd(););
	     
461
    return pushCostCentre(ccs,cc);
462 463 464 465 466 467
}
#endif

/* Append ccs1 to ccs2 (ignoring any CAF cost centre at the root of ccs1 */

#ifdef DEBUG
468
CostCentreStack *_appendCCS ( CostCentreStack *ccs1, CostCentreStack *ccs2 );
469
CostCentreStack *
470 471 472 473 474 475 476 477 478 479 480
appendCCS ( CostCentreStack *ccs1, CostCentreStack *ccs2 )
#define appendCCS _appendCCS
{
  IF_DEBUG(prof,
          if (ccs1 != ccs2) {
            debugBelch("Appending ");
            debugCCS(ccs1);
            debugBelch(" to ");
            debugCCS(ccs2);
            debugBelch("\n");});
  return appendCCS(ccs1,ccs2);
481 482 483 484
}
#endif

CostCentreStack *
485
appendCCS ( CostCentreStack *ccs1, CostCentreStack *ccs2 )
486
{
487 488 489 490 491 492 493 494
    if (ccs1 == ccs2) {
        return ccs1;
    }

    if (ccs2 == CCS_MAIN || ccs2->cc->is_caf == CC_IS_CAF) {
        // stop at a CAF element
        return ccs1;
    }
495

496 497
    return pushCostCentre(appendCCS(ccs1, ccs2->prevStack), ccs2->cc);
}
498

499 500 501
// Pick one:
// #define RECURSION_DROPS
#define RECURSION_TRUNCATES
502

503 504 505
CostCentreStack *
pushCostCentre (CostCentreStack *ccs, CostCentre *cc)
{
506 507 508 509 510 511 512 513 514 515
    CostCentreStack *temp_ccs, *ret;
    IndexTable *ixtable;

    if (ccs == EMPTY_STACK) {
        ACQUIRE_LOCK(&ccs_mutex);
        ret = actualPush(ccs,cc);
    }
    else
    {
        if (ccs->cc == cc) {
516
            return ccs;
517
        } else {
518
            // check if we've already memoized this stack
519 520
            ixtable = ccs->indexTable;
            temp_ccs = isInIndexTable(ixtable,cc);
521
      
522
            if (temp_ccs != EMPTY_STACK) {
523
                return temp_ccs;
524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540
            } else {

                // not in the IndexTable, now we take the lock:
                ACQUIRE_LOCK(&ccs_mutex);

                if (ccs->indexTable != ixtable)
                {
                    // someone modified ccs->indexTable while
                    // we did not hold the lock, so we must
                    // check it again:
                    temp_ccs = isInIndexTable(ixtable,cc);
                    if (temp_ccs != EMPTY_STACK)
                    {
                        RELEASE_LOCK(&ccs_mutex);
                        return temp_ccs;
                    }
                }
541 542 543 544 545 546 547 548 549 550 551 552 553 554 555 556 557 558 559
                temp_ccs = checkLoop(ccs,cc);
                if (temp_ccs != NULL) {
                    // This CC is already in the stack somewhere.
                    // This could be recursion, or just calling
                    // another function with the same CC.
                    // A number of policies are possible at this
                    // point, we implement two here:
                    //   - truncate the stack to the previous instance
                    //     of this CC
                    //   - ignore this push, return the same stack.
                    //
                    CostCentreStack *new_ccs;
#if defined(RECURSION_TRUNCATES)
                    new_ccs = temp_ccs;
#else // defined(RECURSION_DROPS)
                    new_ccs = ccs;
#endif
                    ccs->indexTable = addToIndexTable (ccs->indexTable,
                                                       new_ccs, cc, 1);
560
                    ret = new_ccs;
561
                } else {
562
                    ret = actualPush (ccs,cc);
563 564 565 566
                }
            }
        }
    }
567 568 569

    RELEASE_LOCK(&ccs_mutex);
    return ret;
570
}
571

572
static CostCentreStack *
573
checkLoop (CostCentreStack *ccs, CostCentre *cc)
574
{
575 576 577 578 579 580
    while (ccs != EMPTY_STACK) {
        if (ccs->cc == cc)
            return ccs;
        ccs = ccs->prevStack;
    }
    return NULL;
581 582 583
}

static CostCentreStack *
584
actualPush (CostCentreStack *ccs, CostCentre *cc)
585
{
586
    CostCentreStack *new_ccs;
587

588 589
    // allocate space for a new CostCentreStack
    new_ccs = (CostCentreStack *) arenaAlloc(prof_arena, sizeof(CostCentreStack));
590

591
    return actualPush_(ccs, cc, new_ccs);
592 593
}

594
static CostCentreStack *
595
actualPush_ (CostCentreStack *ccs, CostCentre *cc, CostCentreStack *new_ccs)
596
{
597 598 599 600 601 602 603 604 605 606 607 608 609 610 611 612 613 614 615 616 617 618 619 620 621
    /* assign values to each member of the structure */
    new_ccs->ccsID = CCS_ID++;
    new_ccs->cc = cc;
    new_ccs->prevStack = ccs;
    new_ccs->root = ccs->root;
    new_ccs->depth = ccs->depth + 1;

    new_ccs->indexTable = EMPTY_TABLE;

    /* Initialise the various _scc_ counters to zero
     */
    new_ccs->scc_count        = 0;

    /* Initialize all other stats here.  There should be a quick way
     * that's easily used elsewhere too
     */
    new_ccs->time_ticks = 0;
    new_ccs->mem_alloc = 0;
    new_ccs->inherited_ticks = 0;
    new_ccs->inherited_alloc = 0;

    // Set the selected field.
    ccsSetSelected(new_ccs);

    /* update the memoization table for the parent stack */
622 623
    ccs->indexTable = addToIndexTable(ccs->indexTable, new_ccs, cc,
                                      0/*not a back edge*/);
624 625 626

    /* return a pointer to the new stack */
    return new_ccs;
627 628 629
}


630 631
static CostCentreStack *
isInIndexTable(IndexTable *it, CostCentre *cc)
632
{
633 634 635 636 637 638 639
    while (it!=EMPTY_TABLE)
    {
        if (it->cc == cc)
            return it->ccs;
        else
            it = it->next;
    }
640
  
641 642
    /* otherwise we never found it so return EMPTY_TABLE */
    return EMPTY_TABLE;
643 644 645
}


646 647 648
static IndexTable *
addToIndexTable (IndexTable *it, CostCentreStack *new_ccs,
                 CostCentre *cc, unsigned int back_edge)
649
{
650
    IndexTable *new_it;
651

652 653 654 655 656 657 658
    new_it = arenaAlloc(prof_arena, sizeof(IndexTable));

    new_it->cc = cc;
    new_it->ccs = new_ccs;
    new_it->next = it;
    new_it->back_edge = back_edge;
    return new_it;
659 660
}

661 662 663 664
/* -----------------------------------------------------------------------------
   Generating a time & allocation profiling report.
   -------------------------------------------------------------------------- */

665 666 667 668
/* We omit certain system-related CCs and CCSs from the default
 * reports, so as not to cause confusion.
 */
static rtsBool
669
ignoreCC (CostCentre *cc)
670
{
671 672
    if (RtsFlags.CcFlags.doCostCentres < COST_CENTRES_ALL &&
        (   cc == CC_OVERHEAD
673 674
	 || cc == CC_DONT_CARE
	 || cc == CC_GC 
675 676
         || cc == CC_SYSTEM
         || cc == CC_IDLE)) {
677 678 679 680 681 682 683
	return rtsTrue;
    } else {
	return rtsFalse;
    }
}

static rtsBool
684
ignoreCCS (CostCentreStack *ccs)
685
{
686 687 688 689
    if (RtsFlags.CcFlags.doCostCentres < COST_CENTRES_ALL &&
        (   ccs == CCS_OVERHEAD
         || ccs == CCS_DONT_CARE
         || ccs == CCS_GC
690 691
         || ccs == CCS_SYSTEM
         || ccs == CCS_IDLE)) {
692
        return rtsTrue;
693 694 695 696 697
    } else {
	return rtsFalse;
    }
}

698 699 700 701 702 703 704
/* -----------------------------------------------------------------------------
   Generating the aggregated per-cost-centre time/alloc report.
   -------------------------------------------------------------------------- */

static CostCentre *sorted_cc_list;

static void
705
aggregateCCCosts( CostCentreStack *ccs )
706
{
707
    IndexTable *i;
708

709 710
    ccs->cc->mem_alloc += ccs->mem_alloc;
    ccs->cc->time_ticks += ccs->time_ticks;
711

712 713 714 715
    for (i = ccs->indexTable; i != 0; i = i->next) {
        if (!i->back_edge) {
            aggregateCCCosts(i->ccs);
        }
716
    }
717 718 719
}

static void
720
insertCCInSortedList( CostCentre *new_cc )
721
{
722
    CostCentre **prev, *cc;
723

724 725 726 727 728 729 730 731 732
    prev = &sorted_cc_list;
    for (cc = sorted_cc_list; cc != NULL; cc = cc->link) {
        if (new_cc->time_ticks > cc->time_ticks) {
            new_cc->link = cc;
            *prev = new_cc;
            return;
        } else {
            prev = &(cc->link);
        }
733
    }
734 735
    new_cc->link = NULL;
    *prev = new_cc;
736 737
}

738 739 740 741 742 743 744 745 746 747 748 749 750
static nat
strlen_utf8 (char *s)
{
    nat n = 0;
    unsigned char c;

    for (; *s != '\0'; s++) {
        c = *s;
        if (c < 0x80 || c > 0xBF) n++;
    }
    return n;
}

751
static void
752
reportPerCCCosts( void )
753
{
754 755
    CostCentre *cc, *next;
    nat max_label_len, max_module_len;
756

757 758
    aggregateCCCosts(CCS_MAIN);
    sorted_cc_list = NULL;
759

760 761
    max_label_len  = 11; // no shorter than the "COST CENTRE" header
    max_module_len = 7;  // no shorter than the "MODULE" header
762

763 764 765 766 767 768 769
    for (cc = CC_LIST; cc != NULL; cc = next) {
        next = cc->link;
        if (cc->time_ticks > total_prof_ticks/100
            || cc->mem_alloc > total_alloc/100
            || RtsFlags.CcFlags.doCostCentres >= COST_CENTRES_ALL) {
            insertCCInSortedList(cc);

770 771
            max_label_len = stg_max(strlen_utf8(cc->label), max_label_len);
            max_module_len = stg_max(strlen_utf8(cc->module), max_module_len);
772
        }
773 774
    }

775 776 777 778 779 780 781 782 783 784 785
    fprintf(prof_file, "%-*s %-*s", max_label_len, "COST CENTRE", max_module_len, "MODULE");
    fprintf(prof_file, "%6s %6s", "%time", "%alloc");
    if (RtsFlags.CcFlags.doCostCentres >= COST_CENTRES_VERBOSE) {
        fprintf(prof_file, "  %5s %9s", "ticks", "bytes");
    }
    fprintf(prof_file, "\n\n");

    for (cc = sorted_cc_list; cc != NULL; cc = cc->link) {
        if (ignoreCC(cc)) {
            continue;
        }
786 787 788 789 790 791
        fprintf(prof_file, "%s%*s %s%*s",
                cc->label,
                max_label_len - strlen_utf8(cc->label), "",
                cc->module,
                max_module_len - strlen_utf8(cc->module), "");

792 793 794 795 796 797 798 799 800 801 802 803 804 805
        fprintf(prof_file, "%6.1f %6.1f",
                total_prof_ticks == 0 ? 0.0 : (cc->time_ticks / (StgFloat) total_prof_ticks * 100),
                total_alloc == 0 ? 0.0 : (cc->mem_alloc / (StgFloat)
                                          total_alloc * 100)
            );

        if (RtsFlags.CcFlags.doCostCentres >= COST_CENTRES_VERBOSE) {
            fprintf(prof_file, "  %5" FMT_Word64 " %9" FMT_Word64,
                    (StgWord64)(cc->time_ticks), cc->mem_alloc*sizeof(W_));
        }
        fprintf(prof_file, "\n");
    }

    fprintf(prof_file,"\n\n");
806 807 808 809 810 811 812
}

/* -----------------------------------------------------------------------------
   Generate the cost-centre-stack time/alloc report
   -------------------------------------------------------------------------- */

static void 
813
fprintHeader( nat max_label_len, nat max_module_len )
814
{
815
    fprintf(prof_file, "%-*s %-*s%6s %11s  %11s   %11s\n", max_label_len, "", max_module_len, "", "", "", "individual", "inherited");
816

817 818
    fprintf(prof_file, "%-*s %-*s", max_label_len, "COST CENTRE", max_module_len, "MODULE");
    fprintf(prof_file, "%6s %11s  %5s %5s   %5s %5s", "no.", "entries", "%time", "%alloc", "%time", "%alloc");
819

820 821 822
    if (RtsFlags.CcFlags.doCostCentres >= COST_CENTRES_VERBOSE) {
        fprintf(prof_file, "  %5s %9s", "ticks", "bytes");
    }
823

824
    fprintf(prof_file, "\n\n");
825 826
}

827
void
828
reportCCSProfiling( void )
829 830 831
{
    nat count;
    char temp[128]; /* sigh: magic constant */
832
    
833 834
    stopProfTimer();

835
    total_prof_ticks = 0;
836
    total_alloc = 0;
837
    countTickss(CCS_MAIN);
838
    
839
    if (RtsFlags.CcFlags.doCostCentres == 0) return;
840

841 842 843 844
    fprintf(prof_file, "\t%s Time and Allocation Profiling Report  (%s)\n", 
	    time_str(), "Final");

    fprintf(prof_file, "\n\t  ");
sof's avatar
sof committed
845
    fprintf(prof_file, " %s", prog_name);
846 847 848 849 850 851 852 853
    fprintf(prof_file, " +RTS");
    for (count = 0; rts_argv[count]; count++)
	fprintf(prof_file, " %s", rts_argv[count]);
    fprintf(prof_file, " -RTS");
    for (count = 1; prog_argv[count]; count++)
	fprintf(prof_file, " %s", prog_argv[count]);
    fprintf(prof_file, "\n\n");

854
    fprintf(prof_file, "\ttotal time  = %11.2f secs   (%lu ticks @ %d us, %d processor%s)\n",
Simon Marlow's avatar
Simon Marlow committed
855
            ((double) total_prof_ticks *
856
             (double) RtsFlags.MiscFlags.tickInterval) / (TIME_RESOLUTION * n_capabilities),
857
	    (unsigned long) total_prof_ticks,
858 859
            (int) TimeToUS(RtsFlags.MiscFlags.tickInterval),
            n_capabilities, n_capabilities > 1 ? "s" : "");
860 861

    fprintf(prof_file, "\ttotal alloc = %11s bytes",
Ian Lynagh's avatar
Ian Lynagh committed
862
	    showStgWord64(total_alloc * sizeof(W_),
863 864 865 866
				 temp, rtsTrue/*commas*/));

    fprintf(prof_file, "  (excludes profiling overheads)\n\n");

867
    reportPerCCCosts();
868

869
    inheritCosts(CCS_MAIN);
870

871
    reportCCS(pruneCCSTree(CCS_MAIN));
872 873 874
}

static void 
875
findCCSMaxLens(CostCentreStack *ccs, nat indent, nat *max_label_len, nat *max_module_len) {
876 877 878 879 880
    CostCentre *cc;
    IndexTable *i;

    cc = ccs->cc;

881 882
    *max_label_len = stg_max(*max_label_len, indent + strlen_utf8(cc->label));
    *max_module_len = stg_max(*max_module_len, strlen_utf8(cc->module));
883 884 885 886 887

    for (i = ccs->indexTable; i != 0; i = i->next) {
        if (!i->back_edge) {
            findCCSMaxLens(i->ccs, indent+1, max_label_len, max_module_len);
        }
888 889 890 891 892
    }
}

static void 
logCCS(CostCentreStack *ccs, nat indent, nat max_label_len, nat max_module_len)
893
{
894 895
    CostCentre *cc;
    IndexTable *i;
896

897 898 899 900 901 902
    cc = ccs->cc;

    /* Only print cost centres with non 0 data ! */

    if (!ignoreCCS(ccs))
        /* force printing of *all* cost centres if -Pa */
903 904
    {

905 906 907 908 909 910
        fprintf(prof_file, "%-*s%s%*s %s%*s",
                indent, "",
                cc->label,
                max_label_len-indent - strlen_utf8(cc->label), "",
                cc->module,
                max_module_len - strlen_utf8(cc->module), "");
911

912 913 914 915 916 917
        fprintf(prof_file, "%6ld %11" FMT_Word64 "  %5.1f  %5.1f   %5.1f  %5.1f",
            ccs->ccsID, ccs->scc_count,
                total_prof_ticks == 0 ? 0.0 : ((double)ccs->time_ticks / (double)total_prof_ticks * 100.0),
                total_alloc == 0 ? 0.0 : ((double)ccs->mem_alloc / (double)total_alloc * 100.0),
                total_prof_ticks == 0 ? 0.0 : ((double)ccs->inherited_ticks / (double)total_prof_ticks * 100.0),
                total_alloc == 0 ? 0.0 : ((double)ccs->inherited_alloc / (double)total_alloc * 100.0)
918 919
	    );

920 921 922 923 924
        if (RtsFlags.CcFlags.doCostCentres >= COST_CENTRES_VERBOSE) {
            fprintf(prof_file, "  %5" FMT_Word64 " %9" FMT_Word64,
                    (StgWord64)(ccs->time_ticks), ccs->mem_alloc*sizeof(W_));
        }
        fprintf(prof_file, "\n");
925 926
    }

927 928 929 930
    for (i = ccs->indexTable; i != 0; i = i->next) {
        if (!i->back_edge) {
            logCCS(i->ccs, indent+1, max_label_len, max_module_len);
        }
931
    }
932 933
}

934 935 936
static void
reportCCS(CostCentreStack *ccs)
{
937 938 939 940 941 942 943 944 945
    nat max_label_len, max_module_len;

    max_label_len = 11; // no shorter than "COST CENTRE" header
    max_module_len = 7; // no shorter than "MODULE" header

    findCCSMaxLens(ccs, 0, &max_label_len, &max_module_len);

    fprintHeader(max_label_len, max_module_len);
    logCCS(ccs, 0, max_label_len, max_module_len);
946 947
}

andy's avatar
andy committed
948

949 950 951 952
/* Traverse the cost centre stack tree and accumulate
 * ticks/allocations.
 */
static void
953
countTickss(CostCentreStack *ccs)
954
{
955 956 957 958 959
    IndexTable *i;

    if (!ignoreCCS(ccs)) {
        total_alloc += ccs->mem_alloc;
        total_prof_ticks += ccs->time_ticks;
960
    }
961 962 963 964
    for (i = ccs->indexTable; i != NULL; i = i->next)
        if (!i->back_edge) {
            countTickss(i->ccs);
        }
965 966
}

967 968 969
/* Traverse the cost centre stack tree and inherit ticks & allocs.
 */
static void
970
inheritCosts(CostCentreStack *ccs)
971
{
972
    IndexTable *i;
973

974
    if (ignoreCCS(ccs)) { return; }
975

976 977
    ccs->inherited_ticks += ccs->time_ticks;
    ccs->inherited_alloc += ccs->mem_alloc;
978

979 980 981 982 983 984 985 986
    for (i = ccs->indexTable; i != NULL; i = i->next)
        if (!i->back_edge) {
            inheritCosts(i->ccs);
            ccs->inherited_ticks += i->ccs->inherited_ticks;
            ccs->inherited_alloc += i->ccs->inherited_alloc;
        }

    return;
987 988
}

989 990 991 992
//
// Prune CCSs with zero entries, zero ticks or zero allocation from
// the tree, unless COST_CENTRES_ALL is on.
//
993
static CostCentreStack *
994
pruneCCSTree (CostCentreStack *ccs)
995
{
996 997 998 999 1000 1001 1002 1003 1004 1005 1006 1007 1008 1009 1010 1011 1012
    CostCentreStack *ccs1;
    IndexTable *i, **prev;

    prev = &ccs->indexTable;
    for (i = ccs->indexTable; i != 0; i = i->next) {
        if (i->back_edge) { continue; }

        ccs1 = pruneCCSTree(i->ccs);
        if (ccs1 == NULL) {
            *prev = i->next;
        } else {
            prev = &(i->next);
        }
    }

    if ( (RtsFlags.CcFlags.doCostCentres >= COST_CENTRES_ALL
          /* force printing of *all* cost centres if -P -P */ )
1013

1014 1015 1016 1017
         || ( ccs->indexTable != 0 )
         || ( ccs->scc_count || ccs->time_ticks || ccs->mem_alloc )
        ) {
        return ccs;
1018
    } else {
1019
        return NULL;
1020 1021 1022
    }
}

1023
void
Simon Marlow's avatar