obsereved cost model.
[dyninst.git] / 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.10  1994/07/05 03:25:11  hollings
7  * obsereved cost model.
8  *
9  * Revision 1.9  1994/05/18  00:53:28  hollings
10  * added flush's after error printfs to force data out pipes on the way
11  * to paradyn.
12  *
13  * Revision 1.8  1994/04/07  01:21:30  markc
14  * Cleaned up writes.  Writes interrupted by system calls get retried, others
15  * do not.
16  *
17  * Revision 1.7  1994/03/25  16:03:11  markc
18  * Added retry to write which could be interrupted by a signal.
19  *
20  * Revision 1.6  1994/02/16  00:07:24  hollings
21  * Added a default sampling interval of 500msec.  Previous default was not
22  * to collect any data.
23  *
24  * Revision 1.5  1994/02/02  00:46:14  hollings
25  * Changes to make it compile with the new tree.
26  *
27  * Revision 1.4  1993/12/13  19:48:12  hollings
28  * force records to be word aligned.
29  *
30  * Revision 1.3  1993/10/19  15:29:58  hollings
31  * new simpler primitives.
32  *
33  * Revision 1.2  1993/08/26  19:43:17  hollings
34  * added uarea mapping code.
35  *
36  * Revision 1.1  1993/07/02  21:49:35  hollings
37  * Initial revision
38  *
39  *
40  */
41 #include <stdio.h>
42 #include <sys/time.h>
43 #include <sys/resource.h>
44 #include <sys/param.h>
45 #include <signal.h>
46 #include <errno.h>
47 #include <fcntl.h>
48 #include <assert.h>
49 #include <nlist.h>
50 #include <unistd.h>
51
52 #include "rtinst/h/rtinst.h"
53 #include "rtinst/h/trace.h"
54
55 #define MILLION 1000000
56 extern int DYNINSTmappedUarea;
57 extern float DYNINSTcyclesToUsec;
58 time64 DYNINSTtotalSampleTime;
59 int64 DYNINSTgetObservedCycles();
60
61 /* clockWord must be volatile becuase it changes on clock interrups. 
62  *    -- added volatile jkh 7/3/94
63  *
64  */
65 typedef volatile unsigned int clockWord;
66 extern clockWord *_p_1, *_p_2;
67
68 /*
69  * Missing stuff.
70  *
71  */
72 extern int getrusage(int who, struct rusage *rusage);
73
74 /*
75  * return cpuTime in useconds.
76  *
77  */
78 time64 DYNINSTgetCPUtime()
79 {
80      time64 now;
81      struct rusage ru;
82
83      getrusage(RUSAGE_SELF, &ru);
84      now = ru.ru_utime.tv_sec;
85      now *= MILLION;
86      now += ru.ru_utime.tv_usec;
87
88      return(now);
89 }
90
91 inline time64 DYNINSTgetUserTime()
92 {
93     int first;
94     time64 now;
95
96     if (DYNINSTmappedUarea) {
97 retry:
98          first = *_p_1;
99          now = first;
100          now *= MILLION;
101          now += *_p_2;
102          if (*_p_1 != first) goto retry;
103      } else {
104          now = DYNINSTgetCPUtime();
105      }
106      return(now);
107 }
108
109 void DYNINSTbreakPoint()
110 {
111     kill(getpid(), SIGSTOP);
112 }
113
114 void DYNINSTstartProcessTimer(tTimer *timer)
115 {
116     time64 temp;
117
118     if (timer->counter == 0) {
119          temp = DYNINSTgetUserTime();
120          timer->start = temp;
121          timer->normalize = MILLION;
122     }
123     /* this must be last to prevent race conditions */
124     timer->counter++;
125 }
126
127 void DYNINSTstopProcessTimer(tTimer *timer)
128 {
129     time64 now;
130     struct rusage ru;
131
132     /* don't stop a counter that is not running */
133     if (!timer->counter) return;
134
135
136     /* Warning - there is a window between setting now, and mutex that
137           can cause time to go backwards by the time to execute the
138           instructions between these two points.  This is not a cummlative error
139           and should not affect samples.  This was done (rather than re-sampling
140           now because the cost of computing now is so high).
141     */
142     if (timer->counter == 1) {
143         now = DYNINSTgetUserTime();
144         timer->snapShot = now - timer->start + timer->total;
145         timer->mutex = 1;
146         timer->counter = 0;
147         timer->total = timer->snapShot;
148         timer->mutex = 0;
149         if (now < timer->start) {
150              getrusage(RUSAGE_SELF, &ru);
151              printf("end before start\n");
152              fflush(stdout);
153              sigpause(0xffff);
154         }
155     } else {
156         timer->counter--;
157     }
158 }
159
160
161 void DYNINSTstartWallTimer(tTimer *timer)
162 {
163     struct timeval tv;
164
165     if (timer->counter == 0) {
166          gettimeofday(&tv, NULL);
167          timer->start = tv.tv_sec;
168          timer->start *= (time64) MILLION;
169          timer->start += tv.tv_usec;
170          timer->normalize = MILLION;
171     }
172     /* this must be last to prevent race conditions */
173     timer->counter++;
174 }
175
176 void DYNINSTstopWallTimer(tTimer *timer)
177 {
178     time64 now;
179     struct timeval tv;
180
181     /* don't stop a counter that is not running */
182     if (!timer->counter) return;
183
184     if (timer->counter == 1) {
185          gettimeofday(&tv, NULL);
186          now = tv.tv_sec;
187          now *= MILLION;
188          now += tv.tv_usec;
189          /* see note before StopProcess time for warning about this mutex */
190          timer->snapShot = timer->total + now - timer->start;
191          timer->mutex = 1;
192          timer->counter = 0;
193          timer->total = timer->snapShot;
194          timer->mutex = 0;
195     } else {
196         timer->counter--;
197     }
198 }
199
200 time64 startWall;
201
202 volatile int DYNINSTpauseDone = 0;
203
204 /*
205  * change the variable to let the process proceed.
206  *
207  */
208 void DYNINSTcontinueProcess()
209 {
210     DYNINSTpauseDone = 1;
211 }
212
213 /*
214  * pause the process and let only USR2 signal handlers run until a SIGUSR1.
215  *    arrives.
216  *
217  */
218 void DYNINSTpauseProcess()
219 {
220     int mask;
221     int sigs;
222
223     sigs = ((1 << (SIGUSR2-1)) | (1 << (SIGUSR1-1)) | (1 << (SIGTSTP-1)));
224     mask = ~sigs;
225     DYNINSTpauseDone = 0;
226     while (!DYNINSTpauseDone) {
227 #ifdef notdef
228        sigpause(mask);
229        // temporary busy wait until we figure out what the TSD is up to. 
230        printf("out of sigpuase\n");
231 #endif
232     }
233 }
234
235 void DYNINSTinit(int skipBreakpoint)
236 {
237     int val;
238     int sigs;
239     char *interval;
240     struct sigvec alarmVector;
241     struct sigvec pauseVector;
242     extern float DYNINSTgetClock();
243     extern void DYNINSTalarmExpire();
244
245     startWall = 0;
246
247     /*
248      * Define the signal handlers for stopping a process.
249      *
250      */
251     pauseVector.sv_handler = DYNINSTpauseProcess;
252     sigs = ((1 << (SIGUSR2-1)) | (1 << (SIGUSR1-1)) | (1 << (SIGTSTP-1)));
253     pauseVector.sv_mask = ~sigs;
254     pauseVector.sv_flags = 0;
255     sigvec(SIGPROF, &pauseVector, NULL);
256
257     signal(SIGUSR1, DYNINSTcontinueProcess);
258
259     /* define the alarm signal vector. We block all signals while sampling.  
260      *  This prevents race conditions where signal handlers cause timers to 
261      *  be started and stopped.
262      */
263     alarmVector.sv_handler = DYNINSTalarmExpire;
264     alarmVector.sv_mask = ~0;
265     alarmVector.sv_flags = 0;
266
267
268     /* default is 500msec */
269     val = 500000;
270     interval = (char *) getenv("DYNINSTsampleInterval");
271     if (interval) {
272         val = atoi(interval);
273     }
274     sigvec(SIGALRM, &alarmVector, NULL);
275     ualarm(val, val);
276
277     DYNINSTmappedUarea = DYNINSTmapUarea();
278     DYNINSTcyclesToUsec = 1.0/DYNINSTgetClock();
279
280     /*
281      * pause the process and wait for additional info.
282      *
283      */
284     printf("Time at main %f\n", ((float) DYNINSTgetCPUtime())/1000000.0);
285     if (!skipBreakpoint) DYNINSTbreakPoint();
286 }
287
288 void DYNINSTexit()
289 {
290 }
291
292 /*
293  * generate a trace record onto the named stream.
294  *
295  */
296 void DYNINSTgenerateTraceRecord(traceStream sid, short type, short length,
297     void *eventData)
298 {
299     int ret;
300     int count;
301     struct timeval tv;
302     char buffer[1024], *bufptr;
303     traceHeader header;
304     static Boolean pipeGone = False;
305
306     if (pipeGone) return;
307
308     gettimeofday(&tv, NULL);
309     header.wall = tv.tv_sec;
310     header.wall *= (time64) MILLION;
311     header.wall += tv.tv_usec;
312     header.wall -= startWall;
313
314 #ifdef notdef
315     if (DYNINSTmappedUarea) {
316         header.process = *_p_1;
317         header.process *= MILLION;
318         header.process += *_p_2;
319     } else {
320 #endif
321         header.process = DYNINSTgetCPUtime();
322 #ifdef notdef
323     }
324 #endif
325
326     /* round length off to a word aligned unit */
327     length = ALIGN_TO_WORDSIZE(length);
328
329     header.type = type;
330     header.length = length;
331     count = 0;
332     memcpy(&buffer[count], &sid, sizeof(traceStream));
333     count += sizeof(traceStream);
334
335     memcpy(&buffer[count], &header, sizeof(header));
336     count += sizeof(header);
337
338     memcpy(&buffer[count], eventData, length);
339     count += length;
340
341     /* on this platorm, we have a pipe to the controller process */
342     errno = 0;
343     /* write may be interrupted by a system call */
344     bufptr = buffer;
345     while (count) {
346         ret = write(CONTROLLER_FD, bufptr, count);
347
348         if (ret >= 0)
349             ;     /* check most common case first */
350         else if (errno != EINTR)
351             break; 
352         else
353             ret = 0;
354
355         count -= ret;
356         bufptr += ret;
357     }
358     if (count) {
359         extern char *sys_errlist[];
360         (void) close(CONTROLLER_FD);
361         printf("unable to write trace record %s\n", sys_errlist[errno]);
362         printf("disabling further data logging, pid=%d\n", getpid());
363         fflush(stdout);
364         pipeGone = True;
365     }
366 }
367
368 time64 lastValue[200];
369 double lastTime[200];
370
371 void DYNINSTreportTimer(tTimer *timer)
372 {
373     time64 now;
374     time64 total;
375     struct timeval tv;
376     traceSample sample;
377
378     if (timer->mutex) {
379         total = timer->snapShot;
380     } else if (timer->counter) {
381         /* timer is running */
382         if (timer->type == processTime) {
383             now = DYNINSTgetCPUtime();
384         } else {
385             gettimeofday(&tv, NULL);
386             now = tv.tv_sec;
387             now *= MILLION;
388             now += tv.tv_usec;
389         }
390         total = now - timer->start + timer->total;
391     } else {
392         total = timer->total;
393     }
394     if (total < lastValue[timer->id.id]) {
395          printf("time regressed\n");
396          fflush(stdout);
397          sigpause(0xffff);
398     }
399     lastValue[timer->id.id] = total;
400
401     sample.id = timer->id;
402     sample.value = ((double) total) / (double) timer->normalize;
403
404     DYNINSTgenerateTraceRecord(0, TR_SAMPLE, sizeof(sample), &sample);
405     /* printf("raw sample %d = %f\n", sample.id.id, sample.value); */
406 }
407
408 void DYNINSTfork(void *arg, int pid)
409 {
410     int sid = 0;
411     traceFork forkRec;
412
413     printf("fork called with pid = %d\n", pid);
414     fflush(stdout);
415     if (pid > 0) {
416         forkRec.ppid = getpid();
417         forkRec.pid = pid;
418         forkRec.npids = 1;
419         forkRec.stride = 0;
420         DYNINSTgenerateTraceRecord(sid,TR_FORK,sizeof(forkRec), &forkRec);
421     } else {
422         /* set up signals and stop at a break point */
423         DYNINSTinit(1);
424         sigpause();
425     }
426 }
427
428
429 extern int DYNINSTnumReported;
430 extern int DYNINSTtotalAlaramExpires;
431
432 void DYNINSTprintCost()
433 {
434     time64 now;
435     int64 value;
436     FILE *fp;
437
438     value = DYNINSTgetObservedCycles();
439     printf("Raw cycle count = %f\n", (double) value);
440
441     value *= DYNINSTcyclesToUsec;
442
443     fp = fopen("stats.out", "w");
444
445     fprintf(fp, "DYNINSTtotalAlaramExpires %d\n", DYNINSTtotalAlaramExpires);
446     fprintf(fp, "DYNINSTnumReported %d\n", DYNINSTnumReported);
447
448     fprintf(fp,"Total instrumentation cost = %f\n", ((double) value)/1000000.0);
449     fprintf(fp,"Total handler cost = %f\n", 
450         ((double) DYNINSTtotalSampleTime)/1000000.0);
451
452     now = DYNINSTgetCPUtime();
453
454     fprintf(fp,"Total cpu time of program %f\n", ((double) now)/MILLION);
455     fflush(fp);
456     fclose(fp);
457
458     /* record that we are done -- should be somewhere better. */
459     DYNINSTgenerateTraceRecord(0, TR_EXIT, 0, NULL);
460 }
461