Stats.c 11.2 KB
Newer Older
1
/* -----------------------------------------------------------------------------
2
 * $Id: Stats.c,v 1.9 1999/02/23 15:45:08 simonm Exp $
3
4
 *
 * (c) The GHC Team, 1998-1999
5
6
7
8
9
10
11
12
13
14
 *
 * Statistics and timing-related functions.
 *
 * ---------------------------------------------------------------------------*/

#define NON_POSIX_SOURCE

#include "Rts.h"
#include "RtsFlags.h"
#include "RtsUtils.h"
15
16
#include "StoragePriv.h"
#include "MBlock.h"
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80

/**
 *  Ian: For the moment we just want to ignore
 * these on Nemesis
 **/
#ifdef _NEMESIS_OS_
#ifdef HAVE_SYS_TIMES_H
#undef HAVE_SYS_TIMES_H /* <sys/times.h> */
#endif
#ifdef HAVE_SYS_RESOURCE_H /* <sys/resource.h> */
#undef HAVE_SYS_RESOURCE_H
#endif
#ifdef HAVE_SYS_TIME_H  /* <sys/time.h> */
#undef HAVE_SYS_TIME_H
#endif
#ifdef HAVE_SYS_TIMEB_H 
#undef HAVE_SYS_TIMEB_H /* <sys/timeb.h> */
#endif
#ifdef HAVE_UNISTD_H
#undef HAVE_UNISTD_H    /* <unistd.h> */
#endif
#ifdef HAVE_TIMES
#undef HAVE_TIMES
#endif 
#ifdef HAVE_FTIME
#undef HAVE_FTIME
#endif
#ifdef HAVE_GETRUSAGE
#undef HAVE_GETRUSAGE
#endif
#ifdef HAVE_SYSCONF
#undef HAVE_SYSCONF
#endif
#endif /* _NEMESIS_OS_ */

#include "Stats.h"

#ifdef HAVE_UNISTD_H
#include <unistd.h>
#endif

#ifdef HAVE_SYS_TIMES_H
#include <sys/times.h>
#endif

#ifdef HAVE_SYS_TIME_H
#include <sys/time.h>
#endif

#if defined(HAVE_SYS_RESOURCE_H) && ! irix_TARGET_OS
#include <sys/resource.h>
#endif

#ifdef HAVE_SYS_TIMEB_H
#include <sys/timeb.h>
#endif

#if HAVE_STDLIB_H
#include <stdlib.h>
#endif

/* huh? */
#define BIG_STRING_LEN              512

81
82
static double ElapsedTimeStart = 0.0;
static double TicksPerSecond   = 0.0;
83

84
85
static double InitUserTime = 0.0;
static double InitElapsedTime = 0.0;
86
87

static ullong GC_tot_alloc = 0;
88
static ullong GC_tot_copied = 0;
89

90
91
static double GC_start_time,  GC_tot_time = 0;  /* User GC Time */
static double GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */
92
93
94
95
96
97

lnat MaxResidency = 0;     /* in words; for stats only */
lnat ResidencySamples = 0; /* for stats only */

static lnat GC_start_faults = 0, GC_end_faults = 0;

98
99
static double *GC_coll_times;

100
101
102
103
/* ToDo: convert this to use integers? --SDM */

/* elapsedtime() -- The current elapsed time in seconds */

104
double
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
elapsedtime(void)
{
#if ! (defined(HAVE_TIMES) || defined(HAVE_FTIME))
    /* We will #ifdef around the fprintf for machines
       we *know* are unsupported. (WDP 94/05)
    */
    fprintf(stderr, "NOTE: `elapsedtime' does nothing!\n");
    return 0.0;

#else /* not stumped */

/* "ftime" may be nicer, but "times" is more standard;
   but, on a Sun, if you do not get the SysV one, you are *hosed*...
 */

# if defined(HAVE_TIMES) && ! sunos4_TARGET_OS
    struct tms t;
    clock_t r = times(&t);

124
    return (((double)r)/TicksPerSecond - ElapsedTimeStart);
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161

# else /* HAVE_FTIME */
    struct timeb t;

    ftime(&t);
    return (fabs(t.time + 1e-3*t.millitm - ElapsedTimeStart));

# endif /* HAVE_FTIME */
#endif /* not stumped */
}

static nat
pagefaults(void)
{
# if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS
    return 0;
# else
    struct rusage t;

    getrusage(RUSAGE_SELF, &t);
    return(t.ru_majflt);
# endif
}

/* ToDo: use gettimeofday on systems that support it (u-sec accuracy) */

void
start_time(void)
{
    long ticks;
    /* Determine TicksPerSecond ... */
#ifdef HAVE_SYSCONF
    ticks = sysconf(_SC_CLK_TCK);
    if ( ticks == -1 ) {
	fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
    	stg_exit(EXIT_FAILURE);
    }
162
    TicksPerSecond = (double) ticks;
163
164
165

#else /* no "sysconf"; had better guess */
# ifdef HZ
166
    TicksPerSecond = (double) (HZ);
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183

# else /* had better guess wildly */
    /* We will #ifdef around the fprintf for machines
       we *know* are unsupported. (WDP 94/05)
    */
    fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
    TicksPerSecond = 60.0;
# endif
#endif

    ElapsedTimeStart = elapsedtime();
}


void
initStats(void)
{
184
  nat i;
185
186
187
  FILE *sf = RtsFlags.GcFlags.statsFile;
  
  if (RtsFlags.GcFlags.giveStats) {
188
189
    fprintf(sf, "    Alloc    Collect    Live    GC    GC     TOT     TOT  Page Flts\n");
    fprintf(sf, "    bytes     bytes     bytes  user  elap    user    elap\n");
190
  }
191
192
193
194
195
196
197

  GC_coll_times = 
    (double *)stgMallocBytes(sizeof(double) * RtsFlags.GcFlags.generations,
			   "initStats");
  for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
    GC_coll_times[i] = 0.0;
  }
198
199
200
}    


201
double
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
usertime(void)
{
#if ! (defined(HAVE_GETRUSAGE) || defined(HAVE_TIMES))
    /* We will #ifdef around the fprintf for machines
       we *know* are unsupported. (WDP 94/05)
    */
    fprintf(stderr, "NOTE: `usertime' does nothing!\n");
    return 0.0;

#else /* not stumped */

# if defined(HAVE_TIMES) 
    struct tms t;

    times(&t);
217
    return(((double)(t.tms_utime))/TicksPerSecond);
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274

#else /* HAVE_GETRUSAGE */
    struct rusage t;

    getrusage(RUSAGE_SELF, &t);
    return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);

# endif /* HAVE_GETRUSAGE */
#endif /* not stumped */
}

void 
end_init(void)
{
  InitUserTime = usertime();
  InitElapsedTime = elapsedtime();
  if (InitElapsedTime < 0.0) {
    InitElapsedTime = 0.0;
  }
}

/* -----------------------------------------------------------------------------
   Called at the beginning of each GC
   -------------------------------------------------------------------------- */

static nat rub_bell = 0;

void
stat_startGC(void)
{
    FILE *sf = RtsFlags.GcFlags.statsFile;

    nat bell = RtsFlags.GcFlags.ringBell;

    if (bell) {
	if (bell > 1) {
	    fprintf(stderr, " GC ");
	    rub_bell = 1;
	} else {
	    fprintf(stderr, "\007");
	}
    }

    if (sf != NULL) {
	GC_start_time = usertime();
	GCe_start_time = elapsedtime();
	if (RtsFlags.GcFlags.giveStats) {
	  GC_start_faults = pagefaults();
	}
    }
}

/* -----------------------------------------------------------------------------
   Called at the end of each GC
   -------------------------------------------------------------------------- */

void
275
stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen)
276
277
278
279
{
    FILE *sf = RtsFlags.GcFlags.statsFile;

    if (sf != NULL) {
280
281
	double time = usertime();
	double etime = elapsedtime();
282
283
284
285

	if (RtsFlags.GcFlags.giveStats) {
	    nat faults = pagefaults();

286
287
288
	    fprintf(sf, "%9ld %9ld %9ld",
		    alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_));
	    fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n", 
289
290
291
292
293
294
		    (time-GC_start_time), 
		    (etime-GCe_start_time), 
		    time,
		    etime,
		    faults - GC_start_faults,
		    GC_start_faults - GC_end_faults,
295
		    gen);
296
297
298
299
300

	    GC_end_faults = faults;
	    fflush(sf);
	}

301
302
	GC_coll_times[gen] += time-GC_start_time;

303
304
305
306
	GC_tot_copied += (ullong) copied;
	GC_tot_alloc  += (ullong) alloc;
	GC_tot_time   += time-GC_start_time;
	GCe_tot_time  += etime-GCe_start_time;
307
308
309
310
311
312
313

	if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
	  if (live > MaxResidency) {
	    MaxResidency = live;
	  }
	  ResidencySamples++;
	}
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
    }

    if (rub_bell) {
	fprintf(stderr, "\b\b\b  \b\b\b");
	rub_bell = 0;
    }
}

/* -----------------------------------------------------------------------------
   Called at the end of execution

   NOTE: number of allocations is not entirely accurate: it doesn't
   take into account the few bytes at the end of the heap that
   were left unused when the heap-check failed.
   -------------------------------------------------------------------------- */

void
stat_exit(int alloc)
{
    FILE *sf = RtsFlags.GcFlags.statsFile;

    if (sf != NULL){
	char temp[BIG_STRING_LEN];
337
338
339
	double time = usertime();
	double etime = elapsedtime();
	double MutTime, MutElapsedTime;
340
341
342
343
344
345

	/* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
	if (time  == 0.0)  time = 0.0001;
	if (etime == 0.0) etime = 0.0001;
	

346
347
348
349
350
	fprintf(sf, "%9ld %9.9s %9.9s",
		(lnat)alloc*sizeof(W_), "", "");
	fprintf(sf, " %5.2f %5.2f\n\n", 0.0, 0.0);

	GC_tot_alloc += alloc;
351
352
353

	ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
	fprintf(sf, "%11s bytes allocated in the heap\n", temp);
354

355
356
357
	ullong_format_string(GC_tot_copied*sizeof(W_), temp, rtsTrue/*commas*/);
	fprintf(sf, "%11s bytes copied during GC\n", temp);

358
359
	if ( ResidencySamples > 0 ) {
	    ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
360
	    fprintf(sf, "%11s bytes maximum residency (%ld sample(s))\n",
361
362
363
			      temp,
			      ResidencySamples);
	}
364
365
366
367
368
	fprintf(sf,"\n");

	{ /* Count garbage collections */
	  nat g;
	  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
369
370
	    fprintf(sf, "%11d collections in generation %d (%6.2fs)\n", 
		    generations[g].collections, g, GC_coll_times[g]);
371
372
373
374
	  }
	}
	fprintf(sf,"\n%11ld Mb total memory in use\n\n", 
		mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408

	MutTime = time - GC_tot_time - InitUserTime;
	if (MutTime < 0) { MutTime = 0; }
	MutElapsedTime = etime - GCe_tot_time - InitElapsedTime;
	if (MutElapsedTime < 0) { MutElapsedTime = 0; }	/* sometimes -0.00 */

	fprintf(sf, "  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
		InitUserTime, InitElapsedTime);
	fprintf(sf, "  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
		MutTime, MutElapsedTime);
	fprintf(sf, "  GC    time  %6.2fs  (%6.2fs elapsed)\n",
		GC_tot_time, GCe_tot_time);
	fprintf(sf, "  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
		time, etime);

	fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
		GC_tot_time*100./time, GCe_tot_time*100./etime);

	if (time - GC_tot_time == 0.0)
		ullong_format_string(0, temp, rtsTrue/*commas*/);
	else
		ullong_format_string((ullong)(GC_tot_alloc*sizeof(W_)/
					      (time - GC_tot_time)),
				     temp, rtsTrue/*commas*/);

	fprintf(sf, "  Alloc rate    %s bytes per MUT second\n\n", temp);

	fprintf(sf, "  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
		(time - GC_tot_time - InitUserTime) * 100. / time, 
                (time - GC_tot_time - InitUserTime) * 100. / etime);
	fflush(sf);
	fclose(sf);
    }
}
409
410
411
412
413
414
415
416
417

/* -----------------------------------------------------------------------------
   stat_describe_gens

   Produce some detailed info on the state of the generational GC.
   -------------------------------------------------------------------------- */
void
stat_describe_gens(void)
{
418
  nat g, s, mut, mut_once, lge, live;
419
420
421
422
  StgMutClosure *m;
  bdescr *bd;
  step *step;

423
  fprintf(stderr, "     Gen    Steps      Max   Mutable  Mut-Once  Step   Blocks     Live    Large\n                    Blocks  Closures  Closures                         Objects\n");
424
425
426
427
428

  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
    for (m = generations[g].mut_list, mut = 0; m != END_MUT_LIST; 
	 m = m->mut_link) 
      mut++;
429
430
431
    for (m = generations[g].mut_once_list, mut_once = 0; m != END_MUT_LIST; 
	 m = m->mut_link) 
      mut_once++;
432
    fprintf(stderr, "%8d %8d %8d %9d %9d", g, generations[g].n_steps,
433
	    generations[g].max_blocks, mut, mut_once);
434
435
436
437
438
439

    for (s = 0; s < generations[g].n_steps; s++) {
      step = &generations[g].steps[s];
      for (bd = step->large_objects, lge = 0; bd; bd = bd->link)
	lge++;
      live = 0;
440
441
442
443
444
445
      if (RtsFlags.GcFlags.generations == 1) {
	bd = step->to_space;
      } else {
	bd = step->blocks;
      }
      for (; bd; bd = bd->link) {
446
447
448
	live += (bd->free - bd->start) * sizeof(W_);
      }
      if (s != 0) {
449
	fprintf(stderr,"%46s","");
450
451
452
453
454
455
456
      }
      fprintf(stderr,"%6d %8d %8d %8d\n", s, step->n_blocks,
	      live, lge);
    }
  }
  fprintf(stderr,"\n");
}