profile-analyze.py

#!/usr/bin/python

from __future__ import print_function

"""
This script reads in the profile-raw file generated by Glulxe profiling,
and lists the ten most costly functions. (In terms of how much total time
was spent inside each function. If a function calls other functions, the
time spent in them is not charged to the parent; that is, a function
which does nothing but call other functions will be considered uncostly.)

Optionally, this script can also read the debug output of the Inform 6
compiler (or the assembly output), and use that to figure out the
names of all the functions that were profiled. Both the old and new
(Inform 6.33) debug file format are supported.

You can also generate profiling output in the same form as dumbfrotz's
Z-machine profiling output. (If that happens to be what you want.) Use
the --dumbfrotz argument.

Using this script is currently a nuisance. The requirements:

- You must compile Glulxe with profiling (the VM_PROFILING compile-time
  option).
- (If you want function names) you should compile your Inform 6 source
  using the -k switch. This generates a "gameinfo.dbg" file.
- Run Glulxe, using the "--profile profile-raw" option. (Optionally,
  also the "--profcalls" option.) Play some of the game, and quit. This
  generates a data file called "profile-raw".
- Run this script, giving gameinfo.dbg and profile-raw as arguments.
- You can provide "--glk dispatch_dump.xml" as an optional extra argument.
  This file gives the names of Glk functions; it is available from
  https://github.com/erkyrath/glk-dev/tree/master/dispatch_dump .

To sum up, in command-line form:

% inform -G -k game.inf
% glulxe --profile profile-raw game.ulx
% python profile-analyze.py profile-raw gameinfo.dbg --glk dispatch_dump.xml

You can replace the debug output with the assembly output of the Inform
compiler, which you get with the -a switch. Save the output and use it
instead of the debug file:

% inform -G -a game.inf > game.asm
% glulxe --profile profile-raw game.ulx
% python profile-analyze.py profile-raw game.asm --glk dispatch_dump.xml

* The output:

The output will be a list of ten functions, showing how much time and
how many CPU cycles each one cost. Both the function's own cost and its
cost including children (the functions it calls itself) are shown.

(The top function is generally @glk_$c0 (or @glk_select). This just means
that the game spent a lot of time waiting for user input.)

You can change how many functions are listed with the --count option.
You can change the sorting criterion with the --sort option: the options
are self_time, self_ops, total_time, total_ops, and call_count.

* The limitations:

The profiling code is not smart about VM operations that rearrange the
call stack. In fact, it's downright stupid. @restart, @restore,
@restoreundo, or @throw will kill the interpreter.

The old debug file format (Inform 6.32 and earlier) does not work correctly
with game files larger than 16 megabytes. 

If you leave off the "--glk dispatch_dump.xml" argument, everything will
still work, but @glk function entries will be listed by number rather
than by name.

If you included the "--profcalls" argument when running Glulxe, the
function information will include the number of times it called, and was
called by, every other function. This is rather slow, so it distorts
the function timing information. Only use "--profcalls" when you are
interested in specific call patterns (i.e., trying to identify where
a particular function is being called from).

* Interactive browsing:

You can explore the profiling data in more detail by running the script
interactively:

% python -i profile-analyze.py profile-raw game.asm --glk dispatch_dump.xml

After it runs, you'll be left at a Python prompt. You might want to list
functions sorted in other ways:

>>> list_by('total_time')      # top 10 by total time including children
>>> list_by('total_ops')       # top 10 by total CPU cycles including children
>>> list_by('self_ops', 20)    # top 20 by CPU cycles excluding children

You can also dig into the data directly. The environment will contain
mappings called "functions" (mapping addresses to function objects), and
"function_names" (names to function objects).

>>> functions[0x3c]
<Function $3c 'Main__'>
>>> function_names['Main__']
<Function $3c 'Main__'>
>>> function_names['Main__'].dump()
Main__:
  at $00003c (line 0); called 1 times
  0.000067 sec (1 ops) spent executing
  6.273244 sec (117578 ops) including child calls
>>> function_names['Main__'].show_calls()
Main__:
  at $00003c (line 0); called 1 times:
  made 1 calls to other functions:
    1 to <Function $48 "Main">

(Again, the show_calls() information is only available if you use the
"--profcalls" argument when running Glulxe.)

A Function object has lots of attributes:
 
  addr=INT:         The VM address of the function (in hex).
  hexaddr=STRING:   The VM address of the function in hex (as a string).
  name=STRING:      The function's name, or '<???>' if the function is
    not known (veneer functions).
  linenum=INT:      The line number of the function from the source code,
    or 0 if it is not derived from source (Main__, etc).
  call_count=INT:   The number of times the function was called.
  accel_count=INT:  The number of times the function was called with
    acceleration.
  total_time=FLOAT: The amount of time spent during all calls to the
    function (in seconds, as a floating-point value).
  total_ops=INT:    The number of opcodes executed during all calls to
    the function.
  self_time=FLOAT:  The amount of time spent during all calls to the
    function, excluding time spent in subcalls (functions called *by* the
    function).
  self_ops=INT:     The number of opcodes executed during all calls to
    the function, excluding time spent in subcalls.
  max_depth=INT:    The deepest this function has been nested on the
    stack, during any call.
  max_stack_use=INT: The greatest number of words on the stack, during
    any call. (This is measured when the function returns, so it may
    not capture the peak stack usage. If a function never returns, e.g.
    Main__(), then this value is approximate.)

(The self_time is the "cost" used for the original listing.)

Note that if a function does not make any function calls, total_time
will be the same as self_time (and total_ops the same as self_ops).

Some of the function entries refer to special interpreter operations.
(These have high addresses, outside the range of normal game files.)
Functions with addresses in the 0xE0000000 range are the interpreter's
output opcodes: @streamchar, @streamunichar, @streamnum, @streamstr.

Functions with addresses in the 0xF0000000 range are @glk opcode calls.
The number in the lower bits specifies which Glk function was called.
You will always see a large self_time for function 0xF00000C0; this
represents all the time spent waiting for input in glk_select().

(Both the 0xE0000000 and 0xF0000000 entries represent time spent in the
Glk library, but they get there by different code paths.)

The function with the lowest address is the top-level Main__()
function generated by the compiler. Its total_time is the running time
of the entire program; its total_ops is the number of opcodes executed
by the entire program; its max_depth is zero.

* Debug file browsing:

If you just want to browse an Inform debug file, and bypass all the
profiling stuff, just do:

# python -i profile-analyze.py -d gameinfo.dbg

This will leave you at a Python prompt. The global "debugfile" contains
the parsed debug information, which you can browse:

>>> debugfile.arrays[0]
<Array "gg_event", 4 els of 4 bytes (16 total), at 160940
  (<SourceLoc "parserm" line 96>)>

"""

import sys, os.path
import optparse
import io
import xml.sax
from struct import unpack
from chunk import Chunk

popt = optparse.OptionParser(usage='profile-analyze.py [options] profile-raw [ gameinfo.dbg | game.asm ]')

popt.add_option('--glk',
                action='store', dest='dispatchfile', metavar='DISPATCH_DUMP',
                help='path to dispatch_dump.xml file (optional)')
popt.add_option('--dumbfrotz',
                action='store_true', dest='dumbfrotz',
                help='use dumbfrotz-compatible output format')
popt.add_option('-d', '--debug',
                action='store_true', dest='debugonly',
                help='read only the debug data, no profile data')
popt.add_option('-c', '--count',
                action='store', dest='listcount',
                type=int, default=10,
                help='list the N slowest functions')
popt.add_option('-s', '--sort',
                action='store', dest='listsort',
                type=str, default='self_time',
                help='sort criterion for functions (self_time, self_ops, total_time, total_ops, call_count)')

(opts, args) = popt.parse_args()

if (not args):
    print('Usage: profile-analyze.py [--dumbfrotz] [--glk dispatch_dump.xml] profile-raw [ gameinfo.dbg | game.asm ]')
    sys.exit(1)

profile_raw = None
game_file_data = None

if not opts.debugonly:
    # Normal operation
    profile_raw = args[0]
    if (not os.path.exists(profile_raw)):
        print('File not readable:', profile_raw)
        sys.exit(1)

    if (len(args) >= 2):
        game_file_data = args[1]
        if (not os.path.exists(game_file_data)):
            print('File not readable:', game_file_data)
            sys.exit(1)
else:
    # Debug-only operation
    game_file_data = args[0]
    if (not os.path.exists(game_file_data)):
        print('File not readable:', game_file_data)
        sys.exit(1)

if (opts.dispatchfile):
    if (not os.path.exists(opts.dispatchfile)):
        print('File not readable:', opts.dispatchfile)
        sys.exit(1)

special_functions = {
    0xE0000001: 'streamchar',
    0xE0000002: 'streamunichar',
    0xE0000003: 'streamnum',
    0xE0000004: 'streamstr',
}

glk_functions = {}

functions = None
callcounts = None
sourcemap = None

class Function:
    def __init__(self, addr, hexaddr, attrs):
        self.addr = addr
        self.hexaddr = hexaddr
        val = special_functions.get(addr)
        if (addr >= 0xF0000000):
            name = glk_functions.get(addr-0xF0000000)
            if (not name):
                name = hex(addr-0xF0000000)[2:]
                name = '$' + name.replace('L', '')
            self.name = '<@glk_' + name + '>'
            self.special = True
        elif (val is None):
            self.name = '<???>'
            self.special = False
        else:
            self.name = '<@' + val + '>'
            self.special = True
        self.linenum = 0
        self.call_count  =  int(attrs['call_count'])
        self.accel_count = 0
        val = attrs.get('accel_count')
        if (val):
            self.accel_count   = int(val)
        self.total_ops  =   int(attrs['total_ops'])
        self.total_time = float(attrs['total_time'])
        self.self_ops   =   int(attrs['self_ops'])
        self.self_time  = float(attrs['self_time'])
        val = attrs.get('max_depth')
        if (val):
            self.max_depth     = int(val)
        val = attrs.get('max_stack_use')
        if (val):
            self.max_stack_use = int(val)
        self.incalls = {}
        self.outcalls = {}
        
    def __repr__(self):
        return '<Function $' + self.hexaddr + ' "' + self.name + '">'

    def dump(self):
        print('%s:' % (self.name,))
        print('  %s' % (self.get_summary(),))
        print('  %.6f sec (%d ops) spent executing' % (self.self_time, self.self_ops))
        print('  %.6f sec (%d ops) including child calls' % (self.total_time, self.total_ops))

    def dump_dumbfrotz_style(self):
        percent1 = '    '
        percent2 = '    '
        pc1 = int(100*(float(self.self_ops)/float(ops_executed)))
        pc2 = int(100*(float(self.total_ops)/float(ops_executed)))
        if (pc1 > 0):
            percent1 = "%3d%%" % pc1
        if (pc2 > 0):
            percent2 = "%3d%%" % pc2
        print('%-36s %s %-10lu %s %-10lu %-10lu %-4d' % (self.name, percent1, self.self_ops, percent2, self.total_ops, self.call_count, self.max_depth))

    def get_summary(self):
        res = 'at $%06x' % (self.addr,)
        if (self.linenum):
            res += ' (line %d)' % (self.linenum,)
        res += '; called %d times' % (self.call_count,)
        if (self.accel_count):
            res += ' (%d accelerated)' % (self.accel_count,)
        return res
        
    def show_calls(self):
        if not callcounts:
            raise Exception('Profile data did not include call counts!')
        print('%s:' % (self.name,))
        print('  %s:' % (self.get_summary(),))
        ls = list(self.incalls.items())
        ls.sort()  # by addr
        for (addr, count) in ls:
            func = functions.get(addr, '<???>')
            print('    %d from %s' % (count, func))
        ls = list(self.outcalls.items())
        ls.sort()  # by addr
        val = sum([count for (addr, count) in ls])
        print('  made %d calls to other functions:' % (val,))
        for (addr, count) in ls:
            func = functions.get(addr, '<???>')
            print('    %d to %s' % (count, func))

class DispatchDumpHandler(xml.sax.handler.ContentHandler):
    def startElement(self, name, attrs):
        if (name == 'function'):
            addr = int(attrs['id'])
            glk_functions[addr] = str(attrs['name'])
        
class ProfileRawHandler(xml.sax.handler.ContentHandler):
    def startElement(self, name, attrs):
        global functions, callcounts
        
        if (name == 'profile'):
            functions = {}
            callcounts = {}
        if (name == 'function'):
            hexaddr = attrs.get('addr')
            addr = int(hexaddr, 16)
            func = Function(addr, hexaddr, attrs)
            functions[addr] = func
        if (name == 'calls'):
            hexaddr = attrs.get('fromaddr')
            fromaddr = int(hexaddr, 16)
            hexaddr = attrs.get('toaddr')
            toaddr = int(hexaddr, 16)
            count = int(attrs.get('count'))
            callcounts[(fromaddr, toaddr)] = count

class SFrameHandler:
    def __init__(self, tag, parent=None, depth=None, children={}, active=None, handler=None):
        self.tag = tag
        self.parent = parent
        self.depth = depth
        self.children = children
        self.handler = handler
        if active is None:
            active = (handler is not None)
        self.active = active

class SFrameFrame:
    def __init__(self, name, attrs, depth):
        self.name = name
        self.attrs = attrs
        self.depth = depth
        self.children = None
        self.handler = None
        self.accumchar = None
        self.accumobj = None

    def final(self):
        self.name = None
        self.attrs = None
        self.children = None
        self.handler = None
        self.accumchar = None
        self.accumobj = None
            
class SimpleXMLFrame(xml.sax.handler.ContentHandler):
    def __init__(self):
        xml.sax.handler.ContentHandler.__init__(self)
        self.sstack = None
        self.taghandlers = {}
        self.init()

    def startDocument(self):
        self.sstack = []

    def endDocument(self):
        assert len(self.sstack) == 0
        
    def startElement(self, name, attrs):
        parframe = None
        if self.sstack:
            parframe = self.sstack[-1]
            
        frame = SFrameFrame(name, attrs, len(self.sstack))
        self.sstack.append(frame)

        parhan = None
        if parframe and parframe.children:
            parhan = parframe.children.get(name)
        if parhan is not None:
            if type(parhan) is list:
                parhan = parhan[0]
            frame.handler = parhan
            if parhan in (int, str):
                frame.accumchar = []
            elif parhan is ():
                taghan = self.taghandlers[name]
                frame.handler = taghan
                frame.children = taghan.children
                frame.accumobj = {}
            elif callable(parhan):
                frame.handler = parhan
                frame.accumchar = []
            else:
                raise Exception('unknown element handler thingie: %s' % (parhan,))
        else:
            taghan = self.taghandlers.get(name)
            if taghan:
                active = taghan.active
                if active:
                    if taghan.parent is not None:
                        if not (parframe and parframe.name == taghan.parent):
                            active = False
                    if taghan.depth is not None:
                        if not (frame.depth == taghan.depth):
                            active = False
                if active:
                    frame.handler = taghan
                    frame.children = taghan.children
                    frame.accumobj = {}

    def characters(self, data):
        frame = self.sstack[-1]
        if frame.accumchar is not None:
            frame.accumchar.append(data)

    def endElement(self, name):
        frame = self.sstack.pop()
        assert frame.name == name
        
        res = None
        if frame.handler is None:
            pass
        elif frame.handler is str:
            res = ''.join(frame.accumchar)
        elif frame.handler is int:
            val = ''.join(frame.accumchar)
            res = int(val.strip())
        elif isinstance(frame.handler, SFrameHandler):
            if frame.handler.handler:
                res = frame.handler.handler(frame.name, frame.attrs, frame.accumobj)
            else:
                res = frame.accumobj
        elif callable(frame.handler):
            val = ''.join(frame.accumchar)
            res = frame.handler(frame.name, frame.attrs, val)
        else:
            raise Exception('unknown element handler thingie: %s' % (frame.handler,))
        
        frame.final()
        
        if self.sstack and res is not None:
            parframe = self.sstack[-1]
            if parframe.accumobj is not None:
                if type(parframe.children.get(name)) is list:
                    subls = parframe.accumobj.get(name)
                    if subls:
                        subls.append(res)
                    else:
                        subls = [ res ]
                        parframe.accumobj[name] = subls
                else:
                    parframe.accumobj[name] = res

    def handle_tag(self, tag, parent=None, depth=None, children={},
                   active=None, handler=None):
        self.taghandlers[tag] = SFrameHandler(tag, parent, depth, children, active, handler)

class NewDebugFile:
    def __init__(self):
        self.sourcefiles = {}
        self.constants = {}
        self.objects = []
        self.globals = []
        self.arrays = []
        self.functions = []

class NewDebugSourceFile:
    def __init__(self, index, filename):
        self.index = index
        self.filename = filename
    def __repr__(self):
        return '<SourceFile %d: "%s">' % (self.index, self.filename,)

class NewDebugConstant:
    def __init__(self, ident, value=None, sourceloc=None):
        self.id = ident
        self.value = value
        if not sourceloc:
            sourceloc = 'compiler'
        self.sourceloc = sourceloc
    def __repr__(self):
        return '<Constant "%s": %d (%s)>' % (self.id, self.value, self.sourceloc)

class NewDebugObject:
    def __init__(self, ident, value=None, sourceloc=None, artificial=False):
        self.id = ident
        self.value = value
        if not sourceloc:
            sourceloc = 'compiler'
        self.sourceloc = sourceloc
        self.artificial = '*' if artificial else ''
    def __repr__(self):
        return '<Object "%s"%s: %d (%s)>' % (self.id, self.artificial, self.value, self.sourceloc)

class NewDebugGlobal:
    def __init__(self, ident, address, sourceloc=None):
        self.id = ident
        self.address = address
        if not sourceloc:
            sourceloc = 'compiler'
        self.sourceloc = sourceloc
    def __repr__(self):
        return '<Global "%s" at %d (%s)>' % (self.id, self.address, self.sourceloc)

class NewDebugArray:
    def __init__(self, ident, address, bytecount, bytesperel, sourceloc=None):
        self.id = ident
        self.address = address
        self.bytecount = bytecount
        self.bytesperel = bytesperel
        self.elcount = bytecount / bytesperel
        if not sourceloc:
            sourceloc = 'compiler'
        self.sourceloc = sourceloc
    def __repr__(self):
        return '<Array "%s", %d els of %d bytes (%d total), at %d (%s)>' % (self.id, self.elcount, self.bytesperel, self.bytecount, self.address, self.sourceloc)

class NewDebugFunction:
    def __init__(self, ident, address, args=(), sourceloc=None, artificial=False):
        self.id = ident
        self.address = address
        self.args = args
        if not sourceloc:
            sourceloc = 'veneer'
        self.sourceloc = sourceloc
        self.artificial = '*' if artificial else ''
    def __repr__(self):
        return '<Function "%s"%s at %d (%s)>' % (self.id, self.artificial, self.address, self.sourceloc)

class NewDebugSourceLoc:
    def __init__(self, line, fileref=None):
        self.line = line
        self.fileref = fileref
    def __repr__(self):
        if (isinstance(self.fileref, NewDebugSourceFile)):
            return '<SourceLoc "%s" line %d>' % (self.fileref.filename, self.line)
        elif (self.fileref):
            return '<SourceLoc file #%d, line %d>' % (self.fileref, self.line)
        else:
            return '<SourceLoc line %d>' % (self.line,)

class NewDebugHandler(SimpleXMLFrame):
    def init(self):
        self._debugfile = NewDebugFile()
        
        self.handle_tag('source', parent='inform-story-file',
                        children={'given-path':str},
                        handler=self.handle_source_file)
        self.handle_tag('constant', parent='inform-story-file',
                        children={'identifier':str, 'value':int, 'source-code-location':()},
                        handler=self.handle_constant)
        self.handle_tag('object', parent='inform-story-file',
                        children={'identifier':self.handle_ident_artificial, 'value':int, 'source-code-location':()},
                        handler=self.handle_object)
        self.handle_tag('global-variable', parent='inform-story-file',
                        children={'identifier':str, 'address':int, 'source-code-location':()},
                        handler=self.handle_global_var)
        self.handle_tag('array', parent='inform-story-file',
                        children={'identifier':str, 'value':int, 'byte-count':int, 'bytes-per-element':int, 'source-code-location':()},
                        handler=self.handle_array)
        self.handle_tag('routine', parent='inform-story-file',
                        children={'identifier':self.handle_ident_artificial, 'address':int, 'source-code-location':(), 'local-variable':[()]},
                        handler=self.handle_function)
        self.handle_tag('source-code-location', active=False,
                        children={'line':int, 'file-index':int},
                        handler=self.handle_source_code_loc)
        self.handle_tag('local-variable',
                        children={'identifier':str})

    def debugfile(self):
        return self._debugfile

    def handle_source_file(self, name, attrs, obj):
        srcfile = NewDebugSourceFile(int(attrs['index']), obj['given-path'])
        self._debugfile.sourcefiles[srcfile.index] = srcfile

    def handle_constant(self, name, attrs, obj):
        con = NewDebugConstant(obj['identifier'], obj.get('value'), obj.get('source-code-location'))
        self._debugfile.constants[con.id] = con

    def handle_object(self, name, attrs, obj):
        (ident, artificial) = obj['identifier']
        con = NewDebugObject(ident, obj.get('value'), obj.get('source-code-location'), artificial=artificial)
        self._debugfile.objects.append(con)

    def handle_global_var(self, name, attrs, obj):
        glob = NewDebugGlobal(obj['identifier'], obj['address'], obj.get('source-code-location'))
        self._debugfile.globals.append(glob)

    def handle_array(self, name, attrs, obj):
        arr = NewDebugArray(obj['identifier'], obj['value'], obj['byte-count'], obj['bytes-per-element'], obj.get('source-code-location'))
        self._debugfile.arrays.append(arr)

    def handle_function(self, name, attrs, obj):
        (ident, artificial) = obj['identifier']
        args = obj.get('local-variable')
        if not args:
            args = ()
        else:
            args = tuple([ loc['identifier'] for loc in args ])
        func = NewDebugFunction(ident, obj['address'], args, obj.get('source-code-location'), artificial=artificial)
        self._debugfile.functions.append(func)

    def handle_ident_artificial(self, name, attrs, obj):
        artificial = attrs.get('artificial')
        return (obj.strip(), artificial)

    def handle_source_code_loc(self, name, attrs, obj):
        fileref = obj.get('file-index')
        if fileref is not None:
            srcfile = self._debugfile.sourcefiles.get(fileref)
            if srcfile:
                fileref = srcfile
        return NewDebugSourceLoc(obj['line'], fileref)

            
def parse_inform_assembly(fl):
    global sourcemap
    sourcemap = {}
    
    lasttup = None
    while True:
        ln = fl.readline()
        if (not ln):
            break
        ln = ln.strip()
        ls = ln.split()
        if (lasttup and not ls):
            (linenum, funcname, addr) = lasttup
            sourcemap[addr] = (linenum, funcname)
        lasttup = None
        try:
            if (len(ls) >= 4 and ls[2] == '[' and ls[1].startswith('+')):
                linenum = int(ls[0])
                funcname = ls[3]
                addr = int(ls[1][1:], 16)
                lasttup = (linenum, funcname, addr)
        except ValueError:
            pass

class InformFunc:
    def __init__(self, funcnum):
        self.funcnum = funcnum
        self.name = '<???>'
        self.addr = 0
        self.linenum = None
        self.endaddr = None
        self.endlinenum = None
        self.locals = None
        self.seqpts = None
    def __repr__(self):
        return '<InformFunc $' + hex(self.addr)[2:] + ' ' + repr(self.name) + '>'
            
class DebugFile:
    def __init__(self, fl):
        self.files = {}
        self.functions = {}
        self.function_names = {}
        self.classes = []
        self.objects = {}
        self.arrays = {}
        self.globals = {}
        self.properties = {}
        self.attributes = {}
        self.actions = {}
        self.fake_actions = {}
        self.map = {}
        self.header = None
        
        dat = fl.read(2)
        val = unpack('>H', dat)[0]
        if (val != 0xDEBF):
            raise ValueError('not an Inform debug file')
            
        dat = fl.read(2)
        self.debugversion = unpack('>H', dat)[0]
        dat = fl.read(2)
        self.informversion = unpack('>H', dat)[0]

        rectable = {
            1:  self.read_file_rec,
            2:  self.read_class_rec,
            3:  self.read_object_rec,
            4:  self.read_global_rec,
            5:  self.read_attr_rec,
            6:  self.read_prop_rec,
            7:  self.read_fake_action_rec,
            8:  self.read_action_rec,
            9:  self.read_header_rec,
            10: self.read_lineref_rec,
            11: self.read_routine_rec,
            12: self.read_array_rec,
            13: self.read_map_rec,
            14: self.read_routine_end_rec,
        }

        while True:
            dat = fl.read(1)
            rectype = unpack('>B', dat)[0]
            if (rectype == 0):
                break
            recfunc = rectable.get(rectype)
            if (not recfunc):
                raise ValueError('unknown debug record type: %d' % (rectype,))
            recfunc(fl)

        for func in self.functions.values():
            self.function_names[func.name] = func

    def read_file_rec(self, fl):
        dat = fl.read(1)
        filenum = unpack('>B', dat)[0]
        includename = self.read_string(fl)
        realname = self.read_string(fl)
        self.files[filenum] = ( includename, realname )
        
    def read_class_rec(self, fl):
        name = self.read_string(fl)
        start = self.read_linenum(fl)
        end = self.read_linenum(fl)
        self.classes.append( (name, start, end) )
        
    def read_object_rec(self, fl):
        dat = fl.read(2)
        num = unpack('>H', dat)[0]
        name = self.read_string(fl)
        start = self.read_linenum(fl)
        end = self.read_linenum(fl)
        self.objects[num] = (name, start, end)
    
    def read_global_rec(self, fl):
        dat = fl.read(1)
        num = unpack('>B', dat)[0]
        name = self.read_string(fl)
        self.globals[num] = name
    
    def read_array_rec(self, fl):
        dat = fl.read(2)
        num = unpack('>H', dat)[0]
        name = self.read_string(fl)
        self.arrays[num] = name
    
    def read_attr_rec(self, fl):
        dat = fl.read(2)
        num = unpack('>H', dat)[0]
        name = self.read_string(fl)
        self.attributes[num] = name
    
    def read_prop_rec(self, fl):
        dat = fl.read(2)
        num = unpack('>H', dat)[0]
        name = self.read_string(fl)
        self.properties[num] = name
    
    def read_action_rec(self, fl):
        dat = fl.read(2)
        num = unpack('>H', dat)[0]
        name = self.read_string(fl)
        self.actions[num] = name
    
    def read_fake_action_rec(self, fl):
        dat = fl.read(2)
        num = unpack('>H', dat)[0]
        name = self.read_string(fl)
        self.fake_actions[num] = name
    
    def read_routine_rec(self, fl):
        dat = fl.read(2)
        funcnum = unpack('>H', dat)[0]
        func = self.get_function(funcnum)
        
        func.linenum = self.read_linenum(fl)
        dat = fl.read(3)
        addr = unpack('>I', b'\0'+dat)[0]
        func.addr = int(addr)
        func.name = self.read_string(fl)
        locals = []
        while True:
            val = self.read_string(fl)
            if (not val):
                break
            locals.append(val)
        func.locals = locals

    def read_lineref_rec(self, fl):
        dat = fl.read(2)
        funcnum = unpack('>H', dat)[0]
        func = self.get_function(funcnum)

        if (not func.seqpts):
            func.seqpts = []
        
        dat = fl.read(2)
        count = unpack('>H', dat)[0]
        for ix in range(count):
            linenum = self.read_linenum(fl)
            dat = fl.read(2)
            addr = unpack('>H', dat)[0]
            func.seqpts.append( (linenum, addr) )
        
    def read_routine_end_rec(self, fl):
        dat = fl.read(2)
        funcnum = unpack('>H', dat)[0]
        func = self.get_function(funcnum)

        func.endlinenum = self.read_linenum(fl)
        dat = fl.read(3)
        addr = unpack('>I', b'\0'+dat)[0]
        func.endaddr = int(addr)

    def read_header_rec(self, fl):
        dat = fl.read(64)
        self.header = dat
    
    def read_map_rec(self, fl):
        while True:
            name = self.read_string(fl)
            if (not name):
                break
            dat = fl.read(3)
            addr = unpack('>I', b'\0'+dat)[0]
            addr = int(addr)
            self.map[name] = addr
    
    def read_linenum(self, fl):
        dat = fl.read(4)
        (funcnum, linenum, charnum) = unpack('>BHB', dat)
        return (funcnum, linenum, charnum)

    def read_string(self, fl):
        val = b''
        while True:
            dat = fl.read(1)
            if (dat == b'\0'):
                return val.decode()
            val += dat

    def get_function(self, funcnum):
        func = self.functions.get(funcnum)
        if (not func):
            func = InformFunc(funcnum)
            self.functions[funcnum] = func
        return func

# A simple I/O wrapper class: read a subrange of a (readable binary)
# file. We use this to treat a Blorb chunk as a readable file.
class BinaryRangeIO(io.RawIOBase):
    def __init__(self, file, start, length):
        self.file = file
        self.start = start
        self.length = length
        self.offset = 0
        self.file.seek(self.start)

    def readable(self):
        return True

    def close(self):
        self.file = None
        io.RawIOBase.close(self)

    def tell(self):
        return self.offset

    def readinto(self, dat):
        count = len(dat)
        if count > self.length - self.offset:
            count = self.length - self.offset
            newdat = self.file.read(count)
            newlen = len(newdat)
            dat[:newlen] = newdat
        else:
            newlen = self.file.readinto(dat)
        self.offset += newlen
        return newlen

def typestring(dat):
    return "'" + dat.decode() + "'"

class BlorbChunk:
    def __init__(self, formchunk, typ, start, len, formtype=None):
        self.formchunk = formchunk
        self.type = typ
        self.start = start
        self.len = len
        self.formtype = formtype
        
    def __repr__(self):
        return '<BlorbChunk %s at %d, len %d>' % (typestring(self.type), self.start, self.len)
    
    def data(self, max=None):
        self.formchunk.seek(self.start)
        toread = self.len
        if (max is not None):
            toread = min(self.len, max)
        return self.formchunk.read(toread)

    def describe(self):
        if (not self.formtype):
            return '%s (%d bytes, start %d)' % (typestring(self.type), self.len, self.start)
        else:
            return '%s/%s (%d+8 bytes, start %d)' % (typestring(self.type), typestring(self.formtype), self.len, self.start)

def blorb_find_debug_chunk(filename):
    file = open(filename, 'rb')
    formchunk = Chunk(file)
    formchunk = formchunk

    if (formchunk.getname() != b'FORM'):
        raise Exception('This does not appear to be a Blorb file.')
    formtype = formchunk.read(4)
    if (formtype != b'IFRS'):
        raise Exception('This does not appear to be a Blorb file.')

    chunks = []
    debugchunk = None
    
    formlen = formchunk.getsize()
    while formchunk.tell() < formlen:
        chunk = Chunk(formchunk)
        start = formchunk.tell()
        size = chunk.getsize()
        formtype = None
        if chunk.getname() == b'FORM':
            formtype = chunk.read(4)
        subchunk = BlorbChunk(formchunk, chunk.getname(), start, size, formtype)
        chunks.append(subchunk)
        chunk.skip()
        chunk.close()

    for chunk in chunks:
        if (chunk.type == b'Dbug'):
            debugchunk = chunk

    formchunk.close()
    file.close()
    file = None

    return debugchunk

    
def list_by(key='self_time', limit=10):
    ls = functions.values()
    ls.sort(lambda x1, x2: cmp(getattr(x2, key), getattr(x1, key)))
    for func in ls[:limit]:
        func.dump()

# Read in the various files
            
if (opts.dispatchfile):
    # Fills out the glk_functions global
    xml.sax.parse(opts.dispatchfile, DispatchDumpHandler())

if (profile_raw):
    # Fills out the functions global
    xml.sax.parse(profile_raw, ProfileRawHandler())

need_function_address_offset = False

if (game_file_data):
    # Fill out the sourcemap global, by one of various methods
    fl = open(game_file_data, 'rb')
    val = fl.read(2)
    fl.close()
    if (not val):
        pass
    elif (val == b'\xde\xbf'):
        # Old-style Inform debug info.
        need_function_address_offset = True
        fl = open(game_file_data, 'rb')
        debugfile = DebugFile(fl)
        fl.close()
        sourcemap = {}
        for func in debugfile.functions.values():
            sourcemap[func.addr] = ( func.linenum[1], func.name )
    elif (val == b'<?'):
        # New-style Inform debug info.
        han = NewDebugHandler()
        xml.sax.parse(game_file_data, han)
        debugfile = han.debugfile()
        sourcemap = {}
        for func in debugfile.functions:
            linenum = 0
            if func.sourceloc and isinstance(func.sourceloc, NewDebugSourceLoc):
                linenum = func.sourceloc.line
            sourcemap[func.address] = ( linenum, func.id )
    elif (val == b'\x46\x4F'):
        # Looks like a Blorb file. Scan for a Dbug chunk.
        debugchunk = blorb_find_debug_chunk(game_file_data)
        if not debugchunk:
            raise Exception('This Blorb file has no Dbug chunk.')
        # Now we check the contents, which means repeating a
        # bunch of the above code.
        fl = open(game_file_data, 'rb')
        fl.seek(debugchunk.start+8)
        val = fl.read(2)
        if (val == b'\xde\xbf'):
            need_function_address_offset = True
            subfl = BinaryRangeIO(fl, debugchunk.start+8, debugchunk.len)
            debugfile = DebugFile(fl)
            subfl.close()
            sourcemap = {}
            for func in debugfile.functions.values():
                sourcemap[func.addr] = ( func.linenum[1], func.name )
        elif (val == b'<?'):
            subfl = BinaryRangeIO(fl, debugchunk.start+8, debugchunk.len)
            han = NewDebugHandler()
            xml.sax.parse(subfl, han)
            subfl.close()
            debugfile = han.debugfile()
            sourcemap = {}
            for func in debugfile.functions:
                linenum = 0
                if func.sourceloc and isinstance(func.sourceloc, NewDebugSourceLoc):
                    linenum = func.sourceloc.line
                sourcemap[func.address] = ( linenum, func.id )
        else:
            raise Exception('Blorb Dbug chunk was not recognized.')
        fl.close()
    else:
        # Assume it's an Inform assembly dump.
        need_function_address_offset = True
        fl = open(game_file_data, 'rU')
        parse_inform_assembly(fl)
        fl.close()

if (profile_raw):
    # If there is profile data, display it.
    
    source_start = min([ func.addr for func in functions.values()
        if not func.special ])

    # For old debug formats, all the function addresses are relative to
    # the start of function memory. For the new format, they're all
    # correct as-is.
    if need_function_address_offset:
        function_address_offset = source_start
    else:
        function_address_offset = 0
    
    if (not opts.dumbfrotz):
        print('Code segment begins at', hex(source_start))
        print(len(functions), 'called functions found in', profile_raw)

    for (tup, count) in callcounts.items():
        (fromaddr, toaddr) = tup
        fromfunc = functions.get(fromaddr)
        tofunc = functions.get(toaddr)
        if (fromfunc):
            fromfunc.outcalls[toaddr] = count
        if (tofunc):
            tofunc.incalls[fromaddr] = count
    
    if (sourcemap):
        badls = []
    
        for (addr, func) in functions.items():
            if (func.special):
                continue
            tup = sourcemap.get(addr-function_address_offset)
            if (not tup):
                badls.append(addr)
                continue
            (linenum, funcname) = tup
            func.name = funcname
            func.linenum = linenum
        
        if (not opts.dumbfrotz):
            if (badls):
                print(len(badls), 'functions from', profile_raw, 'did not appear in asm (veneer functions)')
        
        function_names = {}
        for func in functions.values():
            function_names[func.name] = func
    
    if (sourcemap):
        uncalled_funcs = [ funcname for (addr, (linenum, funcname)) in sourcemap.items() if (addr+function_address_offset) not in functions ]
        if (not opts.dumbfrotz):
            print(len(uncalled_funcs), 'functions found in', game_file_data, 'were never called')
    
    if (opts.dumbfrotz):
        ls = functions.values()
        ls.sort(lambda x1, x2: cmp(x2.total_ops, x1.total_ops))
        ops_executed = 0
        routine_calls = 0
        max_stack_use = max([func.max_stack_use for func in ls])
        for func in ls:
            if (func.total_ops > ops_executed):
                ops_executed = func.total_ops
            routine_calls = routine_calls + func.call_count
        print('Total opcodes: %lu' % ops_executed)
        print('Total routine calls: %lu' % routine_calls)
        print('Max. stack usage: %li' % max_stack_use)
        print('')
        print('%-35s      %-10s      %-10s %-10s %-4s' % ('Routine', 'Ops', 'Ops(+Subs)', 'Calls', 'Nest'))
        for func in ls:
            func.dump_dumbfrotz_style()
    else:
        print('Functions that consumed the most time (excluding children):')
        ls = list(functions.values())
        
        sortfunc = lambda fn:-fn.self_time
        if (opts.listsort in ('self_time', 'self-time', 'selftime')):
            sortfunc = lambda fn:-fn.self_time
        elif (opts.listsort in ('self_ops', 'self-ops', 'selfops')):
            sortfunc = lambda fn:-fn.self_ops
        elif (opts.listsort in ('total_time', 'total-time', 'totaltime')):
            sortfunc = lambda fn:-fn.total_time
        elif (opts.listsort in ('total_ops', 'total-ops', 'totalops')):
            sortfunc = lambda fn:-fn.total_ops
        elif (opts.listsort in ('call_count', 'call-count', 'callcount')):
            sortfunc = lambda fn:-fn.call_count
            
        ls.sort(key=sortfunc)
        for func in ls[0 : opts.listcount]:
            func.dump()