rtinst/src/RTunix.c

   1 /*
   2  * This file contains the implementation of runtime dynamic instrumentation
   3  *   functions for a processor running UNIX.
   4  *
   5  * $Log: RTunix.c,v $
   6  * Revision 1.22  1995/02/16 09:07:33  markc
   7  * Made Boolean type RT_Boolean to prevent picking up a different boolean
   8  * definition.
   9  *
  10  * Revision 1.21  1994/11/11  10:39:14  markc
  11  * Commented out non-emergency printfs
  12  *
  13  * Revision 1.20  1994/10/09  21:26:05  hollings
  14  * Fixed cycles to time conversion.
  15  *
  16  * Revision 1.19  1994/09/20  18:26:51  hollings
  17  * added DYNINSTcyclesPerSecond to get cost values no matter the clock speed.
  18  *
  19  * removed a race condition in DYNINSTcyclesPerSecond.
  20  *
  21  * Revision 1.18  1994/08/22  16:05:37  markc
  22  * Removed lastValue array.
  23  * Added lastValue variable to timer structure.
  24  * Added error messages for timer regression.
  25  * Removed lastValue array.
  26  * Added lastValue variable to timer structure.
  27  * Added error messages for timer regression.
  28  *
  29  * Revision 1.17  1994/08/17  17:16:45  markc
  30  * Increased the size of the lastValue and lastTime arrays.  lastValue is
  31  * referenced by the timer id, which can be greater than 200.  There should
  32  * be some way of enforcing a limit between paradynd and rtinst.
  33  *
  34  * Revision 1.16  1994/08/02  18:18:57  hollings
  35  * added code to save/restore FP state on entry/exit to signal handle
  36  * (really jcargill, but commited by hollings).
  37  *
  38  * changed comparisons on time regression to use 64 bit int compares rather
  39  * than floats to prevent fp rounding error from causing false alarms.
  40  *
  41  * Revision 1.15  1994/07/26  20:04:48  hollings
  42  * removed slots used variables.
  43  *
  44  * Revision 1.14  1994/07/22  19:24:54  hollings
  45  * added actual paused time for CM-5.
  46  *
  47  * Revision 1.13  1994/07/16  03:39:31  hollings
  48  * stopped using assembly version of clocks (temporary).
  49  *
  50  * Revision 1.12  1994/07/14  23:35:36  hollings
  51  * added return of cost model record.
  52  *
  53  * Revision 1.11  1994/07/11  22:47:51  jcargill
  54  * Major CM5 commit: include syntax changes, some timer changes, removal
  55  * of old aggregation code, old pause code, added signal-driven sampling
  56  * within node processes
  57  *
  58  * Revision 1.10  1994/07/05  03:25:11  hollings
  59  * obsereved cost model.
  60  *
  61  * Revision 1.9  1994/05/18  00:53:28  hollings
  62  * added flush's after error printfs to force data out pipes on the way
  63  * to paradyn.
  64  *
  65  * Revision 1.8  1994/04/07  01:21:30  markc
  66  * Cleaned up writes.  Writes interrupted by system calls get retried, others
  67  * do not.
  68  *
  69  * Revision 1.7  1994/03/25  16:03:11  markc
  70  * Added retry to write which could be interrupted by a signal.
  71  *
  72  * Revision 1.6  1994/02/16  00:07:24  hollings
  73  * Added a default sampling interval of 500msec.  Previous default was not
  74  * to collect any data.
  75  *
  76  * Revision 1.5  1994/02/02  00:46:14  hollings
  77  * Changes to make it compile with the new tree.
  78  *
  79  * Revision 1.4  1993/12/13  19:48:12  hollings
  80  * force records to be word aligned.
  81  *
  82  * Revision 1.3  1993/10/19  15:29:58  hollings
  83  * new simpler primitives.
  84  *
  85  * Revision 1.2  1993/08/26  19:43:17  hollings
  86  * added uarea mapping code.
  87  *
  88  * Revision 1.1  1993/07/02  21:49:35  hollings
  89  * Initial revision
  90  *
  91  *
  92  */
  93 #include <stdio.h>
  94 #include <string.h>
  95 #include <sys/time.h>
  96 #include <sys/resource.h>
  97 #include <sys/param.h>
  98 #include <signal.h>
  99 #include <errno.h>
 100 #include <fcntl.h>
 101 #include <assert.h>
 102 #include <nlist.h>
 103 #include <unistd.h>
 104
 105 #include "kludges.h"
 106 #include "rtinst/h/rtinst.h"
 107 #include "rtinst/h/trace.h"
 108
 109 #define MILLION 1000000
 110 extern int DYNINSTmappedUarea;
 111 extern float DYNINSTcyclesToUsec;
 112 extern int DYNINSTnumReported;
 113 extern int DYNINSTtotalAlaramExpires;
 114 extern int DYNINSTtotalSamples;
 115 extern float DYNINSTsamplingRate;
 116 extern time64 DYNINSTtotalSampleTime;
 117 extern time64 DYNINSTlastCPUTime;
 118 extern time64 DYNINSTlastWallTime;
 119
 120
 121 FILE *DYNINSTtraceFp;
 122 tTimer DYNINSTelapsedTime;
 123 tTimer DYNINSTelapsedCPUTime;
 124 int64 DYNINSTgetObservedCycles(RT_Boolean);
 125 time64 DYNINSTtotalSampleTime;
 126 int64 DYNINSTgetObservedCycles();
 127
 128 /* clockWord must be volatile becuase it changes on clock interrups.
 129  *    -- added volatile jkh 7/3/94
 130  *
 131  */
 132 typedef volatile unsigned int clockWord;
 133 extern clockWord *_p_1, *_p_2;
 134
 135 /*
 136  * Missing stuff.
 137  *
 138  */
 139 extern int getrusage(int who, struct rusage *rusage);
 140
 141 /*
 142  * return cpuTime in useconds.
 143  *
 144  */
 145 time64 DYNINSTgetCPUtime()
 146 {
 147      time64 now;
 148      struct rusage ru;
 149
 150      getrusage(RUSAGE_SELF, &ru);
 151      now = ru.ru_utime.tv_sec;
 152      now *= MILLION;
 153      now += ru.ru_utime.tv_usec;
 154
 155      return(now);
 156 }
 157
 158 time64 DYNINSTgetWallTime()
 159 {
 160      time64 now;
 161      struct timeval tv;
 162
 163      gettimeofday(&tv, NULL);
 164      now = tv.tv_sec;
 165      now *= (time64) MILLION;
 166      now += tv.tv_usec;
 167
 168      return(now);
 169 }
 170
 171 inline time64 DYNINSTgetUserTime()
 172 {
 173     int first;
 174     time64 now;
 175
 176     if (DYNINSTmappedUarea) {
 177 retry:
 178          first = *_p_1;
 179          now = first;
 180          now *= MILLION;
 181          now += *_p_2;
 182          if (*_p_1 != first) goto retry;
 183      } else {
 184          now = DYNINSTgetCPUtime();
 185      }
 186      return(now);
 187 }
 188
 189
 190 void DYNINSTbreakPoint()
 191 {
 192 /*     printf ("Process %d about to stop self...\n", getpid()); */
 193 /*     fflush (stdout); */
 194     kill(getpid(), SIGSTOP);
 195 /*     printf ("Process %d has been restarted...\n", getpid()); */
 196 /*     fflush (stdout); */
 197 }
 198
 199 void DYNINSTstartProcessTimer(tTimer *timer)
 200 {
 201     time64 temp;
 202
 203     if (timer->counter == 0) {
 204          temp = DYNINSTgetUserTime();
 205          timer->start = temp;
 206          timer->normalize = MILLION;
 207     }
 208     /* this must be last to prevent race conditions */
 209     timer->counter++;
 210 }
 211
 212 void DYNINSTstopProcessTimer(tTimer *timer)
 213 {
 214     time64 now;
 215     struct rusage ru;
 216
 217     /* don't stop a counter that is not running */
 218     if (!timer->counter) return;
 219
 220
 221     /* Warning - there is a window between setting now, and mutex that
 222           can cause time to go backwards by the time to execute the
 223           instructions between these two points.  This is not a cummlative error
 224           and should not affect samples.  This was done (rather than re-sampling
 225           now because the cost of computing now is so high).
 226     */
 227     if (timer->counter == 1) {
 228         now = DYNINSTgetUserTime();
 229         timer->snapShot = now - timer->start + timer->total;
 230         timer->mutex = 1;
 231         timer->counter = 0;
 232         /* This next line can have the race condition. */
 233         /* timer->total = timer->snapShot; */
 234         timer->total = DYNINSTgetUserTime() - timer->start + timer->total;
 235         timer->mutex = 0;
 236         if (now < timer->start) {
 237              getrusage(RUSAGE_SELF, &ru);
 238              printf("end before start\n");
 239              fflush(stdout);
 240              sigpause(0xffff);
 241         }
 242     } else {
 243         timer->counter--;
 244     }
 245 }
 246
 247
 248 void DYNINSTstartWallTimer(tTimer *timer)
 249 {
 250     struct timeval tv;
 251
 252     if (timer->counter == 0) {
 253          gettimeofday(&tv, NULL);
 254          timer->start = tv.tv_sec;
 255          timer->start *= (time64) MILLION;
 256          timer->start += tv.tv_usec;
 257          timer->normalize = MILLION;
 258     }
 259     /* this must be last to prevent race conditions */
 260     timer->counter++;
 261 }
 262
 263 void DYNINSTstopWallTimer(tTimer *timer)
 264 {
 265     time64 now;
 266     struct timeval tv;
 267
 268     /* don't stop a counter that is not running */
 269     if (!timer->counter) return;
 270
 271     if (timer->counter == 1) {
 272          gettimeofday(&tv, NULL);
 273          now = tv.tv_sec;
 274          now *= MILLION;
 275          now += tv.tv_usec;
 276          /* see note before StopProcess time for warning about this mutex */
 277          timer->snapShot = timer->total + now - timer->start;
 278          timer->mutex = 1;
 279          timer->counter = 0;
 280          timer->total = timer->snapShot;
 281          timer->mutex = 0;
 282     } else {
 283         timer->counter--;
 284     }
 285 }
 286
 287 time64 startWall;
 288
 289 volatile int DYNINSTpauseDone = 0;
 290
 291 /*
 292  * change the variable to let the process proceed.
 293  *
 294  */
 295 void DYNINSTcontinueProcess()
 296 {
 297     DYNINSTpauseDone = 1;
 298 }
 299
 300 #ifdef notdef
 301 int DYNINSTbufsiz;
 302 int DYNINSTprofile;
 303 #endif
 304
 305 /*
 306  * pause the process and let only USR2 signal handlers run until a SIGUSR1.
 307  *    arrives.
 308  *
 309  */
 310 void DYNINSTpauseProcess()
 311 {
 312     int mask;
 313     int sigs;
 314
 315     sigs = ((1 << (SIGUSR2-1)) | (1 << (SIGUSR1-1)) | (1 << (SIGTSTP-1)));
 316     mask = ~sigs;
 317     DYNINSTpauseDone = 0;
 318     while (!DYNINSTpauseDone) {
 319 #ifdef notdef
 320        sigpause(mask);
 321        /* temporary busy wait until we figure out what the TSD is up to.  */
 322        printf("out of sigpuase\n");
 323 #endif
 324     }
 325 }
 326
 327
 328 void DYNINSTinit(int skipBreakpoint)
 329 {
 330     int val;
 331     char *interval;
 332     struct sigvec alarmVector;
 333     extern int DYNINSTmapUarea();
 334     extern float DYNINSTcyclesPerSecond();
 335     extern void DYNINSTalarmExpire();
 336
 337     startWall = 0;
 338
 339     /*
 340      * clear global base tramp and cycle counters.
 341      *
 342      */
 343 #ifdef notdef
 344     asm("mov 0, %g7");
 345 #endif
 346
 347     /* init these before the first alarm can expire */
 348     DYNINSTcyclesToUsec = (1.0/DYNINSTcyclesPerSecond()) * 1000000;
 349     DYNINSTlastCPUTime = DYNINSTgetCPUtime();
 350     DYNINSTlastWallTime = DYNINSTgetWallTime();
 351
 352     /* define the alarm signal vector. We block all signals while sampling.
 353      *  This prevents race conditions where signal handlers cause timers to
 354      *  be started and stopped.
 355      */
 356     alarmVector.sv_handler = DYNINSTalarmExpire;
 357     alarmVector.sv_mask = ~0;
 358     alarmVector.sv_flags = 0;
 359
 360     sigvec(SIGALRM, &alarmVector, NULL);
 361
 362     /* All the signal-initiating stuff is now in the paradynd. */
 363
 364     /* default is 500msec */
 365     val = 500000;
 366     interval = (char *) getenv("DYNINSTsampleInterval");
 367     if (interval) {
 368         val = atoi(interval);
 369     }
 370     DYNINSTsamplingRate = val/1000000.0;
 371     sigvec(SIGALRM, &alarmVector, NULL);
 372     ualarm(val, val);
 373
 374     DYNINSTmappedUarea = DYNINSTmapUarea();
 375
 376     /*
 377      * pause the process and wait for additional info.
 378      *
 379      */
 380     printf("Time at main %f\n", ((float) DYNINSTgetCPUtime())/1000000.0);
 381     if (!skipBreakpoint) DYNINSTbreakPoint();
 382
 383     DYNINSTstartWallTimer(&DYNINSTelapsedTime);
 384     DYNINSTstartProcessTimer(&DYNINSTelapsedCPUTime);
 385
 386 }
 387
 388
 389 void DYNINSTexit()
 390 {
 391 }
 392
 393 static int pipeGone;
 394
 395 /*
 396  * generate a trace record onto the named stream.
 397  *
 398  */
 399 void DYNINSTgenerateTraceRecord(traceStream sid, short type, short length,
 400     void *eventData, int flush)
 401 {
 402     int ret;
 403     int count;
 404     struct timeval tv;
 405     char buffer[1024];
 406     traceHeader header;
 407
 408     if (pipeGone) return;
 409
 410     gettimeofday(&tv, NULL);
 411     header.wall = tv.tv_sec;
 412     header.wall *= (time64) MILLION;
 413     header.wall += tv.tv_usec;
 414     header.wall -= startWall;
 415
 416 #ifdef notdef
 417     if (DYNINSTmappedUarea) {
 418         header.process = *_p_1;
 419         header.process *= MILLION;
 420         header.process += *_p_2;
 421     } else {
 422 #endif
 423         header.process = DYNINSTgetCPUtime();
 424 #ifdef notdef
 425     }
 426 #endif
 427
 428     /* round length off to a word aligned unit */
 429     length = ALIGN_TO_WORDSIZE(length);
 430
 431     header.type = type;
 432     header.length = length;
 433     count = 0;
 434     memcpy(&buffer[count], &sid, sizeof(traceStream));
 435     count += sizeof(traceStream);
 436
 437     memcpy(&buffer[count], &header, sizeof(header));
 438     count += sizeof(header);
 439
 440     count = ALIGN_TO_WORDSIZE(count);
 441     memcpy(&buffer[count], eventData, length);
 442     count += length;
 443
 444     /* on this platorm, we have a pipe to the controller process */
 445     errno = 0;
 446
 447     if (!DYNINSTtraceFp || (type == TR_EXIT)) {
 448         DYNINSTtraceFp = fdopen(dup(CONTROLLER_FD), "w");
 449     }
 450     ret = fwrite(buffer, count, 1, DYNINSTtraceFp);
 451     if (ret != 1) {
 452         extern char *sys_errlist[];
 453         printf("unable to write trace record %s\n", sys_errlist[errno]);
 454         printf("disabling further data logging, pid=%d\n", getpid());
 455         fflush(stdout);
 456         /* pipeGone = True; */
 457     }
 458     if (flush) DYNINSTflushTrace();
 459 }
 460
 461 void DYNINSTflushTrace()
 462 {
 463     if (DYNINSTtraceFp) fflush(DYNINSTtraceFp);
 464 }
 465
 466 /* time64 lastValue[10000]; */
 467 double lastTime[200];
 468
 469 void DYNINSTreportTimer(tTimer *timer)
 470 {
 471     time64 now;
 472     time64 total;
 473     struct timeval tv;
 474     traceSample sample;
 475
 476     if (timer->mutex) {
 477         total = timer->snapShot;
 478     } else if (timer->counter) {
 479         /* timer is running */
 480         if (timer->type == processTime) {
 481             /* now = DYNINSTgetCPUtime(); */
 482             /* use mapped time if available */
 483             now = DYNINSTgetUserTime();
 484         } else {
 485             gettimeofday(&tv, NULL);
 486             now = tv.tv_sec;
 487             now *= MILLION;
 488             now += tv.tv_usec;
 489         }
 490         total = now - timer->start + timer->total;
 491     } else {
 492         total = timer->total;
 493     }
 494     if (total < timer->lastValue) {
 495          if (timer->type == processTime) {
 496              printf("process ");
 497          } else {
 498              printf("wall ");
 499          }
 500          printf("time regressed timer %d, total = %f, last = %f\n",
 501              timer->id.id, (float) total, (float) timer->lastValue);
 502         if (timer->counter) {
 503             printf("timer was active\n");
 504         } else {
 505             printf("timer was inactive\n");
 506         }
 507         printf("mutex=%d, counter=%d, sampled=%d, snapShot=%f\n\n",
 508                (int)timer->mutex, (int)timer->counter, (int)timer->sampled,
 509                (double) timer->snapShot);
 510         printf("now = %f\n start = %f\n total = %f\n",
 511                (double) now, (double) timer->start, (double) timer->total);
 512         fflush(stdout);
 513         sigpause(0xffff);
 514     }
 515     timer->lastValue = total;
 516
 517     sample.id = timer->id;
 518     sample.value = ((double) total) / (double) timer->normalize;
 519     DYNINSTtotalSamples++;
 520
 521     DYNINSTgenerateTraceRecord(0, TR_SAMPLE, sizeof(sample), &sample, 0);
 522     /* printf("raw sample %d = %f\n", sample.id.id, sample.value); */
 523 }
 524
 525 void DYNINSTfork(void *arg, int pid)
 526 {
 527     int sid = 0;
 528     traceFork forkRec;
 529
 530     printf("fork called with pid = %d\n", pid);
 531     fflush(stdout);
 532     if (pid > 0) {
 533         forkRec.ppid = getpid();
 534         forkRec.pid = pid;
 535         forkRec.npids = 1;
 536         forkRec.stride = 0;
 537         DYNINSTgenerateTraceRecord(sid,TR_FORK,sizeof(forkRec), &forkRec, 1);
 538     } else {
 539         /* set up signals and stop at a break point */
 540         DYNINSTinit(1);
 541         sigpause(0);
 542     }
 543 }
 544
 545
 546 void DYNINSTprintCost()
 547 {
 548     FILE *fp;
 549     time64 now;
 550     int64 value;
 551     struct rusage ru;
 552     struct endStatsRec stats;
 553
 554     DYNINSTstopProcessTimer(&DYNINSTelapsedCPUTime);
 555     DYNINSTstopWallTimer(&DYNINSTelapsedTime);
 556
 557     value = DYNINSTgetObservedCycles(0);
 558     stats.instCycles = value;
 559
 560     value *= DYNINSTcyclesToUsec;
 561
 562     stats.alarms = DYNINSTtotalAlaramExpires;
 563     stats.numReported = DYNINSTnumReported;
 564     stats.instTime = ((double) value)/1000000.0;
 565     stats.handlerCost = ((double) DYNINSTtotalSampleTime)/1000000.0;
 566
 567     now = DYNINSTgetCPUtime();
 568     stats.totalCpuTime = ((double) DYNINSTelapsedCPUTime.total)/MILLION;
 569     stats.totalWallTime = ((double) DYNINSTelapsedTime.total/MILLION);
 570
 571     stats.samplesReported = DYNINSTtotalSamples;
 572     stats.samplingRate = DYNINSTsamplingRate;
 573
 574     stats.userTicks = 0;
 575     stats.instTicks = 0;
 576
 577     fp = fopen("stats.out", "w");
 578
 579 #ifdef notdef
 580     if (DYNINSTprofile) {
 581         int i;
 582         int limit;
 583         int pageSize;
 584         int startInst;
 585         extern void DYNINSTreportCounter();
 586
 587
 588         limit = DYNINSTbufsiz/sizeof(short);
 589         /* should really be _DYNINSTendUserCode */
 590         startInst = (int) &DYNINSTreportCounter;
 591         fprintf(fp, "startInst = %x\n", startInst);
 592         for (i=0; i < limit; i++) {
 593             if (DYNINSTprofBuffer[i])
 594                 fprintf(fp, "%x %d\n", i*2, DYNINSTprofBuffer[i]);
 595             if (i * 2 > startInst) {
 596                 stats.instTicks += DYNINSTprofBuffer[i];
 597             } else {
 598                 stats.userTicks += DYNINSTprofBuffer[i];
 599             }
 600         }
 601
 602         /* fwrite(DYNINSTprofBuffer, DYNINSTbufsiz, 1, fp); */
 603         fprintf(fp, "stats.instTicks %d\n", stats.instTicks);
 604         fprintf(fp, "stats.userTicks %d\n", stats.userTicks);
 605
 606     }
 607 #endif
 608     getrusage(RUSAGE_SELF, &ru);
 609
 610     fprintf(fp, "DYNINSTtotalAlaramExpires %d\n", stats.alarms);
 611     fprintf(fp, "DYNINSTnumReported %d\n", stats.numReported);
 612     fprintf(fp,"Raw cycle count = %f\n", (double) stats.instCycles);
 613     fprintf(fp,"Total instrumentation cost = %f\n", stats.instTime);
 614     fprintf(fp,"Total handler cost = %f\n", stats.handlerCost);
 615     fprintf(fp,"Total cpu time of program %f\n", stats.totalCpuTime);
 616     fprintf(fp,"Total system time of program %f\n",
 617          ru.ru_stime.tv_sec * 1000000.0 + ru.ru_stime.tv_usec);
 618     fprintf(fp,"Elapsed wall time of program %f\n",
 619         stats.totalWallTime/1000000.0);
 620     fprintf(fp,"total data samples %d\n", stats.samplesReported);
 621     fprintf(fp,"sampling rate %f\n", stats.samplingRate);
 622     fprintf(fp,"Application program ticks %d\n", stats.userTicks);
 623     fprintf(fp,"Instrumentation ticks %d\n", stats.instTicks);
 624
 625     fclose(fp);
 626
 627     /* record that we are done -- should be somewhere better. */
 628     DYNINSTgenerateTraceRecord(0, TR_EXIT, sizeof(stats), &stats, 1);
 629 }
 630
 631
 632 /*
 633  * These are null routines for Unix: signal handler semantics
 634  * guarantee that the FPU state is saved/restored.  Not so on CM5 nodes!
 635  */
 636
 637 void saveFPUstate(float *base)
 638 {
 639 }
 640
 641
 642 void restoreFPUstate(float *base)
 643 {
 644 }
 645
 646
 647 /*
 648  * If we can't read it, try to guess it.
 649  */
 650 static float guessClock()
 651 {
 652     return(0.0);
 653 }
 654
 655 #define PATTERN "\tclock-frequency:"
 656 /*
 657  * find the number of cycles per second on this machine.
 658  */
 659 float DYNINSTcyclesPerSecond()
 660 {
 661     FILE *fp;
 662     char *ptr;
 663     int speed;
 664     char line[80];
 665
 666     fp = popen("/usr/etc/devinfo -vp", "r");
 667     if (!fp) {
 668         /* can't run command so guess the clock rate. */
 669     } else {
 670         while (fgets(line, sizeof(line), fp)) {
 671             if (!strncmp(PATTERN, line, strlen(PATTERN))) {
 672                 ptr = strchr(line, ' ');
 673                 if (!ptr) return(guessClock());
 674                 speed = strtol(ptr, NULL, 16);
 675                 break;
 676             }
 677         }
 678     }
 679     pclose(fp);
 680     /* printf(line, "Clock = %d\n", speed); */
 681     return(speed);
 682 }