rts/parallel/ParTicky.c

   1 /* -------------------------------------------------------------------------
   2  *
   3  * (c) Hans-Wolfgang Loidl, 2000-
   4  *
   5  * Parallel ticky profiling, monitoring basic RTS operations in GUM.
   6  * Similar in structure to TICKY_TICKY profiling, but doesn't need a
   7  * separate way of building GHC.
   8  *-------------------------------------------------------------------------- */
   9
  10 #if defined(PAR) && defined(PAR_TICKY)
  11
  12 #include "Rts.h"
  13 #include "RtsFlags.h"
  14 #include "RtsUtils.h"
  15 //#include "StoragePriv.h"
  16 //#include "MBlock.h"
  17 //#include "Schedule.h"
  18 #include "GC.h"
  19 #include "Stats.h"
  20 #include "ParTicky.h"                       // ToDo: move into Rts.h
  21 #include "ParallelRts.h"
  22
  23 #if defined(PAR) && defined(HAVE_GETRUSAGE)
  24 #include <sys/resource.h>
  25 #endif
  26
  27 /* external data */
  28 extern double ElapsedTimeStart;
  29
  30 extern ullong GC_tot_alloc;
  31 extern ullong GC_tot_copied;
  32
  33 extern lnat MaxResidency;     /* in words; for stats only */
  34 extern lnat ResidencySamples; /* for stats only */
  35
  36 /* ngIplu' {Stats.c}vo' */
  37 #define BIG_STRING_LEN              512
  38
  39 /* ngIplu' {Ticky.c}vo' */
  40 #define INTAVG(a,b) ((b == 0) ? 0.0 : ((double) (a) / (double) (b)))
  41 #define PC(a)       (100.0 * a)
  42
  43 #define AVG(thing) \
  44         StgDouble avg##thing  = INTAVG(tot##thing,ctr##thing)
  45
  46
  47 #if 0
  48 void
  49 set_foo_time(double *x) {
  50   *x = usertime();
  51 }
  52
  53 double
  54 get_foo_time(double x) {
  55   fprintf(stderr, "get_foo_time: %7.2f (%7.5f,%7.5f) \n",
  56           usertime()-x,usertime(),x);
  57   return (usertime()-x);
  58 }
  59 #endif
  60
  61 static double start_time_GA = 0.0;
  62 static double start_mark = 0.0;
  63 static double start_pack = 0.0;
  64 static double start_unpack = 0.0;
  65
  66 void
  67 par_ticky_Par_start (void) {
  68 # if !defined(HAVE_GETRUSAGE) || irix_HOST_OS || defined(_WIN32)
  69     fprintf(stderr, "|| sorry don't have RUSAGE\n");
  70     return ;
  71 # else
  72     FILE *sf = RtsFlags.GcFlags.statsFile;
  73     struct rusage t;
  74     double utime, stime;
  75
  76     if (RtsFlags.GcFlags.giveStats>1 && sf != NULL) {
  77       getrusage(RUSAGE_SELF, &t);
  78
  79       utime = t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec;
  80       stime = t.ru_stime.tv_sec + 1e-6*t.ru_stime.tv_usec;
  81
  82       fprintf(stderr, "|| user time: %5.2f; system time: %5.2f\n",
  83               utime, stime);
  84       fprintf(stderr, "|| max RSS: %ld; int SM size: %ld; int USM data size: %ld; int USS size: %ld\n",
  85               t.ru_maxrss, t.ru_ixrss, t.ru_idrss, t.ru_isrss);
  86     }
  87 #endif
  88 }
  89
  90 #if 0
  91 FYI:
  92             struct rusage
  93             {
  94                  struct timeval ru_utime; /* user time used */
  95                  struct timeval ru_stime; /* system time used */
  96                  long ru_maxrss;          /* maximum resident set size */
  97                  long ru_ixrss;      /* integral shared memory size */
  98                  long ru_idrss;      /* integral unshared data size */
  99                  long ru_isrss;      /* integral unshared stack size */
 100                  long ru_minflt;          /* page reclaims */
 101                  long ru_majflt;          /* page faults */
 102                  long ru_nswap;      /* swaps */
 103                  long ru_inblock;         /* block input operations */
 104                  long ru_oublock;         /* block output operations */
 105                  long ru_msgsnd;          /* messages sent */
 106                  long ru_msgrcv;          /* messages received */
 107                  long ru_nsignals;        /* signals received */
 108                  long ru_nvcsw;      /* voluntary context switches */
 109                  long ru_nivcsw;          /* involuntary context switches */
 110             };
 111 #endif
 112
 113
 114 void
 115 par_ticky_rebuildGAtables_start(void) {
 116   // collect parallel global statistics (currently done together with GC stats)
 117   if (RtsFlags.ParFlags.ParStats.Global &&
 118       RtsFlags.GcFlags.giveStats > NO_GC_STATS) {
 119     //set_foo_time(&start_time_GA);
 120     start_time_GA = usertime();
 121   }
 122 }
 123
 124 void
 125 par_ticky_rebuildGAtables_end(nat n, nat size_GA) {
 126   // collect parallel global statistics (currently done together with GC stats)
 127   if (RtsFlags.ParFlags.ParStats.Global &&
 128       RtsFlags.GcFlags.giveStats > NO_GC_STATS) {
 129     static double foo = 0.0;
 130     foo = usertime() - start_time_GA; // get_foo_time(start_time_GA);
 131     globalParStats.cnt_rebuild_GA++;
 132     globalParStats.tot_rebuild_GA += n;
 133     if ( n > globalParStats.res_rebuild_GA )
 134       globalParStats.res_rebuild_GA = n;
 135     // fprintf(stderr, "rebuildGAtables: footime=%7.2f (%11.5f, %11.5f)\n",
 136     //    foo, usertime(), start_time_GA);
 137     globalParStats.time_rebuild_GA += foo;
 138     globalParStats.tot_size_GA += size_GA;
 139     if ( size_GA > globalParStats.res_size_GA )
 140       globalParStats.res_size_GA = size_GA;
 141   }
 142   // fprintf(stderr, ">> n: %d; size: %d;; tot: %d;  res: %d\n",
 143   //      n, size_GA, globalParStats.tot_size_GA, globalParStats.res_size_GA);
 144 }
 145
 146 void
 147 par_ticky_markLocalGAs_start(void) {
 148   // collect parallel global statistics (currently done together with GC stats)
 149   if (RtsFlags.ParFlags.ParStats.Global &&
 150       RtsFlags.GcFlags.giveStats > NO_GC_STATS) {
 151     start_time_GA = usertime();
 152   }
 153 }
 154
 155 void
 156 par_ticky_markLocalGAs_end(nat n) {
 157   // collect parallel global statistics (currently done together with GC stats)
 158   if (RtsFlags.ParFlags.ParStats.Global &&
 159       RtsFlags.GcFlags.giveStats > NO_GC_STATS) {
 160     globalParStats.cnt_mark_GA++;
 161     globalParStats.tot_mark_GA += n;
 162     if ( n > globalParStats.res_mark_GA )
 163       globalParStats.res_mark_GA = n;
 164     globalParStats.time_mark_GA += usertime() - start_time_GA;
 165   }
 166 }
 167
 168 void
 169 par_ticky_markSparkQueue_start(void) {
 170   // collect parallel global statistics (currently done together with GC stats)
 171   if (RtsFlags.ParFlags.ParStats.Global &&
 172       RtsFlags.GcFlags.giveStats > NO_GC_STATS) {
 173     start_mark=usertime();
 174   }
 175 }
 176
 177 void
 178 par_ticky_markSparkQueue_end(nat n) {
 179   // collect parallel global statistics (currently done together with GC stats)
 180   if (RtsFlags.ParFlags.ParStats.Global &&
 181       RtsFlags.GcFlags.giveStats > NO_GC_STATS) {
 182     globalParStats.time_sparks += usertime() - start_mark;
 183
 184     globalParStats.tot_sparks_marked += n;
 185     if ( n > globalParStats.res_sparks_marked )
 186       globalParStats.res_sparks_marked = n;
 187   }
 188 }
 189
 190 void
 191 par_ticky_PackNearbyGraph_start (void) {
 192   if (RtsFlags.ParFlags.ParStats.Global &&
 193       RtsFlags.GcFlags.giveStats > NO_GC_STATS) {
 194     start_pack=usertime();
 195   }
 196 }
 197
 198 void
 199 par_ticky_PackNearbyGraph_end(nat n, nat thunks) {
 200   // collect parallel global statistics (currently done together with GC stats)
 201   if (RtsFlags.ParFlags.ParStats.Global &&
 202       RtsFlags.GcFlags.giveStats > NO_GC_STATS) {
 203     globalParStats.time_pack += usertime() - start_pack;
 204
 205     globalParStats.tot_packets++;
 206     globalParStats.tot_packet_size += n;
 207     if ( n > globalParStats.res_packet_size )
 208       globalParStats.res_packet_size = n;
 209     globalParStats.tot_thunks += thunks;
 210     if ( thunks > globalParStats.res_thunks )
 211       globalParStats.res_thunks = thunks;
 212   }
 213 }
 214
 215 void
 216 par_ticky_UnpackGraph_start (void) {
 217   if (RtsFlags.ParFlags.ParStats.Global &&
 218       RtsFlags.GcFlags.giveStats > NO_GC_STATS) {
 219     start_unpack=usertime();
 220   }
 221 }
 222
 223 void
 224 par_ticky_UnpackGraph_end(nat n, nat thunks) {
 225   // collect parallel global statistics (currently done together with GC stats)
 226   if (RtsFlags.ParFlags.ParStats.Global &&
 227       RtsFlags.GcFlags.giveStats > NO_GC_STATS) {
 228     globalParStats.time_unpack += usertime() - start_unpack;
 229
 230     globalParStats.rec_packets++;
 231     globalParStats.rec_packet_size += n;
 232     /*
 233     if ( n > globalParStats.res_packet_size )
 234       globalParStats.res_packet_size = n;
 235     */
 236     globalParStats.rec_thunks += thunks;
 237     /*
 238     if ( thunks > globalParStats.res_thunks )
 239       globalParStats.res_thunks = thunks;
 240     */
 241   }
 242 }
 243
 244 void
 245 par_ticky_TP (void) {
 246     StgSparkPool *pool;
 247     nat tp_size, sp_size; // stats only
 248
 249     // Global stats gathering
 250     /* the spark pool for the current PE */
 251     pool = &(MainRegTable.rSparks); // generalise to cap = &MainRegTable
 252
 253     // Global statistics: residency of thread and spark pool
 254     if (RtsFlags.ParFlags.ParStats.Global &&
 255         RtsFlags.GcFlags.giveStats > NO_GC_STATS) {
 256       tp_size = run_queue_len() + 1; // add the TSO just poped
 257       // No: there may be many blocked threads being awoken at the same time
 258       // ASSERT(tp_size <= RtsFlags.ParFlags.maxThreads);
 259       globalParStats.tot_tp += tp_size;
 260       globalParStats.emp_tp += (tp_size==0) ? 1 : 0;
 261       globalParStats.cnt_tp++;
 262       if ( tp_size > globalParStats.res_tp)
 263         globalParStats.res_tp = tp_size;
 264       // fprintf(stderr, "run_queue_len() = %d (max %d)\n", run_queue_len(), globalParStats.res_tp);
 265       sp_size = spark_queue_len(pool);
 266       //ASSERT(sp_size <= RtsFlags.ParFlags.maxLocalSparks);
 267       globalParStats.tot_sp += sp_size;
 268       globalParStats.emp_sp += (sp_size==0) ? 1 : 0;
 269       globalParStats.cnt_sp++;
 270       if ( sp_size > globalParStats.res_sp)
 271         globalParStats.res_sp = sp_size;
 272       // fprintf(stderr, "spark_queue_len(pool) = %d (max %d)\n", spark_queue_len(pool), globalParStats.res_sp);
 273     }
 274 }
 275
 276 void
 277 globalParStat_exit(void)
 278 {
 279     FILE *sf = RtsFlags.GcFlags.statsFile;
 280     double time, etime;
 281
 282     /* print only if GC stats is enabled, too; i.e. -sstderr */
 283     if (!(RtsFlags.ParFlags.ParStats.Global &&
 284         RtsFlags.GcFlags.giveStats > NO_GC_STATS))
 285       return;
 286
 287     time = usertime();
 288     etime = elapsedtime() - ElapsedTimeStart;
 289     // fprintf(stderr, "foo=%7.2f\n", time);
 290
 291     if (sf != NULL){
 292         char temp[BIG_STRING_LEN];
 293
 294         // GC_tot_alloc += alloc;
 295         fprintf(sf,"\n");
 296
 297         fprintf(sf, "%11d threads created\n",
 298                 globalParStats.tot_threads_created);
 299         /*
 300           Would need to add a ++ to the par macro to use this
 301
 302         fprintf(sf, "%11d sparks created\n",
 303                 globalParStats.tot_sparks_created);
 304         fprintf(sf, "%11d sparks ignored\n",
 305                 globalParStats.tot_sparks_ignored);
 306         */
 307         ullong_format_string(globalParStats.res_tp, temp, rtsTrue/*commas*/);
 308         fprintf(sf, "%11s thread pool residency", temp);
 309         fprintf(sf, " (avg: %3.2f; %d times (%2.2f%%) of %d empty)\n",
 310                 (double)globalParStats.tot_tp/(double)globalParStats.cnt_tp,
 311                 globalParStats.emp_tp,
 312                 globalParStats.emp_tp*100.0/(double)globalParStats.cnt_tp,
 313                 globalParStats.cnt_tp);
 314         ullong_format_string(globalParStats.res_sp, temp, rtsTrue/*commas*/);
 315         fprintf(sf, "%11s spark pool residency", temp);
 316
 317         fprintf(sf, " (avg: %3.2f; %d times (%2.2f%%) of %d empty)\n",
 318                 (double)globalParStats.tot_sp/(double)globalParStats.cnt_sp,
 319                 globalParStats.emp_sp,
 320                 globalParStats.emp_sp*100.0/(double)globalParStats.cnt_sp,
 321                 globalParStats.cnt_sp);
 322         //ullong_format_string(globalParStats.tot_fishes, temp, rtsTrue/*commas*/);
 323         fprintf(sf, "%11d messages sent (%d fish, %d fetch, %d resume, %d schedule",
 324                 globalParStats.tot_fish_mess+globalParStats.tot_fetch_mess+
 325                 globalParStats.tot_resume_mess+globalParStats.tot_schedule_mess,
 326                 globalParStats.tot_fish_mess, globalParStats.tot_fetch_mess,
 327                 globalParStats.tot_resume_mess, globalParStats.tot_schedule_mess);
 328 #if defined(DIST)
 329         fprintf(sf, "%d revals", globalParStats.tot_reval_mess);
 330 #endif
 331         fprintf(sf,")\n");
 332         fprintf(sf, "%11d messages received (%d fish, %d fetch, %d resume, %d schedule",
 333                 globalParStats.rec_fish_mess+globalParStats.rec_fetch_mess+
 334                 globalParStats.rec_resume_mess+globalParStats.rec_schedule_mess,
 335                 globalParStats.rec_fish_mess, globalParStats.rec_fetch_mess,
 336                 globalParStats.rec_resume_mess, globalParStats.rec_schedule_mess);
 337 #if defined(DIST)
 338         fprintf(sf, "%d revals", globalParStats.rec_reval_mess);
 339 #endif
 340         fprintf(sf,")\n\n");
 341
 342         ullong_format_string(globalParStats.tot_size_GA*sizeof(W_), temp, rtsTrue/*commas*/);
 343         fprintf(sf, "%11s bytes of global heap in total ", temp);
 344         fprintf(sf, "(%5.2f%% of total allocated heap)\n",
 345                 globalParStats.tot_size_GA*sizeof(W_)*100.0/(double)GC_tot_alloc*sizeof(W_));
 346         ullong_format_string(globalParStats.res_size_GA*sizeof(W_), temp, rtsTrue/*commas*/);
 347         fprintf(sf, "%11s bytes global heap residency ", temp);
 348         fprintf(sf, "(%5.2f%% of max heap residency)\n",
 349                 globalParStats.res_size_GA*sizeof(W_)*100.0/(double)MaxResidency*sizeof(W_));
 350
 351         //ullong_format_string(globalParStats.res_mark_GA, temp, rtsTrue/*commas*/);
 352         //fprintf(sf, "%11s GAs residency in GALA table ", temp);
 353         // ullong_format_string(globalParStats.tot_mark_GA, temp, rtsTrue/*commas*/);
 354         //fprintf(sf, "(avg %5.2f; %d samples)\n",
 355         //      (double)globalParStats.tot_mark_GA/(double)globalParStats.cnt_mark_GA,
 356         //      globalParStats.cnt_mark_GA);
 357
 358         ullong_format_string(globalParStats.local_alloc_GA, temp, rtsTrue/*commas*/);
 359         fprintf(sf, "%11s GAs locally allocated (calls to makeGlobal)\n", temp);
 360
 361         ullong_format_string(globalParStats.tot_rebuild_GA, temp, rtsTrue/*commas*/);
 362         fprintf(sf, "%11s live GAs in total (after rebuilding tables)\n", temp);
 363         ullong_format_string(globalParStats.res_rebuild_GA, temp, rtsTrue/*commas*/);
 364         fprintf(sf, "%11s GAs residency (after rebuilding tables) ", temp);
 365         fprintf(sf, "(avg %5.2f; %d samples)\n",
 366                 (double)globalParStats.tot_rebuild_GA/(double)globalParStats.cnt_rebuild_GA,
 367                 globalParStats.cnt_rebuild_GA);
 368         ullong_format_string(globalParStats.res_free_GA, temp, rtsTrue/*commas*/);
 369         fprintf(sf, "%11s residency of freeing GAs", temp);
 370         fprintf(sf, " (avg %5.2f; %d samples)\n",
 371                 (double)globalParStats.tot_free_GA/(double)globalParStats.cnt_free_GA,
 372                 globalParStats.cnt_free_GA);
 373
 374         fprintf(sf, "%11.2fs spent marking GAs (%7.2f%% of %7.2fs)\n",
 375                 globalParStats.time_mark_GA,
 376                 globalParStats.time_mark_GA*100./time, time);
 377         fprintf(sf, "%11.2fs spent rebuilding GALA tables (%7.2f%% of %7.2fs; %7.2f%% of %7.2fs)\n",
 378                 globalParStats.time_rebuild_GA,
 379                 globalParStats.time_rebuild_GA*100./time, time,
 380                 globalParStats.time_rebuild_GA*100./etime, etime);
 381
 382         ullong_format_string(globalParStats.tot_sparks_marked, temp, rtsTrue/*commas*/);
 383         fprintf(sf, "%11s sparks marked\t", temp);
 384         ullong_format_string(globalParStats.res_sparks_marked, temp, rtsTrue/*commas*/);
 385         fprintf(sf, "%6s spark mark residency\n", temp);
 386         fprintf(sf, "%11.2fs spent marking sparks (%7.2f%% of %7.2fs; %7.2f%% of %7.2fs elapsed)\n",
 387                 globalParStats.time_sparks,
 388                 globalParStats.time_sparks*100./time, time,
 389                 globalParStats.time_sparks*100./etime, etime);
 390
 391         fprintf(sf,"\n");
 392
 393         ullong_format_string(globalParStats.tot_packets, temp, rtsTrue/*commas*/);
 394         fprintf(sf, "%11s packets sent\n", temp);
 395         ullong_format_string(globalParStats.tot_packet_size, temp, rtsTrue/*commas*/);
 396         fprintf(sf, "%11s bytes of graph sent in total (max %d; avg %.2f)\n",
 397                 temp, globalParStats.res_packet_size,
 398                 (double)globalParStats.tot_packet_size/(double)globalParStats.tot_packets);
 399         ullong_format_string(globalParStats.tot_thunks, temp, rtsTrue/*commas*/);
 400         fprintf(sf, "%11s thunks sent in total (max %d; avg %.2f)\n",
 401                 temp, globalParStats.res_thunks,
 402                 (double)globalParStats.tot_thunks/(double)globalParStats.tot_packets);
 403         fprintf(sf, "%11.2fs spent packing graph structures (%7.2f%% of %7.2fs; %7.2f%% of %7.2fs elapsed)\n",
 404                 globalParStats.time_pack,
 405                 globalParStats.time_pack*100./time, time,
 406                 globalParStats.time_pack*100./etime, etime);
 407
 408         ullong_format_string(globalParStats.rec_packets, temp, rtsTrue/*commas*/);
 409         fprintf(sf, "%11s packets received\n", temp);
 410         ullong_format_string(globalParStats.rec_packet_size, temp, rtsTrue/*commas*/);
 411         fprintf(sf, "%11s bytes of graph received in total (max %d; avg %.2f)\n",
 412                 temp, globalParStats.rec_res_packet_size,
 413                 (double)globalParStats.rec_packet_size/(double)globalParStats.rec_packets);
 414         ullong_format_string(globalParStats.rec_thunks, temp, rtsTrue/*commas*/);
 415         fprintf(sf, "%11s thunks received in total (max %d; avg %.2f)\n",
 416                 temp, globalParStats.rec_res_thunks,
 417                 (double)globalParStats.rec_thunks/(double)globalParStats.rec_packets);
 418         fprintf(sf, "%11.2fs spent unpacking graph structures (%7.2f%% of %7.2fs; %7.2f%% of %7.2fs elapsed)\n",
 419                 globalParStats.time_unpack,
 420                 globalParStats.time_unpack*100./time, time,
 421                 globalParStats.time_unpack*100./etime, etime);
 422
 423         fprintf(sf,"\n");
 424
 425         ullong_format_string(globalParStats.tot_arrs, temp, rtsTrue/*commas*/);
 426         fprintf(sf, "%11s bytearrays sent; ", temp);
 427         ullong_format_string(globalParStats.tot_arr_size, temp, rtsTrue/*commas*/);
 428         fprintf(sf, " %s bytes in total (avg %.2f)\n",
 429                 temp,
 430                 (double)globalParStats.tot_arr_size/(double)globalParStats.tot_arrs);
 431
 432         fprintf(sf,"\n");
 433
 434         fprintf(sf, "%11d yields, %d stack overflows, %d heap overflows\n",
 435                 globalParStats.tot_yields, globalParStats.tot_stackover,
 436                 globalParStats.tot_heapover);
 437
 438         fprintf(sf,"\n");
 439
 440         //fprintf(stderr, "Printing this pathetic statistics took %7.2fs (start @ %7.2f)\n",
 441         //      usertime()-time, time);
 442
 443         fflush(sf);
 444         // Open filehandle needed by other stats printing fcts
 445         // fclose(sf);
 446     }
 447 }
 448
 449 #endif
 450