File: profile-analyze.py

package info (click to toggle)
glulxe 0.5.4-1
  • links: PTS, VCS
  • area: main
  • in suites: bullseye, sid
  • size: 516 kB
  • sloc: ansic: 9,504; python: 835; objc: 483; makefile: 29
file content (1157 lines) | stat: -rwxr-xr-x 41,706 bytes parent folder | download | duplicates (2)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
775
776
777
778
779
780
781
782
783
784
785
786
787
788
789
790
791
792
793
794
795
796
797
798
799
800
801
802
803
804
805
806
807
808
809
810
811
812
813
814
815
816
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
838
839
840
841
842
843
844
845
846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
864
865
866
867
868
869
870
871
872
873
874
875
876
877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
914
915
916
917
918
919
920
921
922
923
924
925
926
927
928
929
930
931
932
933
934
935
936
937
938
939
940
941
942
943
944
945
946
947
948
949
950
951
952
953
954
955
956
957
958
959
960
961
962
963
964
965
966
967
968
969
970
971
972
973
974
975
976
977
978
979
980
981
982
983
984
985
986
987
988
989
990
991
992
993
994
995
996
997
998
999
1000
1001
1002
1003
1004
1005
1006
1007
1008
1009
1010
1011
1012
1013
1014
1015
1016
1017
1018
1019
1020
1021
1022
1023
1024
1025
1026
1027
1028
1029
1030
1031
1032
1033
1034
1035
1036
1037
1038
1039
1040
1041
1042
1043
1044
1045
1046
1047
1048
1049
1050
1051
1052
1053
1054
1055
1056
1057
1058
1059
1060
1061
1062
1063
1064
1065
1066
1067
1068
1069
1070
1071
1072
1073
1074
1075
1076
1077
1078
1079
1080
1081
1082
1083
1084
1085
1086
1087
1088
1089
1090
1091
1092
1093
1094
1095
1096
1097
1098
1099
1100
1101
1102
1103
1104
1105
1106
1107
1108
1109
1110
1111
1112
1113
1114
1115
1116
1117
1118
1119
1120
1121
1122
1123
1124
1125
1126
1127
1128
1129
1130
1131
1132
1133
1134
1135
1136
1137
1138
1139
1140
1141
1142
1143
1144
1145
1146
1147
1148
1149
1150
1151
1152
1153
1154
1155
1156
1157
#!/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()