Merge commit 'cbb35cca'
[projects/chimara/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 You can also generate profiling output in the same form as dumbfrotz's
15 Z-machine profiling output. (If that happens to be what you want.) Use
16 the --dumbfrotz argument.
17
18 Using this script is currently a nuisance. The requirements:
19
20 - You must compile Glulxe with profiling (the VM_PROFILING compile-time
21   option).
22 - (If you want function names) you should compile your Inform 6 source
23   using the -k switch. This generates a "gameinfo.dbg" file.
24 - Run Glulxe, using the "--profile profile-raw" option. Play some of
25   the game, and quit. This generates a data file called "profile-raw".
26 - Run this script, giving gameinfo.dbg and profile-raw as arguments.
27   (You can provide dispatch_dump.xml as an optional third argument.
28   This file gives the names of Glk functions; it is available from
29   https://github.com/erkyrath/glk-dev/tree/master/dispatch_dump .)
30
31 To sum up, in command-line form:
32
33 % inform -G -k game.inf
34 % glulxe --profile profile-raw game.ulx
35 % python profile-analyze.py profile-raw gameinfo.dbg dispatch_dump.xml
36
37 You can also use the assembly output of the Inform compiler, which you
38 get with the -a switch. Save the output and use it instead of the debug
39 file:
40
41 % inform -G -a game.inf > game.asm
42 % glulxe --profile profile-raw game.ulx
43 % python profile-analyze.py profile-raw game.asm dispatch_dump.xml
44
45 The limitations:
46
47 The profiling code is not smart about VM operations that rearrange the
48 call stack. In fact, it's downright stupid. @restart, @restore,
49 @restoreundo, or @throw will kill the interpreter.
50
51 Inform's -k switch does not work correctly with game files larger than
52 16 megabytes.
53
54 Inform's -a switch does not display code for veneer functions, so if
55 you use that data, these will not be named; they will be listed as
56 "<???>". This is a particular nuisance because veneer functions are
57 often the most costly ones. (Therefore, you'll almost certainly want
58 to use -k.)
59
60 If you leave off the "dispatch_dump.xml" argument, everything will
61 still work, but @glk function entries will be listed by number rather
62 than by name.
63
64 You can explore the profiling data in more detail by running the script
65 interactively:
66
67 % python -i profile-analyze.py profile-raw game.asm dispatch_dump.xml
68
69 After it runs, you'll be left at a Python prompt. The environment
70 will contain mappings called "functions" (mapping addresses to
71 function objects), and "function_names" (names to function objects).
72
73 >>> functions[0x3c]
74 <Function $3c 'Main__'>
75 >>> function_names['Main__']
76 <Function $3c 'Main__'>
77 >>> function_names['Main__'].dump()
78 Main__:
79   at $00003c (line 0); called 1 times
80   0.000067 sec (1 ops) spent executing
81   6.273244 sec (117578 ops) including child calls
82
83 A Function object has lots of attributes:
84  
85   addr=INT:         The VM address of the function (in hex).
86   hexaddr=STRING:   The VM address of the function in hex (as a string).
87   name=STRING:      The function's name, or '<???>' if the function is
88     not known (veneer functions).
89   linenum=INT:      The line number of the function from the source code,
90     or 0 if it is not derived from source (Main__, etc).
91   call_count=INT:   The number of times the function was called.
92   accel_count=INT:  The number of times the function was called with
93     acceleration.
94   total_time=FLOAT: The amount of time spent during all calls to the
95     function (in seconds, as a floating-point value).
96   total_ops=INT:    The number of opcodes executed during all calls to
97     the function.
98   self_time=FLOAT:  The amount of time spent during all calls to the
99     function, excluding time spent in subcalls (functions called *by* the
100     function).
101   self_ops=INT:     The number of opcodes executed during all calls to
102     the function, excluding time spent in subcalls.
103   max_depth=INT:    The deepest this function has been nested on the
104     stack, during any call.
105   max_stack_use=INT: The greatest number of words on the stack, during
106     any call. (This is measured when the function returns, so it may
107     not capture the peak stack usage. If a function never returns, e.g.
108     Main__(), then this value is approximate.)
109
110 (The self_time is the "cost" used for the original listing.)
111
112 Note that if a function does not make any function calls, total_time
113 will be the same as self_time (and total_ops the same as self_ops).
114
115 Some of the function entries refer to special interpreter operations.
116 (These have high addresses, outside the range of normal game files.)
117 Functions with addresses in the 0xE0000000 range are the interpreter's
118 output opcodes: @streamchar, @streamunichar, @streamnum, @streamstr.
119
120 Functions with addresses in the 0xF0000000 range are @glk opcode calls.
121 The number in the lower bits specifies which Glk function was called.
122 You will always see a large self_time for function 0xF00000C0; this
123 represents all the time spent waiting for input in glk_select().
124
125 (Both the 0xE0000000 and 0xF0000000 entries represent time spent in the
126 Glk library, but they get there by different code paths.)
127
128 The function with the lowest address is the top-level Main__()
129 function generated by the compiler. Its total_time is the running time
130 of the entire program; its total_ops is the number of opcodes executed
131 by the entire program; its max_depth is zero.
132
133 """
134
135 import sys, os.path
136 import xml.sax
137 from struct import unpack
138
139 dumb_frotz_mode = False
140
141 if ('--dumbfrotz' in sys.argv):
142     sys.argv.remove('--dumbfrotz')
143     dumb_frotz_mode = True
144
145 if (len(sys.argv) < 2):
146     print "Usage: profile-analyze.py [--dumbfrotz] profile-raw [ gameinfo.dbg | game.asm ] [ dispatch_dump.xml ]"
147     sys.exit(1)
148
149 profile_raw = sys.argv[1]
150 if (not os.path.exists(profile_raw)):
151     print 'File not readable:', profile_raw
152     sys.exit(1)
153
154 game_asm = None
155 if (len(sys.argv) >= 3):
156     game_asm = sys.argv[2]
157     if (not os.path.exists(game_asm)):
158         print 'File not readable:', game_asm
159         sys.exit(1)
160
161 dispatch_dump = None
162 if (len(sys.argv) >= 4):
163     dispatch_dump = sys.argv[3]
164     if (not os.path.exists(dispatch_dump)):
165         print 'File not readable:', dispatch_dump
166         sys.exit(1)
167
168 special_functions = {
169     0xE0000001: 'streamchar',
170     0xE0000002: 'streamunichar',
171     0xE0000003: 'streamnum',
172     0xE0000004: 'streamstr',
173 }
174
175 glk_functions = {}
176
177 functions = None
178 sourcemap = None
179
180 class Function:
181     def __init__(self, addr, hexaddr, attrs):
182         self.addr = addr
183         self.hexaddr = hexaddr
184         val = special_functions.get(addr)
185         if (addr >= 0xF0000000):
186             name = glk_functions.get(addr-0xF0000000)
187             if (not name):
188                 name = hex(addr-0xF0000000)[2:]
189                 name = '$' + name.replace('L', '')
190             self.name = '<@glk_' + name + '>'
191             self.special = True
192         elif (val is None):
193             self.name = '<???>'
194             self.special = False
195         else:
196             self.name = '<@' + val + '>'
197             self.special = True
198         self.linenum = 0
199         self.call_count =   int(attrs['call_count'])
200         self.accel_count = 0
201         if (attrs.has_key('accel_count')):
202             self.accel_count = int(attrs['accel_count'])
203         self.total_ops  =   int(attrs['total_ops'])
204         self.total_time = float(attrs['total_time'])
205         self.self_ops   =   int(attrs['self_ops'])
206         self.self_time  = float(attrs['self_time'])
207         if (attrs.has_key('max_depth')):
208             self.max_depth     = int(attrs['max_depth'])
209         if (attrs.has_key('max_stack_use')):
210             self.max_stack_use = int(attrs['max_stack_use'])
211         
212     def __repr__(self):
213         return '<Function $' + self.hexaddr + ' ' + repr(self.name) + '>'
214
215     def dump(self):
216         print '%s:' % (self.name,)
217         val = ''
218         if (self.accel_count):
219             val = ' (%d accelerated)' % (self.accel_count,)
220         print '  at $%06x (line %d); called %d times%s' % (self.addr, self.linenum,self.call_count,val)
221         print '  %.6f sec (%d ops) spent executing' % (self.self_time, self.self_ops)
222         print '  %.6f sec (%d ops) including child calls' % (self.total_time, self.total_ops)
223
224     def dump_dumbfrotz_style(self):
225         percent1 = '    '
226         percent2 = '    '
227         pc1 = int(100*(float(self.self_ops)/float(ops_executed)))
228         pc2 = int(100*(float(self.total_ops)/float(ops_executed)))
229         if (pc1 > 0):
230             percent1 = "%3d%%" % pc1
231         if (pc2 > 0):
232             percent2 = "%3d%%" % pc2
233         print '%-36s %s %-10lu %s %-10lu %-10lu %-4d' % (self.name, percent1, self.self_ops, percent2, self.total_ops, self.call_count, self.max_depth)
234
235 class DispatchDumpHandler(xml.sax.handler.ContentHandler):
236     def startElement(self, name, attrs):
237         if (name == 'function'):
238             addr = int(attrs['id'])
239             glk_functions[addr] = str(attrs['name'])
240         
241 class ProfileRawHandler(xml.sax.handler.ContentHandler):
242     def startElement(self, name, attrs):
243         global functions
244         
245         if (name == 'profile'):
246             functions = {}
247         if (name == 'function'):
248             hexaddr = attrs.get('addr')
249             addr = int(hexaddr, 16)
250             func = Function(addr, hexaddr, attrs)
251             functions[addr] = func
252
253 def parse_asm(fl):
254     global sourcemap
255     sourcemap = {}
256     
257     lasttup = None
258     while True:
259         ln = fl.readline()
260         if (not ln):
261             break
262         ln = ln.strip()
263         ls = ln.split()
264         if (lasttup and not ls):
265             (linenum, funcname, addr) = lasttup
266             sourcemap[addr] = (linenum, funcname)
267         lasttup = None
268         try:
269             if (len(ls) >= 4 and ls[2] == '[' and ls[1].startswith('+')):
270                 linenum = int(ls[0])
271                 funcname = ls[3]
272                 addr = int(ls[1][1:], 16)
273                 lasttup = (linenum, funcname, addr)
274         except ValueError:
275             pass
276
277 class InformFunc:
278     def __init__(self, funcnum):
279         self.funcnum = funcnum
280         self.name = '<???>'
281         self.addr = 0
282         self.linenum = None
283         self.endaddr = None
284         self.endlinenum = None
285         self.locals = None
286         self.seqpts = None
287     def __repr__(self):
288         return '<InformFunc $' + hex(self.addr)[2:] + ' ' + repr(self.name) + '>'
289             
290 class DebugFile:
291     def __init__(self, fl):
292         self.files = {}
293         self.functions = {}
294         self.function_names = {}
295         self.classes = []
296         self.objects = {}
297         self.arrays = {}
298         self.globals = {}
299         self.properties = {}
300         self.attributes = {}
301         self.actions = {}
302         self.fake_actions = {}
303         self.map = {}
304         self.header = None
305         
306         dat = fl.read(2)
307         val = unpack('>H', dat)[0]
308         if (val != 0xDEBF):
309             raise ValueError('not an Inform debug file')
310             
311         dat = fl.read(2)
312         self.debugversion = unpack('>H', dat)[0]
313         dat = fl.read(2)
314         self.informversion = unpack('>H', dat)[0]
315
316         rectable = {
317             1:  self.read_file_rec,
318             2:  self.read_class_rec,
319             3:  self.read_object_rec,
320             4:  self.read_global_rec,
321             5:  self.read_attr_rec,
322             6:  self.read_prop_rec,
323             7:  self.read_fake_action_rec,
324             8:  self.read_action_rec,
325             9:  self.read_header_rec,
326             10: self.read_lineref_rec,
327             11: self.read_routine_rec,
328             12: self.read_array_rec,
329             13: self.read_map_rec,
330             14: self.read_routine_end_rec,
331         }
332
333         while True:
334             dat = fl.read(1)
335             rectype = unpack('>B', dat)[0]
336             if (rectype == 0):
337                 break
338             recfunc = rectable.get(rectype)
339             if (not recfunc):
340                 raise ValueError('unknown debug record type: %d' % (rectype,))
341             recfunc(fl)
342
343         for func in self.functions.values():
344             self.function_names[func.name] = func
345
346     def read_file_rec(self, fl):
347         dat = fl.read(1)
348         filenum = unpack('>B', dat)[0]
349         includename = self.read_string(fl)
350         realname = self.read_string(fl)
351         self.files[filenum] = ( includename, realname )
352         
353     def read_class_rec(self, fl):
354         name = self.read_string(fl)
355         start = self.read_linenum(fl)
356         end = self.read_linenum(fl)
357         self.classes.append( (name, start, end) )
358         
359     def read_object_rec(self, fl):
360         dat = fl.read(2)
361         num = unpack('>H', dat)[0]
362         name = self.read_string(fl)
363         start = self.read_linenum(fl)
364         end = self.read_linenum(fl)
365         self.objects[num] = (name, start, end)
366     
367     def read_global_rec(self, fl):
368         dat = fl.read(1)
369         num = unpack('>B', dat)[0]
370         name = self.read_string(fl)
371         self.globals[num] = name
372     
373     def read_array_rec(self, fl):
374         dat = fl.read(2)
375         num = unpack('>H', dat)[0]
376         name = self.read_string(fl)
377         self.arrays[num] = name
378     
379     def read_attr_rec(self, fl):
380         dat = fl.read(2)
381         num = unpack('>H', dat)[0]
382         name = self.read_string(fl)
383         self.attributes[num] = name
384     
385     def read_prop_rec(self, fl):
386         dat = fl.read(2)
387         num = unpack('>H', dat)[0]
388         name = self.read_string(fl)
389         self.properties[num] = name
390     
391     def read_action_rec(self, fl):
392         dat = fl.read(2)
393         num = unpack('>H', dat)[0]
394         name = self.read_string(fl)
395         self.actions[num] = name
396     
397     def read_fake_action_rec(self, fl):
398         dat = fl.read(2)
399         num = unpack('>H', dat)[0]
400         name = self.read_string(fl)
401         self.fake_actions[num] = name
402     
403     def read_routine_rec(self, fl):
404         dat = fl.read(2)
405         funcnum = unpack('>H', dat)[0]
406         func = self.get_function(funcnum)
407         
408         func.linenum = self.read_linenum(fl)
409         dat = fl.read(3)
410         addr = unpack('>I', '\0'+dat)[0]
411         func.addr = int(addr)
412         func.name = self.read_string(fl)
413         locals = []
414         while True:
415             val = self.read_string(fl)
416             if (not val):
417                 break
418             locals.append(val)
419         func.locals = locals
420
421     def read_lineref_rec(self, fl):
422         dat = fl.read(2)
423         funcnum = unpack('>H', dat)[0]
424         func = self.get_function(funcnum)
425
426         if (not func.seqpts):
427             func.seqpts = []
428         
429         dat = fl.read(2)
430         count = unpack('>H', dat)[0]
431         for ix in range(count):
432             linenum = self.read_linenum(fl)
433             dat = fl.read(2)
434             addr = unpack('>H', dat)[0]
435             func.seqpts.append( (linenum, addr) )
436         
437     def read_routine_end_rec(self, fl):
438         dat = fl.read(2)
439         funcnum = unpack('>H', dat)[0]
440         func = self.get_function(funcnum)
441
442         func.endlinenum = self.read_linenum(fl)
443         dat = fl.read(3)
444         addr = unpack('>I', '\0'+dat)[0]
445         func.endaddr = int(addr)
446
447     def read_header_rec(self, fl):
448         dat = fl.read(64)
449         self.header = dat
450     
451     def read_map_rec(self, fl):
452         while True:
453             name = self.read_string(fl)
454             if (not name):
455                 break
456             dat = fl.read(3)
457             addr = unpack('>I', '\0'+dat)[0]
458             addr = int(addr)
459             self.map[name] = addr
460     
461     def read_linenum(self, fl):
462         dat = fl.read(4)
463         (funcnum, linenum, charnum) = unpack('>BHB', dat)
464         return (funcnum, linenum, charnum)
465
466     def read_string(self, fl):
467         val = ''
468         while True:
469             dat = fl.read(1)
470             if (dat == '\0'):
471                 return val
472             val += dat
473
474     def get_function(self, funcnum):
475         func = self.functions.get(funcnum)
476         if (not func):
477             func = InformFunc(funcnum)
478             self.functions[funcnum] = func
479         return func
480                         
481 # Begin the work
482             
483 if (dispatch_dump):
484     xml.sax.parse(dispatch_dump, DispatchDumpHandler())
485         
486 xml.sax.parse(profile_raw, ProfileRawHandler())
487
488 source_start = min([ func.addr for func in functions.values()
489     if not func.special ])
490
491 if (not dumb_frotz_mode):
492     print 'Code segment begins at', hex(source_start)
493     print len(functions), 'called functions found in', profile_raw
494
495 if (game_asm):
496     fl = open(game_asm, 'rb')
497     val = fl.read(2)
498     fl.close()
499     if (not val):
500         pass
501     elif (val == '\xde\xbf'):
502         fl = open(game_asm, 'rb')
503         debugfile = DebugFile(fl)
504         fl.close()
505         sourcemap = {}
506         for func in debugfile.functions.values():
507             sourcemap[func.addr] = ( func.linenum[1], func.name)
508     else:
509         fl = open(game_asm, 'rU')
510         parse_asm(fl)
511         fl.close()
512
513 if (sourcemap):
514     badls = []
515
516     for (addr, func) in functions.items():
517         if (func.special):
518             continue
519         tup = sourcemap.get(addr-source_start)
520         if (not tup):
521             badls.append(addr)
522             continue
523         (linenum, funcname) = tup
524         func.name = funcname
525         func.linenum = linenum
526     
527     if (not dumb_frotz_mode):
528         if (badls):
529             print len(badls), 'functions from', profile_raw, 'did not appear in asm (veneer functions)'
530     
531     function_names = {}
532     for func in functions.values():
533         function_names[func.name] = func
534
535 if (sourcemap):
536     uncalled_funcs = [ funcname for (addr, (linenum, funcname)) in sourcemap.items() if (addr+source_start) not in functions ]
537     if (not dumb_frotz_mode):
538         print len(uncalled_funcs), 'functions found in', game_asm, 'were never called'
539
540 if (dumb_frotz_mode):
541     ls = functions.values()
542     ls.sort(lambda x1, x2: cmp(x2.total_ops, x1.total_ops))
543     ops_executed = 0
544     routine_calls = 0
545     max_stack_use = max([func.max_stack_use for func in ls])
546     for func in ls:
547         if (func.total_ops > ops_executed):
548             ops_executed = func.total_ops
549         routine_calls = routine_calls + func.call_count
550     print 'Total opcodes: %lu' % ops_executed
551     print 'Total routine calls: %lu' % routine_calls
552     print 'Max. stack usage: %li' % max_stack_use
553     print ''
554     print '%-35s      %-10s      %-10s %-10s %-4s' % ('Routine', 'Ops', 'Ops(+Subs)', 'Calls', 'Nest')
555     for func in ls:
556         func.dump_dumbfrotz_style()
557 else:
558     print 'Functions that consumed the most time (excluding children):'
559     ls = functions.values()
560     ls.sort(lambda x1, x2: cmp(x2.self_time, x1.self_time))
561     for func in ls[:10]:
562         func.dump()