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.)
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.
14 Using this script is currently a nuisance. The requirements:
16 - You must compile Glulxe with profiling (the VM_PROFILING compile-time
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.
24 To sum up, in command-line form:
26 % inform -G -k game.inf
28 % python profile-analyze.py profile-raw gameinfo.dbg
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
34 % inform -G -a game.inf > game.asm
36 % python profile-analyze.py profile-raw game.asm
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.
44 Inform's -k switch does not work correctly with game files larger than
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
53 You can explore the profiling data in more detail by running the script
56 % python -i profile-analyze.py profile-raw game.asm
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).
63 <Function $3c 'Main__'>
64 >>> function_names['Main__']
65 <Function $3c 'Main__'>
66 >>> function_names['Main__'].dump()
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
72 A Function object has lots of attributes:
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
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
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
90 self_ops=INT: The number of opcodes executed during all calls to
91 the function, excluding time spent in subcalls.
93 (The self_time is the "cost" used for the original listing.)
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).
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.
103 The function with address "2" represents the time spent printing string
104 data (the @streamchar, @streamunichar, @streamnum, and @streamstr
107 (Both "1" and "2" represent time spent in the Glk library, but they
108 get there by different code paths.)
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.
118 from struct import unpack
120 if (len(sys.argv) < 2):
121 print "Usage: profile-analyze.py profile-raw [ gameinfo.dbg | game.asm ]"
124 profile_raw = sys.argv[1]
125 if (not os.path.exists(profile_raw)):
126 print 'File not readable:', profile_raw
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
136 special_functions = {
137 1: 'glk', 2: 'streamout'
139 max_special_functions = max(special_functions.keys())
145 def __init__(self, addr, hexaddr, attrs):
147 self.hexaddr = hexaddr
148 val = special_functions.get(addr)
153 self.name = '<@' + val + '>'
156 self.call_count = int(attrs['call_count'])
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'])
166 return '<Function $' + self.hexaddr + ' ' + repr(self.name) + '>'
169 print '%s:' % (self.name,)
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)
177 class ProfileRawHandler(xml.sax.handler.ContentHandler):
178 def startElement(self, name, attrs):
181 if (name == 'profile'):
183 if (name == 'function'):
184 hexaddr = attrs.get('addr')
185 addr = int(hexaddr, 16)
186 func = Function(addr, hexaddr, attrs)
187 functions[addr] = func
200 if (lasttup and not ls):
201 (linenum, funcname, addr) = lasttup
202 sourcemap[addr] = (linenum, funcname)
205 if (len(ls) >= 4 and ls[2] == '[' and ls[1].startswith('+')):
208 addr = int(ls[1][1:], 16)
209 lasttup = (linenum, funcname, addr)
214 def __init__(self, funcnum):
215 self.funcnum = funcnum
220 self.endlinenum = None
224 return '<InformFunc $' + hex(self.addr)[2:] + ' ' + repr(self.name) + '>'
227 def __init__(self, fl):
230 self.function_names = {}
238 self.fake_actions = {}
243 val = unpack('>H', dat)[0]
245 raise ValueError('not an Inform debug file')
248 self.debugversion = unpack('>H', dat)[0]
250 self.informversion = unpack('>H', dat)[0]
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,
271 rectype = unpack('>B', dat)[0]
274 recfunc = rectable.get(rectype)
276 raise ValueError('unknown debug record type: %d' % (rectype,))
279 for func in self.functions.values():
280 self.function_names[func.name] = func
282 def read_file_rec(self, fl):
284 filenum = unpack('>B', dat)[0]
285 includename = self.read_string(fl)
286 realname = self.read_string(fl)
287 self.files[filenum] = ( includename, realname )
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) )
295 def read_object_rec(self, fl):
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)
303 def read_global_rec(self, fl):
305 num = unpack('>B', dat)[0]
306 name = self.read_string(fl)
307 self.arrays[num] = name
309 def read_array_rec(self, fl):
311 num = unpack('>H', dat)[0]
312 name = self.read_string(fl)
313 self.arrays[num] = name
315 def read_attr_rec(self, fl):
317 num = unpack('>H', dat)[0]
318 name = self.read_string(fl)
319 self.attributes[num] = name
321 def read_prop_rec(self, fl):
323 num = unpack('>H', dat)[0]
324 name = self.read_string(fl)
325 self.properties[num] = name
327 def read_action_rec(self, fl):
329 num = unpack('>H', dat)[0]
330 name = self.read_string(fl)
331 self.actions[num] = name
333 def read_fake_action_rec(self, fl):
335 num = unpack('>H', dat)[0]
336 name = self.read_string(fl)
337 self.fake_actions[num] = name
339 def read_routine_rec(self, fl):
341 funcnum = unpack('>H', dat)[0]
342 func = self.get_function(funcnum)
344 func.linenum = self.read_linenum(fl)
346 addr = unpack('>I', '\0'+dat)[0]
347 func.addr = int(addr)
348 func.name = self.read_string(fl)
351 val = self.read_string(fl)
357 def read_lineref_rec(self, fl):
359 funcnum = unpack('>H', dat)[0]
360 func = self.get_function(funcnum)
362 if (not func.seqpts):
366 count = unpack('>H', dat)[0]
367 for ix in range(count):
368 linenum = self.read_linenum(fl)
370 addr = unpack('>H', dat)[0]
371 func.seqpts.append( (linenum, addr) )
373 def read_routine_end_rec(self, fl):
375 funcnum = unpack('>H', dat)[0]
376 func = self.get_function(funcnum)
378 func.endlinenum = self.read_linenum(fl)
380 addr = unpack('>I', '\0'+dat)[0]
381 func.endaddr = int(addr)
383 def read_header_rec(self, fl):
387 def read_map_rec(self, fl):
389 name = self.read_string(fl)
393 addr = unpack('>I', '\0'+dat)[0]
395 self.map[name] = addr
397 def read_linenum(self, fl):
399 (funcnum, linenum, charnum) = unpack('>BHB', dat)
400 return (funcnum, linenum, charnum)
402 def read_string(self, fl):
410 def get_function(self, funcnum):
411 func = self.functions.get(funcnum)
413 func = InformFunc(funcnum)
414 self.functions[funcnum] = func
419 xml.sax.parse(profile_raw, ProfileRawHandler())
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)
425 print len(functions), 'called functions found in', profile_raw
428 fl = open(game_asm, 'rb')
431 if (val == '\xde\xbf'):
432 fl = open(game_asm, 'rb')
433 debugfile = DebugFile(fl)
436 for func in debugfile.functions.values():
437 sourcemap[func.addr] = ( func.linenum[1], func.name)
439 fl = open(game_asm, 'rU')
446 for (addr, func) in functions.items():
449 tup = sourcemap.get(addr-source_start)
453 (linenum, funcname) = tup
455 func.linenum = linenum
458 print len(badls), 'functions from', profile_raw, 'did not appear in asm (veneer functions)'
461 for func in functions.values():
462 function_names[func.name] = func
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'
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))