@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
<profile>
<function ... />
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.
*/
#include <string.h>
#include <sys/time.h>
+/* 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;
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;
typedef struct frame_struct {
struct frame_struct *parent;
function_t *func;
+ glui32 depth;
struct timeval entry_time;
glui32 entry_op;
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)
func->total_ops = 0;
timerclear(&func->self_time);
func->self_ops = 0;
+ func->max_depth = 0;
+ func->max_stack_use = 0;
}
return func;
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);
}
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.");
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;
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)
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;
void profile_fail(char *reason)
{
+ if (!profiling_active)
+ return;
+
fatal_error_2("Profiler: unable to handle operation", reason);
}
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, "<profile>\n");
func->self_ops,
timeprint(&func->self_time, self_buf));
### */
- sprintf(linebuf, " <function addr=\"%lx\" call_count=\"%ld\" accel_count=\"%ld\" total_ops=\"%ld\" total_time=\"%s\" self_ops=\"%ld\" self_time=\"%s\" />\n",
- func->addr, func->call_count, func->accel_count,
- func->total_ops,
+ 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",
+ (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);
}
}
#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. */
projects / projects / chimara / chimara.git / blobdiff