Show sources of cost centers in .prof

This fixes the problem with duplicate cost-centre names that was
reported a couple of times before. When a module implements a typeclass
multiple times for different types, methods of different implementations
get same cost-centre names and are reported like this:

    COST CENTRE MODULE            %time %alloc

    CAF         GHC.IO.Handle.FD    0.0   32.8
    CAF         GHC.Read            0.0    1.0
    CAF         GHC.IO.Encoding     0.0    1.8
    showsPrec   Main                0.0    1.2
    readPrec    Main                0.0   19.4
    readPrec    Main                0.0   20.5
    main        Main                0.0   20.2

                                            individual      inherited
    COST CENTRE  MODULE  no.     entries  %time %alloc   %time %alloc

    MAIN         MAIN     53          0    0.0    0.2     0.0  100.0
     CAF         Main    105          0    0.0    0.3     0.0   62.5
      readPrec   Main    109          1    0.0    0.6     0.0    0.6
      readPrec   Main    107          1    0.0    0.6     0.0    0.6
      main       Main    106          1    0.0   20.2     0.0   61.0
       ==        Main    114          1    0.0    0.0     0.0    0.0
       ==        Main    113          1    0.0    0.0     0.0    0.0
       showsPrec Main    112          2    0.0    1.2     0.0    1.2
       showsPrec Main    111          2    0.0    0.9     0.0    0.9
       readPrec  Main    110          0    0.0   18.8     0.0   18.8
       readPrec  Main    108          0    0.0   19.9     0.0   19.9

It's not possible to tell from the report which `==` took how long. This
patch adds one more column at the cost of making outputs wider. The
report now looks like this:

    COST CENTRE MODULE           SRC                       %time %alloc

    CAF         GHC.IO.Handle.FD <entire-module>             0.0   32.9
    CAF         GHC.IO.Encoding  <entire-module>             0.0    1.8
    CAF         GHC.Read         <entire-module>             0.0    1.0
    showsPrec   Main             Main_1.hs:7:19-22           0.0    1.2
    readPrec    Main             Main_1.hs:7:13-16           0.0   19.5
    readPrec    Main             Main_1.hs:4:13-16           0.0   20.5
    main        Main             Main_1.hs:(10,1)-(20,20)    0.0   20.2

                                                                       individual      inherited
    COST CENTRE  MODULE        SRC                      no. entries  %time %alloc   %time %alloc

    MAIN         MAIN          <built-in>                53      0    0.0    0.2     0.0  100.0
     CAF         Main          <entire-module>          105      0    0.0    0.3     0.0   62.5
      readPrec   Main          Main_1.hs:7:13-16        109      1    0.0    0.6     0.0    0.6
      readPrec   Main          Main_1.hs:4:13-16        107      1    0.0    0.6     0.0    0.6
      main       Main          Main_1.hs:(10,1)-(20,20) 106      1    0.0   20.2     0.0   61.0
       ==        Main          Main_1.hs:7:25-26        114      1    0.0    0.0     0.0    0.0
       ==        Main          Main_1.hs:4:25-26        113      1    0.0    0.0     0.0    0.0
       showsPrec Main          Main_1.hs:7:19-22        112      2    0.0    1.2     0.0    1.2
       showsPrec Main          Main_1.hs:4:19-22        111      2    0.0    0.9     0.0    0.9
       readPrec  Main          Main_1.hs:7:13-16        110      0    0.0   18.8     0.0   18.8
       readPrec  Main          Main_1.hs:4:13-16        108      0    0.0   19.9     0.0   19.9
     CAF         Text.Read.Lex <entire-module>          102      0    0.0    0.5     0.0    0.5

To fix failing test cases because of different orderings of cost centres
(e.g. optimized and non-optimized build printing in different order),
with this patch we also start sorting cost centres before printing. The
order depends on 1) entries (more entered cost centres come first) 2)
names (using strcmp() on cost centre names).

Reviewers: simonmar, austin, erikd, bgamari

Reviewed By: simonmar, bgamari

Subscribers: thomie

Differential Revision: https://phabricator.haskell.org/D2282

GHC Trac Issues: #11543, #8473, #7105

1 files changed, 94 insertions, 18 deletions

diff --git a/rts/Profiling.c b/rts/Profiling.c
index a4fc281967..ea1e9dbb2e 100644
--- a/rts/Profiling.c
+++ b/rts/Profiling.c
@@ -119,16 +119,19 @@ static  void              findCCSMaxLens  ( CostCentreStack *ccs,
                                             uint32_t indent,
                                             uint32_t *max_label_len,
                                             uint32_t *max_module_len,
+                                            uint32_t *max_src_len,
                                             uint32_t *max_id_len );
 static  void              logCCS          ( CostCentreStack *ccs,
                                             uint32_t indent,
                                             uint32_t max_label_len,
                                             uint32_t max_module_len,
+                                            uint32_t max_src_len,
                                             uint32_t max_id_len );
 static  void              reportCCS       ( CostCentreStack *ccs );
 static  CostCentreStack * checkLoop       ( CostCentreStack *ccs,
                                             CostCentre *cc );
 static  CostCentreStack * pruneCCSTree    ( CostCentreStack *ccs );
+static  void              sortCCSTree     ( CostCentreStack *ccs );
 static  CostCentreStack * actualPush      ( CostCentreStack *, CostCentre * );
 static  CostCentreStack * isInIndexTable  ( IndexTable *, CostCentre * );
 static  IndexTable *      addToIndexTable ( IndexTable *, CostCentreStack *,
@@ -764,13 +767,14 @@ static void
 reportPerCCCosts( void )
 {
     CostCentre *cc, *next;
-    uint32_t max_label_len, max_module_len;
+    uint32_t max_label_len, max_module_len, max_src_len;
 
     aggregateCCCosts(CCS_MAIN);
     sorted_cc_list = NULL;
 
     max_label_len  = 11; // no shorter than the "COST CENTRE" header
     max_module_len = 6;  // no shorter than the "MODULE" header
+    max_src_len    = 3;  // no shorter than the "SRC" header
 
     for (cc = CC_LIST; cc != NULL; cc = next) {
         next = cc->link;
@@ -781,10 +785,12 @@ reportPerCCCosts( void )
 
             max_label_len = stg_max(strlen_utf8(cc->label), max_label_len);
             max_module_len = stg_max(strlen_utf8(cc->module), max_module_len);
+            max_src_len = stg_max(strlen_utf8(cc->srcloc), max_src_len);
         }
     }
 
-    fprintf(prof_file, "%-*s %-*s", max_label_len, "COST CENTRE", max_module_len, "MODULE");
+    fprintf(prof_file, "%-*s %-*s %-*s",
+            max_label_len, "COST CENTRE", max_module_len, "MODULE", max_src_len, "SRC");
     fprintf(prof_file, " %6s %6s", "%time", "%alloc");
     if (RtsFlags.CcFlags.doCostCentres >= COST_CENTRES_VERBOSE) {
         fprintf(prof_file, "  %5s %9s", "ticks", "bytes");
@@ -795,11 +801,13 @@ reportPerCCCosts( void )
         if (ignoreCC(cc)) {
             continue;
         }
-        fprintf(prof_file, "%s%*s %s%*s",
+        fprintf(prof_file, "%s%*s %s%*s %s%*s",
                 cc->label,
                 max_label_len - strlen_utf8(cc->label), "",
                 cc->module,
-                max_module_len - strlen_utf8(cc->module), "");
+                max_module_len - strlen_utf8(cc->module), "",
+                cc->srcloc,
+                max_src_len - strlen_utf8(cc->srcloc), "");
 
         fprintf(prof_file, " %6.1f %6.1f",
                 total_prof_ticks == 0 ? 0.0 : (cc->time_ticks / (StgFloat) total_prof_ticks * 100),
@@ -823,17 +831,19 @@ reportPerCCCosts( void )
 
 static void
 fprintHeader( uint32_t max_label_len, uint32_t max_module_len,
-                uint32_t max_id_len )
+                uint32_t max_src_len, uint32_t max_id_len )
 {
-    fprintf(prof_file, "%-*s %-*s %-*s %11s  %12s   %12s\n",
+    fprintf(prof_file, "%-*s %-*s %-*s %-*s %11s  %12s   %12s\n",
             max_label_len, "",
             max_module_len, "",
+            max_src_len, "",
             max_id_len, "",
             "", "individual", "inherited");
 
-    fprintf(prof_file, "%-*s %-*s %-*s",
+    fprintf(prof_file, "%-*s %-*s %-*s %-*s",
             max_label_len, "COST CENTRE",
             max_module_len, "MODULE",
+            max_src_len, "SRC",
             max_id_len, "no.");
 
     fprintf(prof_file, " %11s  %5s %6s   %5s %6s",
@@ -890,7 +900,9 @@ reportCCSProfiling( void )
 
     inheritCosts(CCS_MAIN);
 
-    reportCCS(pruneCCSTree(CCS_MAIN));
+    CostCentreStack *stack = pruneCCSTree(CCS_MAIN);
+    sortCCSTree(stack);
+    reportCCS(stack);
 }
 
 static uint32_t
@@ -911,7 +923,7 @@ numDigits(StgInt i) {
 
 static void
 findCCSMaxLens(CostCentreStack *ccs, uint32_t indent, uint32_t *max_label_len,
-        uint32_t *max_module_len, uint32_t *max_id_len) {
+        uint32_t *max_module_len, uint32_t *max_src_len, uint32_t *max_id_len) {
     CostCentre *cc;
     IndexTable *i;
 
@@ -919,19 +931,21 @@ findCCSMaxLens(CostCentreStack *ccs, uint32_t indent, uint32_t *max_label_len,
 
     *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));
+    *max_src_len = stg_max(*max_src_len, strlen_utf8(cc->srcloc));
     *max_id_len = stg_max(*max_id_len, numDigits(ccs->ccsID));
 
     for (i = ccs->indexTable; i != 0; i = i->next) {
         if (!i->back_edge) {
             findCCSMaxLens(i->ccs, indent+1,
-                    max_label_len, max_module_len, max_id_len);
+                    max_label_len, max_module_len, max_src_len, max_id_len);
         }
     }
 }
 
 static void
 logCCS(CostCentreStack *ccs, uint32_t indent,
-        uint32_t max_label_len, uint32_t max_module_len, uint32_t max_id_len)
+        uint32_t max_label_len, uint32_t max_module_len,
+        uint32_t max_src_len, uint32_t max_id_len)
 {
     CostCentre *cc;
     IndexTable *i;
@@ -944,12 +958,14 @@ logCCS(CostCentreStack *ccs, uint32_t indent,
         /* force printing of *all* cost centres if -Pa */
     {
 
-        fprintf(prof_file, "%-*s%s%*s %s%*s",
+        fprintf(prof_file, "%*s%s%*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), "");
+                max_module_len - strlen_utf8(cc->module), "",
+                cc->srcloc,
+                max_src_len - strlen_utf8(cc->srcloc), "");
 
         fprintf(prof_file,
                 " %*" FMT_Int "%11" FMT_Word64 "  %5.1f  %5.1f   %5.1f  %5.1f",
@@ -969,7 +985,8 @@ logCCS(CostCentreStack *ccs, uint32_t indent,
 
     for (i = ccs->indexTable; i != 0; i = i->next) {
         if (!i->back_edge) {
-            logCCS(i->ccs, indent+1, max_label_len, max_module_len, max_id_len);
+            logCCS(i->ccs, indent+1,
+                   max_label_len, max_module_len, max_src_len, max_id_len);
         }
     }
 }
@@ -977,16 +994,18 @@ logCCS(CostCentreStack *ccs, uint32_t indent,
 static void
 reportCCS(CostCentreStack *ccs)
 {
-    uint32_t max_label_len, max_module_len, max_id_len;
+    uint32_t max_label_len, max_module_len, max_src_len, max_id_len;
 
     max_label_len = 11; // no shorter than "COST CENTRE" header
     max_module_len = 6; // no shorter than "MODULE" header
+    max_src_len = 3; // no shorter than "SRC" header
     max_id_len = 3; // no shorter than "no." header
 
-    findCCSMaxLens(ccs, 0, &max_label_len, &max_module_len, &max_id_len);
+    findCCSMaxLens(ccs, 0,
+                   &max_label_len, &max_module_len, &max_src_len, &max_id_len);
 
-    fprintHeader(max_label_len, max_module_len, max_id_len);
-    logCCS(ccs, 0, max_label_len, max_module_len, max_id_len);
+    fprintHeader(max_label_len, max_module_len, max_src_len, max_id_len);
+    logCCS(ccs, 0, max_label_len, max_module_len, max_src_len, max_id_len);
 }
 
 
@@ -1064,6 +1083,63 @@ pruneCCSTree (CostCentreStack *ccs)
     }
 }
 
+static IndexTable*
+insertIndexTableInSortedList(IndexTable* tbl, IndexTable* sortedList)
+{
+    StgWord tbl_ticks = tbl->ccs->scc_count;
+    char*   tbl_label = tbl->ccs->cc->label;
+
+    IndexTable *prev   = NULL;
+    IndexTable *cursor = sortedList;
+
+    while (cursor != NULL) {
+        StgWord cursor_ticks = cursor->ccs->scc_count;
+        char*   cursor_label = cursor->ccs->cc->label;
+
+        if (tbl_ticks > cursor_ticks ||
+                (tbl_ticks == cursor_ticks && strcmp(tbl_label, cursor_label) < 0)) {
+            if (prev == NULL) {
+                tbl->next = sortedList;
+                return tbl;
+            } else {
+                prev->next = tbl;
+                tbl->next = cursor;
+                return sortedList;
+            }
+        } else {
+            prev   = cursor;
+            cursor = cursor->next;
+        }
+    }
+
+    prev->next = tbl;
+    return sortedList;
+}
+
+static void
+sortCCSTree(CostCentreStack *ccs)
+{
+    if (ccs->indexTable == NULL) return;
+
+    for (IndexTable *tbl = ccs->indexTable; tbl != NULL; tbl = tbl->next)
+        if (!tbl->back_edge)
+            sortCCSTree(tbl->ccs);
+
+    IndexTable *sortedList    = ccs->indexTable;
+    IndexTable *nonSortedList = sortedList->next;
+    sortedList->next = NULL;
+
+    while (nonSortedList != NULL)
+    {
+        IndexTable *nonSortedTail = nonSortedList->next;
+        nonSortedList->next = NULL;
+        sortedList = insertIndexTableInSortedList(nonSortedList, sortedList);
+        nonSortedList = nonSortedTail;
+    }
+
+    ccs->indexTable = sortedList;
+}
+
 void
 fprintCCS( FILE *f, CostCentreStack *ccs )
 {