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()