interpreters/glulxe/profile.c

   1 /* profile.c: Glulxe profiling functions.
   2     Designed by Andrew Plotkin <erkyrath@eblong.com>
   3     http://eblong.com/zarf/glulx/index.html
   4 */
   5
   6 /*
   7 If compiled in, these functions maintain a collection of profiling
   8 information as the Glulx program executes.
   9
  10 The profiling code is not smart about VM operations that rearrange the
  11 call stack. In fact, it's downright stupid. @restart, @restore,
  12 @restoreundo, or @throw will kill the interpreter.
  13
  14 On a normal VM exit (end of top-level routine or @quit), the profiler
  15 writes out a data file called "profile-raw". This is an XML file of
  16 the form
  17
  18 <profile>
  19   <function ... />
  20   <function ... />
  21   ...
  22 </profile>
  23
  24 The function list includes every function which was called during the
  25 program's run. Each function tag includes the following attributes:
  26
  27   addr=HEX:         The VM address of the function (in hex).
  28   call_count=INT:   The number of times the function was called.
  29   accel_count=INT:  The number of times the function was called with
  30     acceleration.
  31   total_time=FLOAT: The amount of time spent during all calls to the
  32     function (in seconds, as a floating-point value).
  33   total_ops=INT:    The number of opcodes executed during all calls to
  34     the function.
  35   self_time=FLOAT:  The amount of time spent during all calls to the
  36     function, excluding time spent in subcalls (functions called *by* the
  37     function).
  38   self_ops=INT:     The number of opcodes executed during all calls to
  39     the function, excluding time spent in subcalls.
  40
  41 Note that if a function does not make any function calls, total_time
  42 will be the same as self_time (and total_ops the same as self_ops).
  43
  44 Two special function entries may be included. The function with address
  45 "1" (which is not a legal Glulx function address) represents time spent
  46 in @glk opcode calls. This will typically have a large self_time,
  47 because it includes all the time spent waiting for input.
  48
  49 The function with address "2" represents the time spent printing string
  50 data (the @streamchar, @streamunichar, @streamnum, and @streamstr
  51 opcodes).
  52
  53 (Both "1" and "2" represent time spent in the Glk library, but they
  54 get there by different code paths.)
  55
  56 The function with the lowest address (ignoring "1" and "2") is the
  57 top-level Main__() function generated by the compiler. Its total_time
  58 is the running time of the entire program.
  59
  60  */
  61
  62 #include "glk.h"
  63 #include "glulxe.h"
  64
  65 #if VM_PROFILING
  66
  67 #include <stdio.h>
  68 #include <string.h>
  69 #include <sys/time.h>
  70
  71 typedef struct function_struct {
  72   glui32 addr;
  73
  74   glui32 call_count;
  75   glui32 accel_count;
  76   glui32 entry_depth;
  77   struct timeval entry_start_time;
  78   glui32 entry_start_op;
  79   struct timeval total_time;
  80   glui32 total_ops;
  81   struct timeval self_time;
  82   glui32 self_ops;
  83
  84   struct function_struct *hash_next;
  85 } function_t;
  86
  87 typedef struct frame_struct {
  88   struct frame_struct *parent;
  89   function_t *func;
  90
  91   struct timeval entry_time;
  92   glui32 entry_op;
  93
  94   struct timeval children_time;
  95   glui32 children_ops;
  96 } frame_t;
  97
  98 #define FUNC_HASH_SIZE (511)
  99
 100 static function_t **functions = NULL;
 101 static frame_t *current_frame = NULL;
 102
 103 glui32 profile_opcount = 0;
 104
 105 int init_profile()
 106 {
 107   int bucknum;
 108
 109   functions = (function_t **)glulx_malloc(FUNC_HASH_SIZE
 110     * sizeof(function_t *));
 111   if (!functions)
 112     return FALSE;
 113
 114   for (bucknum=0; bucknum<FUNC_HASH_SIZE; bucknum++)
 115     functions[bucknum] = NULL;
 116
 117   return TRUE;
 118 }
 119
 120 static function_t *get_function(glui32 addr)
 121 {
 122   int bucknum = (addr % FUNC_HASH_SIZE);
 123   function_t *func;
 124
 125   for (func = (functions[bucknum]);
 126        func && func->addr != addr;
 127        func = func->hash_next) { }
 128
 129   if (!func) {
 130     func = (function_t *)glulx_malloc(sizeof(function_t));
 131     if (!func)
 132       fatal_error("Profiler: cannot malloc function.");
 133     memset(func, 0, sizeof(function_t));
 134     func->hash_next = functions[bucknum];
 135     functions[bucknum] = func;
 136
 137     func->addr = addr;
 138     func->call_count = 0;
 139     func->accel_count = 0;
 140     timerclear(&func->entry_start_time);
 141     func->entry_start_op = 0;
 142     timerclear(&func->total_time);
 143     func->total_ops = 0;
 144     timerclear(&func->self_time);
 145     func->self_ops = 0;
 146   }
 147
 148   return func;
 149 }
 150
 151 static char *timeprint(struct timeval *tv, char *buf)
 152 {
 153   sprintf(buf, "%ld.%.6ld", (long)tv->tv_sec, (long)tv->tv_usec);
 154   return buf;
 155 }
 156
 157 void profile_in(glui32 addr, int accel)
 158 {
 159   frame_t *fra;
 160   function_t *func;
 161   struct timeval now;
 162
 163   /* printf("### IN: %lx%s\n", addr, (accel?" accel":"")); */
 164
 165   gettimeofday(&now, NULL);
 166
 167   func = get_function(addr);
 168   func->call_count += 1;
 169   if (accel)
 170     func->accel_count += 1;
 171   if (!func->entry_depth) {
 172     func->entry_start_time = now;
 173     func->entry_start_op = profile_opcount;
 174   }
 175   func->entry_depth += 1;
 176
 177   fra = (frame_t *)glulx_malloc(sizeof(frame_t));
 178   if (!fra)
 179     fatal_error("Profiler: cannot malloc frame.");
 180   memset(fra, 0, sizeof(frame_t));
 181
 182   fra->parent = current_frame;
 183   current_frame = fra;
 184
 185   fra->func = func;
 186   fra->entry_time = now;
 187   fra->entry_op = profile_opcount;
 188   timerclear(&fra->children_time);
 189   fra->children_ops = 0;
 190 }
 191
 192 void profile_out()
 193 {
 194   frame_t *fra;
 195   function_t *func;
 196   struct timeval now, runtime;
 197   glui32 runops;
 198
 199   /* printf("### OUT\n"); */
 200
 201   if (!current_frame)
 202     fatal_error("Profiler: stack underflow.");
 203
 204   gettimeofday(&now, NULL);
 205
 206   fra = current_frame;
 207   func = fra->func;
 208
 209   timersub(&now, &fra->entry_time, &runtime);
 210   runops = profile_opcount - fra->entry_op;
 211
 212   timeradd(&runtime, &func->self_time, &func->self_time);
 213   timersub(&func->self_time, &fra->children_time, &func->self_time);
 214   func->self_ops += runops;
 215   func->self_ops -= fra->children_ops;
 216
 217   if (fra->parent) {
 218     timeradd(&runtime, &fra->parent->children_time, &fra->parent->children_time);
 219     fra->parent->children_ops += runops;
 220   }
 221
 222   if (!func->entry_depth)
 223     fatal_error("Profiler: function entry underflow.");
 224
 225   func->entry_depth -= 1;
 226   if (!func->entry_depth) {
 227     timersub(&now, &func->entry_start_time, &runtime);
 228     timerclear(&func->entry_start_time);
 229
 230     runops = profile_opcount - func->entry_start_op;
 231     func->entry_start_op = 0;
 232
 233     timeradd(&runtime, &func->total_time, &func->total_time);
 234     func->total_ops += runops;
 235   }
 236
 237   current_frame = fra->parent;
 238   fra->parent = NULL;
 239
 240   glulx_free(fra);
 241 }
 242
 243 /* ### throw/catch */
 244 /* ### restore/restore_undo/restart */
 245
 246 void profile_fail(char *reason)
 247 {
 248   fatal_error_2("Profiler: unable to handle operation", reason);
 249 }
 250
 251 void profile_quit()
 252 {
 253   int bucknum;
 254   function_t *func;
 255   char linebuf[512];
 256   frefid_t profref;
 257   strid_t profstr;
 258
 259   while (current_frame) {
 260     profile_out();
 261   }
 262
 263   profref = glk_fileref_create_by_name(fileusage_BinaryMode|fileusage_Data, "profile-raw", 0);
 264   if (!profref)
 265     fatal_error("Profiler: unable to create profile-raw file");
 266
 267   profstr = glk_stream_open_file(profref, filemode_Write, 0);
 268
 269   glk_put_string_stream(profstr, "<profile>\n");
 270
 271   for (bucknum=0; bucknum<FUNC_HASH_SIZE; bucknum++) {
 272     char total_buf[20], self_buf[20];
 273
 274     for (func = functions[bucknum]; func; func=func->hash_next) {
 275       /* ###
 276       sprintf(linebuf, "function %lx called %ld times, total ops %ld, total time %s, self ops %ld,  self time %s\n",
 277         func->addr, func->call_count,
 278         func->total_ops,
 279         timeprint(&func->total_time, total_buf),
 280         func->self_ops,
 281         timeprint(&func->self_time, self_buf));
 282       ### */
 283       sprintf(linebuf, "  <function addr=\"%lx\" call_count=\"%ld\" accel_count=\"%ld\" total_ops=\"%ld\" total_time=\"%s\" self_ops=\"%ld\" self_time=\"%s\" />\n",
 284         func->addr, func->call_count, func->accel_count,
 285         func->total_ops,
 286         timeprint(&func->total_time, total_buf),
 287         func->self_ops,
 288         timeprint(&func->self_time, self_buf));
 289       glk_put_string_stream(profstr, linebuf);
 290     }
 291   }
 292
 293   glk_put_string_stream(profstr, "</profile>\n");
 294
 295   glk_stream_close(profstr, NULL);
 296
 297   glulx_free(functions);
 298   functions = NULL;
 299 }
 300
 301 #else /* VM_PROFILING */
 302
 303 int init_profile()
 304 {
 305     /* Profiling is not compiled in. Do nothing. */
 306     return TRUE;
 307 }
 308
 309 #endif /* VM_PROFILING */