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 called "profile-raw". This is an XML file of
24 The function list includes every function which was called during the
25 program's run. Each function tag includes the following attributes:
27 addr=HEX: The VM address of the function (in hex).
28 call_count=INT: The number of times the function was called.
29 accel_count=INT: The number of times the function was called with
31 total_time=FLOAT: The amount of time spent during all calls to the
32 function (in seconds, as a floating-point value).
33 total_ops=INT: The number of opcodes executed during all calls to
35 self_time=FLOAT: The amount of time spent during all calls to the
36 function, excluding time spent in subcalls (functions called *by* the
38 self_ops=INT: The number of opcodes executed during all calls to
39 the function, excluding time spent in subcalls.
41 Note that if a function does not make any function calls, total_time
42 will be the same as self_time (and total_ops the same as self_ops).
44 Two special function entries may be included. The function with address
45 "1" (which is not a legal Glulx function address) represents time spent
46 in @glk opcode calls. This will typically have a large self_time,
47 because it includes all the time spent waiting for input.
49 The function with address "2" represents the time spent printing string
50 data (the @streamchar, @streamunichar, @streamnum, and @streamstr
53 (Both "1" and "2" represent time spent in the Glk library, but they
54 get there by different code paths.)
56 The function with the lowest address (ignoring "1" and "2") is the
57 top-level Main__() function generated by the compiler. Its total_time
58 is the running time of the entire program.
71 typedef struct function_struct {
77 struct timeval entry_start_time;
78 glui32 entry_start_op;
79 struct timeval total_time;
81 struct timeval self_time;
84 struct function_struct *hash_next;
87 typedef struct frame_struct {
88 struct frame_struct *parent;
91 struct timeval entry_time;
94 struct timeval children_time;
98 #define FUNC_HASH_SIZE (511)
100 static function_t **functions = NULL;
101 static frame_t *current_frame = NULL;
103 glui32 profile_opcount = 0;
109 functions = (function_t **)glulx_malloc(FUNC_HASH_SIZE
110 * sizeof(function_t *));
114 for (bucknum=0; bucknum<FUNC_HASH_SIZE; bucknum++)
115 functions[bucknum] = NULL;
120 static function_t *get_function(glui32 addr)
122 int bucknum = (addr % FUNC_HASH_SIZE);
125 for (func = (functions[bucknum]);
126 func && func->addr != addr;
127 func = func->hash_next) { }
130 func = (function_t *)glulx_malloc(sizeof(function_t));
132 fatal_error("Profiler: cannot malloc function.");
133 memset(func, 0, sizeof(function_t));
134 func->hash_next = functions[bucknum];
135 functions[bucknum] = func;
138 func->call_count = 0;
139 func->accel_count = 0;
140 timerclear(&func->entry_start_time);
141 func->entry_start_op = 0;
142 timerclear(&func->total_time);
144 timerclear(&func->self_time);
151 static char *timeprint(struct timeval *tv, char *buf)
153 sprintf(buf, "%ld.%.6ld", (long)tv->tv_sec, (long)tv->tv_usec);
157 void profile_in(glui32 addr, int accel)
163 /* printf("### IN: %lx%s\n", addr, (accel?" accel":"")); */
165 gettimeofday(&now, NULL);
167 func = get_function(addr);
168 func->call_count += 1;
170 func->accel_count += 1;
171 if (!func->entry_depth) {
172 func->entry_start_time = now;
173 func->entry_start_op = profile_opcount;
175 func->entry_depth += 1;
177 fra = (frame_t *)glulx_malloc(sizeof(frame_t));
179 fatal_error("Profiler: cannot malloc frame.");
180 memset(fra, 0, sizeof(frame_t));
182 fra->parent = current_frame;
186 fra->entry_time = now;
187 fra->entry_op = profile_opcount;
188 timerclear(&fra->children_time);
189 fra->children_ops = 0;
196 struct timeval now, runtime;
199 /* printf("### OUT\n"); */
202 fatal_error("Profiler: stack underflow.");
204 gettimeofday(&now, NULL);
209 timersub(&now, &fra->entry_time, &runtime);
210 runops = profile_opcount - fra->entry_op;
212 timeradd(&runtime, &func->self_time, &func->self_time);
213 timersub(&func->self_time, &fra->children_time, &func->self_time);
214 func->self_ops += runops;
215 func->self_ops -= fra->children_ops;
218 timeradd(&runtime, &fra->parent->children_time, &fra->parent->children_time);
219 fra->parent->children_ops += runops;
222 if (!func->entry_depth)
223 fatal_error("Profiler: function entry underflow.");
225 func->entry_depth -= 1;
226 if (!func->entry_depth) {
227 timersub(&now, &func->entry_start_time, &runtime);
228 timerclear(&func->entry_start_time);
230 runops = profile_opcount - func->entry_start_op;
231 func->entry_start_op = 0;
233 timeradd(&runtime, &func->total_time, &func->total_time);
234 func->total_ops += runops;
237 current_frame = fra->parent;
243 /* ### throw/catch */
244 /* ### restore/restore_undo/restart */
246 void profile_fail(char *reason)
248 fatal_error_2("Profiler: unable to handle operation", reason);
259 while (current_frame) {
263 profref = glk_fileref_create_by_name(fileusage_BinaryMode|fileusage_Data, "profile-raw", 0);
265 fatal_error("Profiler: unable to create profile-raw file");
267 profstr = glk_stream_open_file(profref, filemode_Write, 0);
269 glk_put_string_stream(profstr, "<profile>\n");
271 for (bucknum=0; bucknum<FUNC_HASH_SIZE; bucknum++) {
272 char total_buf[20], self_buf[20];
274 for (func = functions[bucknum]; func; func=func->hash_next) {
276 sprintf(linebuf, "function %lx called %ld times, total ops %ld, total time %s, self ops %ld, self time %s\n",
277 func->addr, func->call_count,
279 timeprint(&func->total_time, total_buf),
281 timeprint(&func->self_time, self_buf));
283 sprintf(linebuf, " <function addr=\"%lx\" call_count=\"%ld\" accel_count=\"%ld\" total_ops=\"%ld\" total_time=\"%s\" self_ops=\"%ld\" self_time=\"%s\" />\n",
284 func->addr, func->call_count, func->accel_count,
286 timeprint(&func->total_time, total_buf),
288 timeprint(&func->self_time, self_buf));
289 glk_put_string_stream(profstr, linebuf);
293 glk_put_string_stream(profstr, "</profile>\n");
295 glk_stream_close(profstr, NULL);
297 glulx_free(functions);
301 #else /* VM_PROFILING */
305 /* Profiling is not compiled in. Do nothing. */
309 #endif /* VM_PROFILING */