X-Git-Url: https://git.stderr.nl/gitweb?a=blobdiff_plain;f=interpreters%2Fglulxe%2Fprofile.c;h=c8716221fb0e54608b1cc0cbebf69b0a9b4d63c1;hb=2ab029c7428eb3e4894e7d165815c90fbc39a8b2;hp=e7a0810968812b240b2c99c5e755c8651d277d78;hpb=5f927b0d7c728e389f3295ac39acb85ecb3a6ef0;p=projects%2Fchimara%2Fchimara.git diff --git a/interpreters/glulxe/profile.c b/interpreters/glulxe/profile.c index e7a0810..c871622 100644 --- a/interpreters/glulxe/profile.c +++ b/interpreters/glulxe/profile.c @@ -12,8 +12,11 @@ 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 +writes out a data file, using the filename you provided with the +"--profile" option. Note that if the VM exits via glk_exit(), or is +interrupted, the data file will be created (empty) but never filled in. + +The data file is an XML file of the form @@ -37,25 +40,33 @@ program's run. Each function tag includes the following attributes: function). self_ops=INT: The number of opcodes executed during all calls to the function, excluding time spent in subcalls. + max_depth=INT: The deepest this function has been nested on the + stack, during any call. + max_stack_use=INT: The greatest number of words on the stack, during + any call. (This is measured when the function returns, so it may + not capture the peak stack usage. If a function never returns, e.g. + Main__(), then this value is approximate.) 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. +Some of the function entries refer to special interpreter operations. +(These have high addresses, outside the range of normal game files.) +Functions with addresses in the 0xE0000000 range are the interpreter's +output opcodes: @streamchar, @streamunichar, @streamnum, @streamstr. -The function with address "2" represents the time spent printing string -data (the @streamchar, @streamunichar, @streamnum, and @streamstr -opcodes). +Functions with addresses in the 0xF0000000 range are @glk opcode calls. +The number in the lower bits specifies which Glk function was called. +You will always see a large self_time for function 0xF00000C0; this +represents all the time spent waiting for input in glk_select(). -(Both "1" and "2" represent time spent in the Glk library, but they -get there by different code paths.) +(Both the 0xE0000000 and 0xF0000000 entries 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. +The function with the lowest address is the top-level Main__() +function generated by the compiler. Its total_time is the running time +of the entire program; its total_ops is the number of opcodes executed +by the entire program; its max_depth is zero. */ @@ -68,6 +79,11 @@ is the running time of the entire program. #include #include +/* Set if the --profile switch is used. */ +static int profiling_active = FALSE; +static char *profiling_filename = NULL; +static strid_t profiling_stream = NULL; + typedef struct function_struct { glui32 addr; @@ -76,6 +92,8 @@ typedef struct function_struct { glui32 entry_depth; struct timeval entry_start_time; glui32 entry_start_op; + glui32 max_depth; + glui32 max_stack_use; struct timeval total_time; glui32 total_ops; struct timeval self_time; @@ -87,6 +105,7 @@ typedef struct function_struct { typedef struct frame_struct { struct frame_struct *parent; function_t *func; + glui32 depth; struct timeval entry_time; glui32 entry_op; @@ -100,12 +119,49 @@ typedef struct frame_struct { static function_t **functions = NULL; static frame_t *current_frame = NULL; +/* This counter is globally visible, because the profile_tick() macro + increments it. */ glui32 profile_opcount = 0; +/* This is called from the setup code -- glkunix_startup_code(), for the + Unix version. If called, the interpreter will keep profiling information, + and write it out at shutdown time. If this is not called, the interpreter + will skip all the profiling code. (Although it won't be quite as fast + as if the VM_PROFILING symbol were compiled out entirely.) + + The arguments are a little tricky, because I developed this on Unix, + but I want it to remain accessible on all platforms. Pass a writable + stream object as the first argument; at game-shutdown time, the terp + will write the profiling data to this object and then close it. + + However, if it's not convenient to open a stream in the startup code, + you can simply pass a filename as the second argument. This filename + will be opened according to the usual Glk data file rules, which means + it may wind up in a sandboxed data directory. The filename should not + contain slashes or other pathname separators. + + If you pass NULL for both arguments, a file called "profile-raw" will + be written. +*/ +void setup_profile(strid_t stream, char *filename) +{ + profiling_active = TRUE; + + if (stream) + profiling_stream = stream; + else if (filename) + profiling_filename = filename; + else + profiling_filename = "profile-raw"; +} + int init_profile() { int bucknum; + if (!profiling_active) + return TRUE; + functions = (function_t **)glulx_malloc(FUNC_HASH_SIZE * sizeof(function_t *)); if (!functions) @@ -143,6 +199,8 @@ static function_t *get_function(glui32 addr) func->total_ops = 0; timerclear(&func->self_time); func->self_ops = 0; + func->max_depth = 0; + func->max_stack_use = 0; } return func; @@ -154,12 +212,15 @@ static char *timeprint(struct timeval *tv, char *buf) return buf; } -void profile_in(glui32 addr, int accel) +void profile_in(glui32 addr, glui32 stackuse, int accel) { frame_t *fra; function_t *func; struct timeval now; + if (!profiling_active) + return; + /* printf("### IN: %lx%s\n", addr, (accel?" accel":"")); */ gettimeofday(&now, NULL); @@ -174,6 +235,9 @@ void profile_in(glui32 addr, int accel) } func->entry_depth += 1; + if (func->max_stack_use < stackuse) + func->max_stack_use = stackuse; + fra = (frame_t *)glulx_malloc(sizeof(frame_t)); if (!fra) fatal_error("Profiler: cannot malloc frame."); @@ -182,6 +246,8 @@ void profile_in(glui32 addr, int accel) fra->parent = current_frame; current_frame = fra; + if (fra->parent) + fra->depth = fra->parent->depth + 1; fra->func = func; fra->entry_time = now; fra->entry_op = profile_opcount; @@ -189,13 +255,16 @@ void profile_in(glui32 addr, int accel) fra->children_ops = 0; } -void profile_out() +void profile_out(glui32 stackuse) { frame_t *fra; function_t *func; struct timeval now, runtime; glui32 runops; + if (!profiling_active) + return; + /* printf("### OUT\n"); */ if (!current_frame) @@ -214,6 +283,11 @@ void profile_out() func->self_ops += runops; func->self_ops -= fra->children_ops; + if (func->max_depth < fra->depth) + func->max_depth = fra->depth; + if (func->max_stack_use < stackuse) + func->max_stack_use = stackuse; + if (fra->parent) { timeradd(&runtime, &fra->parent->children_time, &fra->parent->children_time); fra->parent->children_ops += runops; @@ -245,6 +319,9 @@ void profile_out() void profile_fail(char *reason) { + if (!profiling_active) + return; + fatal_error_2("Profiler: unable to handle operation", reason); } @@ -253,18 +330,28 @@ void profile_quit() int bucknum; function_t *func; char linebuf[512]; - frefid_t profref; strid_t profstr; + if (!profiling_active) + return; + while (current_frame) { - profile_out(); + profile_out(0); } - profref = glk_fileref_create_by_name(fileusage_BinaryMode|fileusage_Data, "profile-raw", 0); - if (!profref) - fatal_error("Profiler: unable to create profile-raw file"); + if (profiling_stream) { + profstr = profiling_stream; + } + else if (profiling_filename) { + frefid_t profref = glk_fileref_create_by_name(fileusage_BinaryMode|fileusage_Data, profiling_filename, 0); + if (!profref) + fatal_error_2("Profiler: unable to create profile output fileref", profiling_filename); - profstr = glk_stream_open_file(profref, filemode_Write, 0); + profstr = glk_stream_open_file(profref, filemode_Write, 0); + } + else { + fatal_error("Profiler: no profile output handle!"); + } glk_put_string_stream(profstr, "\n"); @@ -280,12 +367,13 @@ void profile_quit() func->self_ops, timeprint(&func->self_time, self_buf)); ### */ - sprintf(linebuf, " \n", - func->addr, func->call_count, func->accel_count, - func->total_ops, + sprintf(linebuf, " \n", + (unsigned long)func->addr, (long)func->call_count, (long)func->accel_count, + (long)func->total_ops, timeprint(&func->total_time, total_buf), - func->self_ops, - timeprint(&func->self_time, self_buf)); + (long)func->self_ops, + timeprint(&func->self_time, self_buf), + (long)func->max_depth, (long)func->max_stack_use); glk_put_string_stream(profstr, linebuf); } } @@ -300,6 +388,11 @@ void profile_quit() #else /* VM_PROFILING */ +void setup_profile(strid_t stream, char *filename) +{ + /* Profiling is not compiled in. Do nothing. */ +} + int init_profile() { /* Profiling is not compiled in. Do nothing. */