X-Git-Url: https://git.stderr.nl/gitweb?a=blobdiff_plain;f=interpreters%2Fglulxe%2Fprofile.c;fp=interpreters%2Fglulxe%2Fprofile.c;h=e7a0810968812b240b2c99c5e755c8651d277d78;hb=147a8cbf17f2b3379277bf7d37cda9866510f16c;hp=0000000000000000000000000000000000000000;hpb=7de488aa6a1709a4d5c59b5ff59862105c1748c5;p=rodin%2Fchimara.git diff --git a/interpreters/glulxe/profile.c b/interpreters/glulxe/profile.c new file mode 100644 index 0000000..e7a0810 --- /dev/null +++ b/interpreters/glulxe/profile.c @@ -0,0 +1,309 @@ +/* profile.c: Glulxe profiling functions. + Designed by Andrew Plotkin + http://eblong.com/zarf/glulx/index.html +*/ + +/* +If compiled in, these functions maintain a collection of profiling +information as the Glulx program executes. + +The profiling code is not smart about VM operations that rearrange the +call stack. In fact, it's downright stupid. @restart, @restore, +@restoreundo, or @throw will kill the interpreter. + +On a normal VM exit (end of top-level routine or @quit), the profiler +writes out a data file called "profile-raw". This is an XML file of +the form + + + + + ... + + +The function list includes every function which was called during the +program's run. Each function tag includes the following attributes: + + addr=HEX: The VM address of the function (in hex). + call_count=INT: The number of times the function was called. + accel_count=INT: The number of times the function was called with + acceleration. + total_time=FLOAT: The amount of time spent during all calls to the + function (in seconds, as a floating-point value). + total_ops=INT: The number of opcodes executed during all calls to + the function. + self_time=FLOAT: The amount of time spent during all calls to the + function, excluding time spent in subcalls (functions called *by* the + function). + self_ops=INT: The number of opcodes executed during all calls to + the function, excluding time spent in subcalls. + +Note that if a function does not make any function calls, total_time +will be the same as self_time (and total_ops the same as self_ops). + +Two special function entries may be included. The function with address +"1" (which is not a legal Glulx function address) represents time spent +in @glk opcode calls. This will typically have a large self_time, +because it includes all the time spent waiting for input. + +The function with address "2" represents the time spent printing string +data (the @streamchar, @streamunichar, @streamnum, and @streamstr +opcodes). + +(Both "1" and "2" represent time spent in the Glk library, but they +get there by different code paths.) + +The function with the lowest address (ignoring "1" and "2") is the +top-level Main__() function generated by the compiler. Its total_time +is the running time of the entire program. + + */ + +#include "glk.h" +#include "glulxe.h" + +#if VM_PROFILING + +#include +#include +#include + +typedef struct function_struct { + glui32 addr; + + glui32 call_count; + glui32 accel_count; + glui32 entry_depth; + struct timeval entry_start_time; + glui32 entry_start_op; + struct timeval total_time; + glui32 total_ops; + struct timeval self_time; + glui32 self_ops; + + struct function_struct *hash_next; +} function_t; + +typedef struct frame_struct { + struct frame_struct *parent; + function_t *func; + + struct timeval entry_time; + glui32 entry_op; + + struct timeval children_time; + glui32 children_ops; +} frame_t; + +#define FUNC_HASH_SIZE (511) + +static function_t **functions = NULL; +static frame_t *current_frame = NULL; + +glui32 profile_opcount = 0; + +int init_profile() +{ + int bucknum; + + functions = (function_t **)glulx_malloc(FUNC_HASH_SIZE + * sizeof(function_t *)); + if (!functions) + return FALSE; + + for (bucknum=0; bucknumaddr != addr; + func = func->hash_next) { } + + if (!func) { + func = (function_t *)glulx_malloc(sizeof(function_t)); + if (!func) + fatal_error("Profiler: cannot malloc function."); + memset(func, 0, sizeof(function_t)); + func->hash_next = functions[bucknum]; + functions[bucknum] = func; + + func->addr = addr; + func->call_count = 0; + func->accel_count = 0; + timerclear(&func->entry_start_time); + func->entry_start_op = 0; + timerclear(&func->total_time); + func->total_ops = 0; + timerclear(&func->self_time); + func->self_ops = 0; + } + + return func; +} + +static char *timeprint(struct timeval *tv, char *buf) +{ + sprintf(buf, "%ld.%.6ld", (long)tv->tv_sec, (long)tv->tv_usec); + return buf; +} + +void profile_in(glui32 addr, int accel) +{ + frame_t *fra; + function_t *func; + struct timeval now; + + /* printf("### IN: %lx%s\n", addr, (accel?" accel":"")); */ + + gettimeofday(&now, NULL); + + func = get_function(addr); + func->call_count += 1; + if (accel) + func->accel_count += 1; + if (!func->entry_depth) { + func->entry_start_time = now; + func->entry_start_op = profile_opcount; + } + func->entry_depth += 1; + + fra = (frame_t *)glulx_malloc(sizeof(frame_t)); + if (!fra) + fatal_error("Profiler: cannot malloc frame."); + memset(fra, 0, sizeof(frame_t)); + + fra->parent = current_frame; + current_frame = fra; + + fra->func = func; + fra->entry_time = now; + fra->entry_op = profile_opcount; + timerclear(&fra->children_time); + fra->children_ops = 0; +} + +void profile_out() +{ + frame_t *fra; + function_t *func; + struct timeval now, runtime; + glui32 runops; + + /* printf("### OUT\n"); */ + + if (!current_frame) + fatal_error("Profiler: stack underflow."); + + gettimeofday(&now, NULL); + + fra = current_frame; + func = fra->func; + + timersub(&now, &fra->entry_time, &runtime); + runops = profile_opcount - fra->entry_op; + + timeradd(&runtime, &func->self_time, &func->self_time); + timersub(&func->self_time, &fra->children_time, &func->self_time); + func->self_ops += runops; + func->self_ops -= fra->children_ops; + + if (fra->parent) { + timeradd(&runtime, &fra->parent->children_time, &fra->parent->children_time); + fra->parent->children_ops += runops; + } + + if (!func->entry_depth) + fatal_error("Profiler: function entry underflow."); + + func->entry_depth -= 1; + if (!func->entry_depth) { + timersub(&now, &func->entry_start_time, &runtime); + timerclear(&func->entry_start_time); + + runops = profile_opcount - func->entry_start_op; + func->entry_start_op = 0; + + timeradd(&runtime, &func->total_time, &func->total_time); + func->total_ops += runops; + } + + current_frame = fra->parent; + fra->parent = NULL; + + glulx_free(fra); +} + +/* ### throw/catch */ +/* ### restore/restore_undo/restart */ + +void profile_fail(char *reason) +{ + fatal_error_2("Profiler: unable to handle operation", reason); +} + +void profile_quit() +{ + int bucknum; + function_t *func; + char linebuf[512]; + frefid_t profref; + strid_t profstr; + + while (current_frame) { + profile_out(); + } + + profref = glk_fileref_create_by_name(fileusage_BinaryMode|fileusage_Data, "profile-raw", 0); + if (!profref) + fatal_error("Profiler: unable to create profile-raw file"); + + profstr = glk_stream_open_file(profref, filemode_Write, 0); + + glk_put_string_stream(profstr, "\n"); + + for (bucknum=0; bucknumhash_next) { + /* ### + sprintf(linebuf, "function %lx called %ld times, total ops %ld, total time %s, self ops %ld, self time %s\n", + func->addr, func->call_count, + func->total_ops, + timeprint(&func->total_time, total_buf), + func->self_ops, + timeprint(&func->self_time, self_buf)); + ### */ + sprintf(linebuf, " \n", + func->addr, func->call_count, func->accel_count, + func->total_ops, + timeprint(&func->total_time, total_buf), + func->self_ops, + timeprint(&func->self_time, self_buf)); + glk_put_string_stream(profstr, linebuf); + } + } + + glk_put_string_stream(profstr, "\n"); + + glk_stream_close(profstr, NULL); + + glulx_free(functions); + functions = NULL; +} + +#else /* VM_PROFILING */ + +int init_profile() +{ + /* Profiling is not compiled in. Do nothing. */ + return TRUE; +} + +#endif /* VM_PROFILING */