Fixed ordering of the application of the styles
[rodin/chimara.git] / interpreters / glulxe / profile-analyze.py
1 #!/usr/bin/python
2
3 """
4 This script reads in the profile-raw file generated by Glulxe profiling,
5 and lists the ten most costly functions. (In terms of how much total time
6 was spent inside each function. If a function calls other functions, the
7 time spent in them is not charged to the parent; that is, a function
8 which does nothing but call other functions will be considered uncostly.)
9
10 Optionally, this script can also read the debug output of the Inform 6
11 compiler (or the assembly output), and use that to figure out the
12 names of all the functions that were profiled.
13
14 Using this script is currently a nuisance. The requirements:
15
16 - You must compile Glulxe with profiling (the VM_PROFILING compile-time
17   option).
18 - (If you want function names) you should compile your Inform 6 source
19   using the -k switch. This generates a "gameinfo.dbg" file.
20 - Run Glulxe, play some of the game, and quit. This generates a data
21   file called "profile-raw".
22 - Run this script, giving gameinfo.dbg and profile-raw as arguments.
23
24 To sum up, in command-line form:
25
26 % inform -G -k game.inf
27 % glulxe game.ulx
28 % python profile-analyze.py profile-raw gameinfo.dbg
29
30 You can also use the assembly output of the Inform compiler, which you
31 get with the -a switch. Save the output and use it instead of the debug
32 file:
33
34 % inform -G -a game.inf > game.asm
35 % glulxe game.ulx
36 % python profile-analyze.py profile-raw game.asm
37
38 The limitations:
39
40 The profiling code is not smart about VM operations that rearrange the
41 call stack. In fact, it's downright stupid. @restart, @restore,
42 @restoreundo, or @throw will kill the interpreter.
43
44 Inform's -k switch does not work correctly with game files larger than
45 16 megabytes.
46
47 Inform's -a switch does not display code for veneer functions, so if
48 you use that data, these will not be named; they will be listed as
49 "<???>". This is a particular nuisance because veneer functions are
50 often the most costly ones. (Therefore, you'll almost certainly want
51 to use -k.)
52
53 You can explore the profiling data in more detail by running the script
54 interactively:
55
56 % python -i profile-analyze.py profile-raw game.asm
57
58 After it runs, you'll be left at a Python prompt. The environment
59 will contain mappings called "functions" (mapping addresses to
60 function objects), and "function_names" (names to function objects).
61
62 >>> functions[0x3c]
63 <Function $3c 'Main__'>
64 >>> function_names['Main__']
65 <Function $3c 'Main__'>
66 >>> function_names['Main__'].dump()
67 Main__:
68   at $00003c (line 0); called 1 times
69   0.000067 sec (1 ops) spent executing
70   6.273244 sec (117578 ops) including child calls
71
72 A Function object has lots of attributes:
73  
74   addr=INT:         The VM address of the function (in hex).
75   hexaddr=STRING:   The VM address of the function in hex (as a string).
76   name=STRING:      The function's name, or '<???>' if the function is
77     not known (veneer functions).
78   linenum=INT:      The line number of the function from the source code,
79     or 0 if it is not derived from source (Main__, etc).
80   call_count=INT:   The number of times the function was called.
81   accel_count=INT:  The number of times the function was called with
82     acceleration.
83   total_time=FLOAT: The amount of time spent during all calls to the
84     function (in seconds, as a floating-point value).
85   total_ops=INT:    The number of opcodes executed during all calls to
86     the function.
87   self_time=FLOAT:  The amount of time spent during all calls to the
88     function, excluding time spent in subcalls (functions called *by* the
89     function).
90   self_ops=INT:     The number of opcodes executed during all calls to
91     the function, excluding time spent in subcalls.
92
93 (The self_time is the "cost" used for the original listing.)
94
95 Note that if a function does not make any function calls, total_time
96 will be the same as self_time (and total_ops the same as self_ops).
97
98 Two special function entries may be included. The function with address
99 "1" (which is not a legal Glulx function address) represents time spent
100 in @glk opcode calls. This will typically have a large self_time, 
101 because it includes all the time spent waiting for input.
102
103 The function with address "2" represents the time spent printing string
104 data (the @streamchar, @streamunichar, @streamnum, and @streamstr
105 opcodes).
106
107 (Both "1" and "2" represent time spent in the Glk library, but they
108 get there by different code paths.)
109
110 The function with the lowest address (ignoring "1" and "2") is the
111 top-level Main__() function generated by the compiler. Its total_time
112 is the running time of the entire program.
113
114 """
115
116 import sys, os.path
117 import xml.sax
118 from struct import unpack
119
120 if (len(sys.argv) < 2):
121     print "Usage: profile-analyze.py profile-raw [ gameinfo.dbg | game.asm ]"
122     sys.exit(1)
123
124 profile_raw = sys.argv[1]
125 if (not os.path.exists(profile_raw)):
126     print 'File not readable:', profile_raw
127     sys.exit(1)
128
129 game_asm = None
130 if (len(sys.argv) >= 3):
131     game_asm = sys.argv[2]
132     if (not os.path.exists(game_asm)):
133         print 'File not readable:', game_asm
134         sys.exit(1)
135
136 special_functions = {
137     1: 'glk', 2: 'streamout'
138 }
139 max_special_functions = max(special_functions.keys())
140
141 functions = None
142 sourcemap = None
143
144 class Function:
145     def __init__(self, addr, hexaddr, attrs):
146         self.addr = addr
147         self.hexaddr = hexaddr
148         val = special_functions.get(addr)
149         if (val is None):
150             self.name = '<???>'
151             self.special = False
152         else:
153             self.name = '<@' + val + '>'
154             self.special = True
155         self.linenum = 0
156         self.call_count =   int(attrs['call_count'])
157         self.accel_count = 0
158         if (attrs.has_key('accel_count')):
159             self.accel_count = int(attrs['accel_count'])
160         self.total_ops  =   int(attrs['total_ops'])
161         self.total_time = float(attrs['total_time'])
162         self.self_ops   =   int(attrs['self_ops'])
163         self.self_time  = float(attrs['self_time'])
164         
165     def __repr__(self):
166         return '<Function $' + self.hexaddr + ' ' + repr(self.name) + '>'
167
168     def dump(self):
169         print '%s:' % (self.name,)
170         val = ''
171         if (self.accel_count):
172             val = ' (%d accelerated)' % (self.accel_count,)
173         print '  at $%06x (line %d); called %d times%s' % (self.addr, self.linenum,self.call_count,val)
174         print '  %.6f sec (%d ops) spent executing' % (self.self_time, self.self_ops)
175         print '  %.6f sec (%d ops) including child calls' % (self.total_time, self.total_ops)
176
177 class ProfileRawHandler(xml.sax.handler.ContentHandler):
178     def startElement(self, name, attrs):
179         global functions
180         
181         if (name == 'profile'):
182             functions = {}
183         if (name == 'function'):
184             hexaddr = attrs.get('addr')
185             addr = int(hexaddr, 16)
186             func = Function(addr, hexaddr, attrs)
187             functions[addr] = func
188
189 def parse_asm(fl):
190     global sourcemap
191     sourcemap = {}
192     
193     lasttup = None
194     while True:
195         ln = fl.readline()
196         if (not ln):
197             break
198         ln = ln.strip()
199         ls = ln.split()
200         if (lasttup and not ls):
201             (linenum, funcname, addr) = lasttup
202             sourcemap[addr] = (linenum, funcname)
203         lasttup = None
204         try:
205             if (len(ls) >= 4 and ls[2] == '[' and ls[1].startswith('+')):
206                 linenum = int(ls[0])
207                 funcname = ls[3]
208                 addr = int(ls[1][1:], 16)
209                 lasttup = (linenum, funcname, addr)
210         except ValueError:
211             pass
212
213 class InformFunc:
214     def __init__(self, funcnum):
215         self.funcnum = funcnum
216         self.name = '<???>'
217         self.addr = 0
218         self.linenum = None
219         self.endaddr = None
220         self.endlinenum = None
221         self.locals = None
222         self.seqpts = None
223     def __repr__(self):
224         return '<InformFunc $' + hex(self.addr)[2:] + ' ' + repr(self.name) + '>'
225             
226 class DebugFile:
227     def __init__(self, fl):
228         self.files = {}
229         self.functions = {}
230         self.function_names = {}
231         self.classes = []
232         self.objects = {}
233         self.arrays = {}
234         self.globals = {}
235         self.properties = {}
236         self.attributes = {}
237         self.actions = {}
238         self.fake_actions = {}
239         self.map = {}
240         self.header = None
241         
242         dat = fl.read(2)
243         val = unpack('>H', dat)[0]
244         if (val != 0xDEBF):
245             raise ValueError('not an Inform debug file')
246             
247         dat = fl.read(2)
248         self.debugversion = unpack('>H', dat)[0]
249         dat = fl.read(2)
250         self.informversion = unpack('>H', dat)[0]
251
252         rectable = {
253             1:  self.read_file_rec,
254             2:  self.read_class_rec,
255             3:  self.read_object_rec,
256             4:  self.read_global_rec,
257             5:  self.read_attr_rec,
258             6:  self.read_prop_rec,
259             7:  self.read_fake_action_rec,
260             8:  self.read_action_rec,
261             9:  self.read_header_rec,
262             10: self.read_lineref_rec,
263             11: self.read_routine_rec,
264             12: self.read_array_rec,
265             13: self.read_map_rec,
266             14: self.read_routine_end_rec,
267         }
268
269         while True:
270             dat = fl.read(1)
271             rectype = unpack('>B', dat)[0]
272             if (rectype == 0):
273                 break
274             recfunc = rectable.get(rectype)
275             if (not recfunc):
276                 raise ValueError('unknown debug record type: %d' % (rectype,))
277             recfunc(fl)
278
279         for func in self.functions.values():
280             self.function_names[func.name] = func
281
282     def read_file_rec(self, fl):
283         dat = fl.read(1)
284         filenum = unpack('>B', dat)[0]
285         includename = self.read_string(fl)
286         realname = self.read_string(fl)
287         self.files[filenum] = ( includename, realname )
288         
289     def read_class_rec(self, fl):
290         name = self.read_string(fl)
291         start = self.read_linenum(fl)
292         end = self.read_linenum(fl)
293         self.classes.append( (name, start, end) )
294         
295     def read_object_rec(self, fl):
296         dat = fl.read(2)
297         num = unpack('>H', dat)[0]
298         name = self.read_string(fl)
299         start = self.read_linenum(fl)
300         end = self.read_linenum(fl)
301         self.objects[num] = (name, start, end)
302     
303     def read_global_rec(self, fl):
304         dat = fl.read(1)
305         num = unpack('>B', dat)[0]
306         name = self.read_string(fl)
307         self.arrays[num] = name
308     
309     def read_array_rec(self, fl):
310         dat = fl.read(2)
311         num = unpack('>H', dat)[0]
312         name = self.read_string(fl)
313         self.arrays[num] = name
314     
315     def read_attr_rec(self, fl):
316         dat = fl.read(2)
317         num = unpack('>H', dat)[0]
318         name = self.read_string(fl)
319         self.attributes[num] = name
320     
321     def read_prop_rec(self, fl):
322         dat = fl.read(2)
323         num = unpack('>H', dat)[0]
324         name = self.read_string(fl)
325         self.properties[num] = name
326     
327     def read_action_rec(self, fl):
328         dat = fl.read(2)
329         num = unpack('>H', dat)[0]
330         name = self.read_string(fl)
331         self.actions[num] = name
332     
333     def read_fake_action_rec(self, fl):
334         dat = fl.read(2)
335         num = unpack('>H', dat)[0]
336         name = self.read_string(fl)
337         self.fake_actions[num] = name
338     
339     def read_routine_rec(self, fl):
340         dat = fl.read(2)
341         funcnum = unpack('>H', dat)[0]
342         func = self.get_function(funcnum)
343         
344         func.linenum = self.read_linenum(fl)
345         dat = fl.read(3)
346         addr = unpack('>I', '\0'+dat)[0]
347         func.addr = int(addr)
348         func.name = self.read_string(fl)
349         locals = []
350         while True:
351             val = self.read_string(fl)
352             if (not val):
353                 break
354             locals.append(val)
355         func.locals = locals
356
357     def read_lineref_rec(self, fl):
358         dat = fl.read(2)
359         funcnum = unpack('>H', dat)[0]
360         func = self.get_function(funcnum)
361
362         if (not func.seqpts):
363             func.seqpts = []
364         
365         dat = fl.read(2)
366         count = unpack('>H', dat)[0]
367         for ix in range(count):
368             linenum = self.read_linenum(fl)
369             dat = fl.read(2)
370             addr = unpack('>H', dat)[0]
371             func.seqpts.append( (linenum, addr) )
372         
373     def read_routine_end_rec(self, fl):
374         dat = fl.read(2)
375         funcnum = unpack('>H', dat)[0]
376         func = self.get_function(funcnum)
377
378         func.endlinenum = self.read_linenum(fl)
379         dat = fl.read(3)
380         addr = unpack('>I', '\0'+dat)[0]
381         func.endaddr = int(addr)
382
383     def read_header_rec(self, fl):
384         dat = fl.read(64)
385         self.header = dat
386     
387     def read_map_rec(self, fl):
388         while True:
389             name = self.read_string(fl)
390             if (not name):
391                 break
392             dat = fl.read(3)
393             addr = unpack('>I', '\0'+dat)[0]
394             addr = int(addr)
395             self.map[name] = addr
396     
397     def read_linenum(self, fl):
398         dat = fl.read(4)
399         (funcnum, linenum, charnum) = unpack('>BHB', dat)
400         return (funcnum, linenum, charnum)
401
402     def read_string(self, fl):
403         val = ''
404         while True:
405             dat = fl.read(1)
406             if (dat == '\0'):
407                 return val
408             val += dat
409
410     def get_function(self, funcnum):
411         func = self.functions.get(funcnum)
412         if (not func):
413             func = InformFunc(funcnum)
414             self.functions[funcnum] = func
415         return func
416                         
417 # Begin the work
418             
419 xml.sax.parse(profile_raw, ProfileRawHandler())
420
421 source_start = min([ func.addr for func in functions.values()
422     if not func.special ])
423 print 'Code segment begins at', hex(source_start)
424
425 print len(functions), 'called functions found in', profile_raw
426
427 if (game_asm):
428     fl = open(game_asm, 'rb')
429     val = fl.read(2)
430     fl.close()
431     if (val == '\xde\xbf'):
432         fl = open(game_asm, 'rb')
433         debugfile = DebugFile(fl)
434         fl.close()
435         sourcemap = {}
436         for func in debugfile.functions.values():
437             sourcemap[func.addr] = ( func.linenum[1], func.name)
438     else:
439         fl = open(game_asm, 'rU')
440         parse_asm(fl)
441         fl.close()
442
443 if (sourcemap):
444     badls = []
445
446     for (addr, func) in functions.items():
447         if (func.special):
448             continue
449         tup = sourcemap.get(addr-source_start)
450         if (not tup):
451             badls.append(addr)
452             continue
453         (linenum, funcname) = tup
454         func.name = funcname
455         func.linenum = linenum
456     
457     if (badls):
458         print len(badls), 'functions from', profile_raw, 'did not appear in asm (veneer functions)'
459     
460     function_names = {}
461     for func in functions.values():
462         function_names[func.name] = func
463
464 if (sourcemap):
465     uncalled_funcs = [ funcname for (addr, (linenum, funcname)) in sourcemap.items() if (addr+source_start) not in functions ]
466     print len(uncalled_funcs), 'functions found in', game_asm, 'were never called'
467
468 print 'Functions that consumed the most time (excluding children):'
469 ls = functions.values()
470 ls.sort(lambda x1, x2: cmp(x2.self_time, x1.self_time))
471 for func in ls[:10]:
472     func.dump()
473