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, using the filename you provided with the
  16 "--profile" option. Note that if the VM exits via glk_exit(), or is
  17 interrupted, the data file will be created (empty) but never filled in.
  18
  19 The data file is an XML file of the form
  20
  21 <profile>
  22   <function ... />
  23   <function ... />
  24   ...
  25 </profile>
  26
  27 The function list includes every function which was called during the
  28 program's run. Each function tag includes the following attributes:
  29
  30   addr=HEX:         The VM address of the function (in hex).
  31   call_count=INT:   The number of times the function was called.
  32   accel_count=INT:  The number of times the function was called with
  33     acceleration.
  34   total_time=FLOAT: The amount of time spent during all calls to the
  35     function (in seconds, as a floating-point value).
  36   total_ops=INT:    The number of opcodes executed during all calls to
  37     the function.
  38   self_time=FLOAT:  The amount of time spent during all calls to the
  39     function, excluding time spent in subcalls (functions called *by* the
  40     function).
  41   self_ops=INT:     The number of opcodes executed during all calls to
  42     the function, excluding time spent in subcalls.
  43   max_depth=INT:    The deepest this function has been nested on the
  44     stack, during any call.
  45   max_stack_use=INT: The greatest number of words on the stack, during
  46     any call. (This is measured when the function returns, so it may
  47     not capture the peak stack usage. If a function never returns, e.g.
  48     Main__(), then this value is approximate.)
  49
  50 Note that if a function does not make any function calls, total_time
  51 will be the same as self_time (and total_ops the same as self_ops).
  52
  53 Some of the function entries refer to special interpreter operations.
  54 (These have high addresses, outside the range of normal game files.)
  55 Functions with addresses in the 0xE0000000 range are the interpreter's
  56 output opcodes: @streamchar, @streamunichar, @streamnum, @streamstr.
  57
  58 Functions with addresses in the 0xF0000000 range are @glk opcode calls.
  59 The number in the lower bits specifies which Glk function was called.
  60 You will always see a large self_time for function 0xF00000C0; this
  61 represents all the time spent waiting for input in glk_select().
  62
  63 (Both the 0xE0000000 and 0xF0000000 entries represent time spent in the
  64 Glk library, but they get there by different code paths.)
  65
  66 The function with the lowest address is the top-level Main__()
  67 function generated by the compiler. Its total_time is the running time
  68 of the entire program; its total_ops is the number of opcodes executed
  69 by the entire program; its max_depth is zero.
  70
  71  */
  72
  73 #include "glk.h"
  74 #include "glulxe.h"
  75
  76 #if VM_PROFILING
  77
  78 #include <stdio.h>
  79 #include <string.h>
  80 #include <sys/time.h>
  81
  82 /* Set if the --profile switch is used. */
  83 static int profiling_active = FALSE;
  84 static char *profiling_filename = NULL;
  85 static strid_t profiling_stream = NULL;
  86
  87 typedef struct function_struct {
  88   glui32 addr;
  89
  90   glui32 call_count;
  91   glui32 accel_count;
  92   glui32 entry_depth;
  93   struct timeval entry_start_time;
  94   glui32 entry_start_op;
  95   glui32 max_depth;
  96   glui32 max_stack_use;
  97   struct timeval total_time;
  98   glui32 total_ops;
  99   struct timeval self_time;
 100   glui32 self_ops;
 101
 102   struct function_struct *hash_next;
 103 } function_t;
 104
 105 typedef struct frame_struct {
 106   struct frame_struct *parent;
 107   function_t *func;
 108   glui32 depth;
 109
 110   struct timeval entry_time;
 111   glui32 entry_op;
 112
 113   struct timeval children_time;
 114   glui32 children_ops;
 115 } frame_t;
 116
 117 #define FUNC_HASH_SIZE (511)
 118
 119 static function_t **functions = NULL;
 120 static frame_t *current_frame = NULL;
 121
 122 /* This counter is globally visible, because the profile_tick() macro
 123    increments it. */
 124 glui32 profile_opcount = 0;
 125
 126 /* This is called from the setup code -- glkunix_startup_code(), for the
 127    Unix version. If called, the interpreter will keep profiling information,
 128    and write it out at shutdown time. If this is not called, the interpreter
 129    will skip all the profiling code. (Although it won't be quite as fast
 130    as if the VM_PROFILING symbol were compiled out entirely.)
 131
 132    The arguments are a little tricky, because I developed this on Unix,
 133    but I want it to remain accessible on all platforms. Pass a writable
 134    stream object as the first argument; at game-shutdown time, the terp
 135    will write the profiling data to this object and then close it.
 136
 137    However, if it's not convenient to open a stream in the startup code,
 138    you can simply pass a filename as the second argument. This filename
 139    will be opened according to the usual Glk data file rules, which means
 140    it may wind up in a sandboxed data directory. The filename should not
 141    contain slashes or other pathname separators.
 142
 143    If you pass NULL for both arguments, a file called "profile-raw" will
 144    be written.
 145 */
 146 void setup_profile(strid_t stream, char *filename)
 147 {
 148   profiling_active = TRUE;
 149
 150   if (stream)
 151     profiling_stream = stream;
 152   else if (filename)
 153     profiling_filename = filename;
 154   else
 155     profiling_filename = "profile-raw";
 156 }
 157
 158 int init_profile()
 159 {
 160   int bucknum;
 161
 162   if (!profiling_active)
 163     return TRUE;
 164
 165   functions = (function_t **)glulx_malloc(FUNC_HASH_SIZE
 166     * sizeof(function_t *));
 167   if (!functions)
 168     return FALSE;
 169
 170   for (bucknum=0; bucknum<FUNC_HASH_SIZE; bucknum++)
 171     functions[bucknum] = NULL;
 172
 173   return TRUE;
 174 }
 175
 176 static function_t *get_function(glui32 addr)
 177 {
 178   int bucknum = (addr % FUNC_HASH_SIZE);
 179   function_t *func;
 180
 181   for (func = (functions[bucknum]);
 182        func && func->addr != addr;
 183        func = func->hash_next) { }
 184
 185   if (!func) {
 186     func = (function_t *)glulx_malloc(sizeof(function_t));
 187     if (!func)
 188       fatal_error("Profiler: cannot malloc function.");
 189     memset(func, 0, sizeof(function_t));
 190     func->hash_next = functions[bucknum];
 191     functions[bucknum] = func;
 192
 193     func->addr = addr;
 194     func->call_count = 0;
 195     func->accel_count = 0;
 196     timerclear(&func->entry_start_time);
 197     func->entry_start_op = 0;
 198     timerclear(&func->total_time);
 199     func->total_ops = 0;
 200     timerclear(&func->self_time);
 201     func->self_ops = 0;
 202     func->max_depth = 0;
 203     func->max_stack_use = 0;
 204   }
 205
 206   return func;
 207 }
 208
 209 static char *timeprint(struct timeval *tv, char *buf)
 210 {
 211   sprintf(buf, "%ld.%.6ld", (long)tv->tv_sec, (long)tv->tv_usec);
 212   return buf;
 213 }
 214
 215 void profile_in(glui32 addr, glui32 stackuse, int accel)
 216 {
 217   frame_t *fra;
 218   function_t *func;
 219   struct timeval now;
 220
 221   if (!profiling_active)
 222     return;
 223
 224   /* printf("### IN: %lx%s\n", addr, (accel?" accel":"")); */
 225
 226   gettimeofday(&now, NULL);
 227
 228   func = get_function(addr);
 229   func->call_count += 1;
 230   if (accel)
 231     func->accel_count += 1;
 232   if (!func->entry_depth) {
 233     func->entry_start_time = now;
 234     func->entry_start_op = profile_opcount;
 235   }
 236   func->entry_depth += 1;
 237
 238   if (func->max_stack_use < stackuse)
 239     func->max_stack_use = stackuse;
 240
 241   fra = (frame_t *)glulx_malloc(sizeof(frame_t));
 242   if (!fra)
 243     fatal_error("Profiler: cannot malloc frame.");
 244   memset(fra, 0, sizeof(frame_t));
 245
 246   fra->parent = current_frame;
 247   current_frame = fra;
 248
 249   if (fra->parent)
 250     fra->depth = fra->parent->depth + 1;
 251   fra->func = func;
 252   fra->entry_time = now;
 253   fra->entry_op = profile_opcount;
 254   timerclear(&fra->children_time);
 255   fra->children_ops = 0;
 256 }
 257
 258 void profile_out(glui32 stackuse)
 259 {
 260   frame_t *fra;
 261   function_t *func;
 262   struct timeval now, runtime;
 263   glui32 runops;
 264
 265   if (!profiling_active)
 266     return;
 267
 268   /* printf("### OUT\n"); */
 269
 270   if (!current_frame)
 271     fatal_error("Profiler: stack underflow.");
 272
 273   gettimeofday(&now, NULL);
 274
 275   fra = current_frame;
 276   func = fra->func;
 277
 278   timersub(&now, &fra->entry_time, &runtime);
 279   runops = profile_opcount - fra->entry_op;
 280
 281   timeradd(&runtime, &func->self_time, &func->self_time);
 282   timersub(&func->self_time, &fra->children_time, &func->self_time);
 283   func->self_ops += runops;
 284   func->self_ops -= fra->children_ops;
 285
 286   if (func->max_depth < fra->depth)
 287     func->max_depth = fra->depth;
 288   if (func->max_stack_use < stackuse)
 289     func->max_stack_use = stackuse;
 290
 291   if (fra->parent) {
 292     timeradd(&runtime, &fra->parent->children_time, &fra->parent->children_time);
 293     fra->parent->children_ops += runops;
 294   }
 295
 296   if (!func->entry_depth)
 297     fatal_error("Profiler: function entry underflow.");
 298
 299   func->entry_depth -= 1;
 300   if (!func->entry_depth) {
 301     timersub(&now, &func->entry_start_time, &runtime);
 302     timerclear(&func->entry_start_time);
 303
 304     runops = profile_opcount - func->entry_start_op;
 305     func->entry_start_op = 0;
 306
 307     timeradd(&runtime, &func->total_time, &func->total_time);
 308     func->total_ops += runops;
 309   }
 310
 311   current_frame = fra->parent;
 312   fra->parent = NULL;
 313
 314   glulx_free(fra);
 315 }
 316
 317 /* ### throw/catch */
 318 /* ### restore/restore_undo/restart */
 319
 320 void profile_fail(char *reason)
 321 {
 322   if (!profiling_active)
 323     return;
 324
 325   fatal_error_2("Profiler: unable to handle operation", reason);
 326 }
 327
 328 void profile_quit()
 329 {
 330   int bucknum;
 331   function_t *func;
 332   char linebuf[512];
 333   strid_t profstr;
 334
 335   if (!profiling_active)
 336     return;
 337
 338   while (current_frame) {
 339     profile_out(0);
 340   }
 341
 342   if (profiling_stream) {
 343     profstr = profiling_stream;
 344   }
 345   else if (profiling_filename) {
 346     frefid_t profref = glk_fileref_create_by_name(fileusage_BinaryMode|fileusage_Data, profiling_filename, 0);
 347     if (!profref)
 348         fatal_error_2("Profiler: unable to create profile output fileref", profiling_filename);
 349
 350     profstr = glk_stream_open_file(profref, filemode_Write, 0);
 351   }
 352   else {
 353     fatal_error("Profiler: no profile output handle!");
 354   }
 355
 356   glk_put_string_stream(profstr, "<profile>\n");
 357
 358   for (bucknum=0; bucknum<FUNC_HASH_SIZE; bucknum++) {
 359     char total_buf[20], self_buf[20];
 360
 361     for (func = functions[bucknum]; func; func=func->hash_next) {
 362       /* ###
 363       sprintf(linebuf, "function %lx called %ld times, total ops %ld, total time %s, self ops %ld,  self time %s\n",
 364         func->addr, func->call_count,
 365         func->total_ops,
 366         timeprint(&func->total_time, total_buf),
 367         func->self_ops,
 368         timeprint(&func->self_time, self_buf));
 369       ### */
 370       sprintf(linebuf, "  <function addr=\"%lx\" call_count=\"%ld\" accel_count=\"%ld\" total_ops=\"%ld\" total_time=\"%s\" self_ops=\"%ld\" self_time=\"%s\" max_depth=\"%ld\" max_stack_use=\"%ld\" />\n",
 371         (unsigned long)func->addr, (long)func->call_count, (long)func->accel_count,
 372         (long)func->total_ops,
 373         timeprint(&func->total_time, total_buf),
 374         (long)func->self_ops,
 375         timeprint(&func->self_time, self_buf),
 376         (long)func->max_depth, (long)func->max_stack_use);
 377       glk_put_string_stream(profstr, linebuf);
 378     }
 379   }
 380
 381   glk_put_string_stream(profstr, "</profile>\n");
 382
 383   glk_stream_close(profstr, NULL);
 384
 385   glulx_free(functions);
 386   functions = NULL;
 387 }
 388
 389 #else /* VM_PROFILING */
 390
 391 void setup_profile(strid_t stream, char *filename)
 392 {
 393     /* Profiling is not compiled in. Do nothing. */
 394 }
 395
 396 int init_profile()
 397 {
 398     /* Profiling is not compiled in. Do nothing. */
 399     return TRUE;
 400 }
 401
 402 #endif /* VM_PROFILING */