Fixed ordering of the application of the styles
[rodin/chimara.git] / interpreters / glulxe / profile.c
1 /* profile.c: Glulxe profiling functions.
2     Designed by Andrew Plotkin <erkyrath@eblong.com>
3     http://eblong.com/zarf/glulx/index.html
4 */
5
6 /* 
7 If compiled in, these functions maintain a collection of profiling
8 information as the Glulx program executes.
9
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.
13
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
16 the form
17
18 <profile>
19   <function ... />
20   <function ... />
21   ...
22 </profile>
23
24 The function list includes every function which was called during the
25 program's run. Each function tag includes the following attributes:
26  
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
30     acceleration.
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
34     the function.
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
37     function).
38   self_ops=INT:     The number of opcodes executed during all calls to
39     the function, excluding time spent in subcalls.
40
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).
43
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.
48
49 The function with address "2" represents the time spent printing string
50 data (the @streamchar, @streamunichar, @streamnum, and @streamstr
51 opcodes).
52
53 (Both "1" and "2" represent time spent in the Glk library, but they
54 get there by different code paths.)
55
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.
59
60  */
61
62 #include "glk.h"
63 #include "glulxe.h"
64
65 #if VM_PROFILING
66
67 #include <stdio.h>
68 #include <string.h>
69 #include <sys/time.h>
70
71 typedef struct function_struct {
72   glui32 addr;
73
74   glui32 call_count;
75   glui32 accel_count;
76   glui32 entry_depth;
77   struct timeval entry_start_time;
78   glui32 entry_start_op;
79   struct timeval total_time;
80   glui32 total_ops;
81   struct timeval self_time;
82   glui32 self_ops;
83
84   struct function_struct *hash_next;
85 } function_t;
86
87 typedef struct frame_struct {
88   struct frame_struct *parent;
89   function_t *func;
90
91   struct timeval entry_time;
92   glui32 entry_op;
93
94   struct timeval children_time;
95   glui32 children_ops;
96 } frame_t;
97
98 #define FUNC_HASH_SIZE (511)
99
100 static function_t **functions = NULL;
101 static frame_t *current_frame = NULL;
102
103 glui32 profile_opcount = 0;
104
105 int init_profile()
106 {
107   int bucknum;
108
109   functions = (function_t **)glulx_malloc(FUNC_HASH_SIZE
110     * sizeof(function_t *));
111   if (!functions) 
112     return FALSE;
113
114   for (bucknum=0; bucknum<FUNC_HASH_SIZE; bucknum++) 
115     functions[bucknum] = NULL;
116
117   return TRUE;
118 }
119
120 static function_t *get_function(glui32 addr)
121 {
122   int bucknum = (addr % FUNC_HASH_SIZE);
123   function_t *func;
124
125   for (func = (functions[bucknum]); 
126        func && func->addr != addr;
127        func = func->hash_next) { }
128
129   if (!func) {
130     func = (function_t *)glulx_malloc(sizeof(function_t));
131     if (!func)
132       fatal_error("Profiler: cannot malloc function.");
133     memset(func, 0, sizeof(function_t));
134     func->hash_next = functions[bucknum];
135     functions[bucknum] = func;
136
137     func->addr = addr;
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);
143     func->total_ops = 0;
144     timerclear(&func->self_time);
145     func->self_ops = 0;
146   }
147
148   return func;
149 }
150
151 static char *timeprint(struct timeval *tv, char *buf)
152 {
153   sprintf(buf, "%ld.%.6ld", (long)tv->tv_sec, (long)tv->tv_usec);
154   return buf;
155 }
156
157 void profile_in(glui32 addr, int accel)
158 {
159   frame_t *fra;
160   function_t *func;
161   struct timeval now;
162
163   /* printf("### IN: %lx%s\n", addr, (accel?" accel":"")); */
164
165   gettimeofday(&now, NULL);
166
167   func = get_function(addr);
168   func->call_count += 1;
169   if (accel)
170     func->accel_count += 1;
171   if (!func->entry_depth) {
172     func->entry_start_time = now;
173     func->entry_start_op = profile_opcount;
174   }
175   func->entry_depth += 1;
176
177   fra = (frame_t *)glulx_malloc(sizeof(frame_t));
178   if (!fra)
179     fatal_error("Profiler: cannot malloc frame.");
180   memset(fra, 0, sizeof(frame_t));
181
182   fra->parent = current_frame;
183   current_frame = fra;
184
185   fra->func = func;
186   fra->entry_time = now;
187   fra->entry_op = profile_opcount;
188   timerclear(&fra->children_time);
189   fra->children_ops = 0;
190 }
191
192 void profile_out()
193 {
194   frame_t *fra;
195   function_t *func;
196   struct timeval now, runtime;
197   glui32 runops;
198
199   /* printf("### OUT\n"); */
200
201   if (!current_frame) 
202     fatal_error("Profiler: stack underflow.");
203
204   gettimeofday(&now, NULL);
205
206   fra = current_frame;
207   func = fra->func;
208
209   timersub(&now, &fra->entry_time, &runtime);
210   runops = profile_opcount - fra->entry_op;
211
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;
216
217   if (fra->parent) {
218     timeradd(&runtime, &fra->parent->children_time, &fra->parent->children_time);
219     fra->parent->children_ops += runops;
220   }
221
222   if (!func->entry_depth) 
223     fatal_error("Profiler: function entry underflow.");
224   
225   func->entry_depth -= 1;
226   if (!func->entry_depth) {
227     timersub(&now, &func->entry_start_time, &runtime);
228     timerclear(&func->entry_start_time);
229
230     runops = profile_opcount - func->entry_start_op;
231     func->entry_start_op = 0;
232
233     timeradd(&runtime, &func->total_time, &func->total_time);
234     func->total_ops += runops;
235   }
236
237   current_frame = fra->parent;
238   fra->parent = NULL;
239
240   glulx_free(fra);
241 }
242
243 /* ### throw/catch */
244 /* ### restore/restore_undo/restart */
245
246 void profile_fail(char *reason)
247 {
248   fatal_error_2("Profiler: unable to handle operation", reason);
249 }
250
251 void profile_quit()
252 {
253   int bucknum;
254   function_t *func;
255   char linebuf[512];
256   frefid_t profref;
257   strid_t profstr;
258
259   while (current_frame) {
260     profile_out();
261   }
262
263   profref = glk_fileref_create_by_name(fileusage_BinaryMode|fileusage_Data, "profile-raw", 0);
264   if (!profref)
265     fatal_error("Profiler: unable to create profile-raw file");
266
267   profstr = glk_stream_open_file(profref, filemode_Write, 0);
268
269   glk_put_string_stream(profstr, "<profile>\n");
270
271   for (bucknum=0; bucknum<FUNC_HASH_SIZE; bucknum++) {
272     char total_buf[20], self_buf[20];
273
274     for (func = functions[bucknum]; func; func=func->hash_next) {
275       /* ###
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,
278         func->total_ops,
279         timeprint(&func->total_time, total_buf),
280         func->self_ops,
281         timeprint(&func->self_time, self_buf));
282       ### */
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,
285         func->total_ops,
286         timeprint(&func->total_time, total_buf),
287         func->self_ops,
288         timeprint(&func->self_time, self_buf));
289       glk_put_string_stream(profstr, linebuf);
290     }
291   }
292
293   glk_put_string_stream(profstr, "</profile>\n");
294
295   glk_stream_close(profstr, NULL);
296
297   glulx_free(functions);
298   functions = NULL;
299 }
300
301 #else /* VM_PROFILING */
302
303 int init_profile()
304 {
305     /* Profiling is not compiled in. Do nothing. */
306     return TRUE;
307 }
308
309 #endif /* VM_PROFILING */