1 /* profile.c: Glulxe profiling functions.
2 Designed by Andrew Plotkin <erkyrath@eblong.com>
3 http://eblong.com/zarf/glulx/index.html
7 If compiled in, these functions maintain a collection of profiling
8 information as the Glulx program executes.
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.
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.
19 The data file is an XML file of the form
27 The function list includes every function which was called during the
28 program's run. Each function tag includes the following attributes:
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
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
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
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.)
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).
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.
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().
63 (Both the 0xE0000000 and 0xF0000000 entries represent time spent in the
64 Glk library, but they get there by different code paths.)
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.
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;
87 typedef struct function_struct {
93 struct timeval entry_start_time;
94 glui32 entry_start_op;
97 struct timeval total_time;
99 struct timeval self_time;
102 struct function_struct *hash_next;
105 typedef struct frame_struct {
106 struct frame_struct *parent;
110 struct timeval entry_time;
113 struct timeval children_time;
117 #define FUNC_HASH_SIZE (511)
119 static function_t **functions = NULL;
120 static frame_t *current_frame = NULL;
122 /* This counter is globally visible, because the profile_tick() macro
124 glui32 profile_opcount = 0;
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.)
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.
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.
143 If you pass NULL for both arguments, a file called "profile-raw" will
146 void setup_profile(strid_t stream, char *filename)
148 profiling_active = TRUE;
151 profiling_stream = stream;
153 profiling_filename = filename;
155 profiling_filename = "profile-raw";
162 if (!profiling_active)
165 functions = (function_t **)glulx_malloc(FUNC_HASH_SIZE
166 * sizeof(function_t *));
170 for (bucknum=0; bucknum<FUNC_HASH_SIZE; bucknum++)
171 functions[bucknum] = NULL;
176 static function_t *get_function(glui32 addr)
178 int bucknum = (addr % FUNC_HASH_SIZE);
181 for (func = (functions[bucknum]);
182 func && func->addr != addr;
183 func = func->hash_next) { }
186 func = (function_t *)glulx_malloc(sizeof(function_t));
188 fatal_error("Profiler: cannot malloc function.");
189 memset(func, 0, sizeof(function_t));
190 func->hash_next = functions[bucknum];
191 functions[bucknum] = func;
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);
200 timerclear(&func->self_time);
203 func->max_stack_use = 0;
209 static char *timeprint(struct timeval *tv, char *buf)
211 sprintf(buf, "%ld.%.6ld", (long)tv->tv_sec, (long)tv->tv_usec);
215 void profile_in(glui32 addr, glui32 stackuse, int accel)
221 if (!profiling_active)
224 /* printf("### IN: %lx%s\n", addr, (accel?" accel":"")); */
226 gettimeofday(&now, NULL);
228 func = get_function(addr);
229 func->call_count += 1;
231 func->accel_count += 1;
232 if (!func->entry_depth) {
233 func->entry_start_time = now;
234 func->entry_start_op = profile_opcount;
236 func->entry_depth += 1;
238 if (func->max_stack_use < stackuse)
239 func->max_stack_use = stackuse;
241 fra = (frame_t *)glulx_malloc(sizeof(frame_t));
243 fatal_error("Profiler: cannot malloc frame.");
244 memset(fra, 0, sizeof(frame_t));
246 fra->parent = current_frame;
250 fra->depth = fra->parent->depth + 1;
252 fra->entry_time = now;
253 fra->entry_op = profile_opcount;
254 timerclear(&fra->children_time);
255 fra->children_ops = 0;
258 void profile_out(glui32 stackuse)
262 struct timeval now, runtime;
265 if (!profiling_active)
268 /* printf("### OUT\n"); */
271 fatal_error("Profiler: stack underflow.");
273 gettimeofday(&now, NULL);
278 timersub(&now, &fra->entry_time, &runtime);
279 runops = profile_opcount - fra->entry_op;
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;
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;
292 timeradd(&runtime, &fra->parent->children_time, &fra->parent->children_time);
293 fra->parent->children_ops += runops;
296 if (!func->entry_depth)
297 fatal_error("Profiler: function entry underflow.");
299 func->entry_depth -= 1;
300 if (!func->entry_depth) {
301 timersub(&now, &func->entry_start_time, &runtime);
302 timerclear(&func->entry_start_time);
304 runops = profile_opcount - func->entry_start_op;
305 func->entry_start_op = 0;
307 timeradd(&runtime, &func->total_time, &func->total_time);
308 func->total_ops += runops;
311 current_frame = fra->parent;
317 /* ### throw/catch */
318 /* ### restore/restore_undo/restart */
320 void profile_fail(char *reason)
322 if (!profiling_active)
325 fatal_error_2("Profiler: unable to handle operation", reason);
335 if (!profiling_active)
338 while (current_frame) {
342 if (profiling_stream) {
343 profstr = profiling_stream;
345 else if (profiling_filename) {
346 frefid_t profref = glk_fileref_create_by_name(fileusage_BinaryMode|fileusage_Data, profiling_filename, 0);
348 fatal_error_2("Profiler: unable to create profile output fileref", profiling_filename);
350 profstr = glk_stream_open_file(profref, filemode_Write, 0);
353 fatal_error("Profiler: no profile output handle!");
356 glk_put_string_stream(profstr, "<profile>\n");
358 for (bucknum=0; bucknum<FUNC_HASH_SIZE; bucknum++) {
359 char total_buf[20], self_buf[20];
361 for (func = functions[bucknum]; func; func=func->hash_next) {
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,
366 timeprint(&func->total_time, total_buf),
368 timeprint(&func->self_time, self_buf));
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);
381 glk_put_string_stream(profstr, "</profile>\n");
383 glk_stream_close(profstr, NULL);
385 glulx_free(functions);
389 #else /* VM_PROFILING */
391 void setup_profile(strid_t stream, char *filename)
393 /* Profiling is not compiled in. Do nothing. */
398 /* Profiling is not compiled in. Do nothing. */
402 #endif /* VM_PROFILING */