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