--- /dev/null
+/* profile.c: Glulxe profiling functions.
+ Designed by Andrew Plotkin <erkyrath@eblong.com>
+ 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
+
+<profile>
+ <function ... />
+ <function ... />
+ ...
+</profile>
+
+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 <stdio.h>
+#include <string.h>
+#include <sys/time.h>
+
+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; bucknum<FUNC_HASH_SIZE; bucknum++)
+ functions[bucknum] = NULL;
+
+ return TRUE;
+}
+
+static function_t *get_function(glui32 addr)
+{
+ int bucknum = (addr % FUNC_HASH_SIZE);
+ function_t *func;
+
+ for (func = (functions[bucknum]);
+ func && func->addr != 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, "<profile>\n");
+
+ for (bucknum=0; bucknum<FUNC_HASH_SIZE; bucknum++) {
+ char total_buf[20], self_buf[20];
+
+ for (func = functions[bucknum]; func; func=func->hash_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, " <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,
+ 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, "</profile>\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 */
projects / rodin / chimara.git / blobdiff