Profiling

A profiler is an execution monitor which measures the number of executions, or amount of time spent executing, the different parts of a program's code. Profiling is motivated by the old 80-20 rule: if 80% of execution time is spent in 20% of the code, then by identifying that 20% of the code we can focus our attentions on improving its correctness and performance.

Who Uses Profilers?

Application developers use profilers largely for performance tuning. System platform providers use profilers to tune kernels, compiler runtime systems, and libraries. As an undergrad I wrote a profiler (for C) which was used to provide input for a code generator which would dynamically improve its generated code based on application runs.

Kinds of Profiling

counting
a profile can report how many times something executed. Precise. Potentially expensive.
timing
a profile can report semi-exact times spent in each program unit, but it is incredibly expensive to do so!
statistical sampling
many profilers such as gprof check the program counter register every clock tick to approximate the amount of time spent in each unit
Profiling is a bit similar to test coverage; telling you what code has not been executed is the same as telling you a profile count of 0.

Profiler Granularity

Profilers vary in granularity; source-code granularities often range from function-level, statement-level and expression-level. It is tempting to work at the basic block level, since all instructions in a basic block will execute the same number of times. Q: does basic block granularity correspond to statement-level, or expression-level?

Java Profilers

The only Java profiler I have used was JProbe, a commercial tool which has been around awhile and worked pretty well for me on a project at the National Library of Medicine. JProbe puts out pretty output like this:

Profiling Example

As a profiling example, let's look at the Unicon virtual machine and see where it spends its time. The Unicon virtual machine, named iconx, is in many ways a typical giant C program. To profile it, I had to compile and link with -pg as well as -g options, and then disable its internal use of the UNIX profil(2) interface! One difference between iconx and some C programs is that its inputs vary more widely than is normal: different programs may use very different language features and spend their time in different places in the virtual machine and its runtime system. We will look at its profile when executing one particular program which is by definition "representative" since it was sent to us by a user in Croatia.

Analysis: this result suggests 2/3rds of execution time on this application is spent in interp_0, the virtual machine interpreter's main loop. A lot of time is also spent derefencing (this is the act of following a memory reference (pointer) to obtain its value), and in type checking and conversion functions. The program garbage collected 25 times, but apparently without spending any significant time at it ?! Statistical approximation has its pros and cons.

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 65.13     25.09    25.09  9876086     0.00     0.00  interp_0
  6.63     27.64     2.56 108318639     0.00     0.00  deref_0
  3.63     29.05     1.40  8472811     0.00     0.00  invoke
  2.93     30.18     1.13 61891780     0.00     0.00  cnv_ec_int
  2.39     31.09     0.92 28907412     0.00     0.00  Oasgn
  2.23     31.95     0.86 17074006     0.00     0.00  Oplus
  1.61     32.58     0.62 14237739     0.00     0.00  equiv
  1.30     33.08     0.50  1355071     0.00     0.00  Zfind
  1.22     33.55     0.47   634739     0.00     0.00  cstos
  1.14     33.98     0.44 12019549     0.00     0.00  Onumeq
  0.93     34.34     0.36 10561077     0.00     0.00  alcsubs_0
  0.92     34.70     0.35  3273189     0.00     0.00  Ofield
  0.88     35.04     0.34   862347     0.00     0.00  Obang
  0.71     35.31     0.28  1562097     0.00     0.00  alcstr_0
  0.66     35.57     0.26  6147174     0.00     0.00  lexcmp
  0.65     35.82     0.25       25    10.00    10.00  adjust
  0.60     36.05     0.23       25     9.20     9.20  compact
  0.57     36.27     0.22 14175397     0.00     0.00  Oeqv
  0.49     36.46     0.19  5398727     0.00     0.00  Olexeq
  0.45     36.63     0.17 17073415     0.00     0.00  add
  0.43     36.80     0.17  5214968     0.00     0.00  cvpos
  0.39     36.95     0.15  4091331     0.00     0.00  Osize
  0.38     37.09     0.14  1405720     0.00     0.00  Osubsc
  0.36     37.23     0.14  5542081     0.00     0.00  cnv_c_int
  0.35     37.37     0.14  1715559     0.00     0.00  Osect
  0.29     37.48     0.11   459321     0.00     0.00  Ztab
  0.23     37.57     0.09  6579734     0.00     0.00  cnv_tstr_0
  0.19     37.65     0.07                             deref_1
  0.18     37.72     0.07     3277     0.02     0.02  cnv_eint
  0.16     37.77     0.06  1005214     0.00     0.00  alcrecd_0
  0.14     37.83     0.06  4179269     0.00     0.00  cnv_str_0
  0.13     37.88     0.05  1088962     0.00     0.00  Olexne
  0.13     37.93     0.05   870748     0.00     0.00  Ocater
  0.13     37.98     0.05                             Olexlt
  0.12     38.02     0.04  2186145     0.00     0.00  Oneg
  0.12     38.07     0.04  1005214     0.00     0.00  Omkrec
  0.10     38.11     0.04   482109     0.00     0.00  retderef
  0.10     38.15     0.04                             Oneqv
  0.10     38.19     0.04                             cnv_tstr_1
  0.08     38.22     0.03   341945     0.00     0.00  Onumlt
  0.08     38.25     0.03                             alcsubs_1
  0.05     38.27     0.02   634739     0.00     0.00  Kletters
  0.05     38.29     0.02   184281     0.00     0.00  Obscan
  0.05     38.31     0.02    58899     0.00     0.00  sub
  0.04     38.33     0.01                             Orefresh
  0.03     38.34     0.01   274449     0.00     0.00  Zmove
  0.03     38.34     0.01   114371     0.00     0.00  memb
  0.03     38.35     0.01    98987     0.00     0.00  Ollist
  0.03     38.37     0.01    90644     0.00     0.00  itos
  0.03     38.38     0.01    85123     0.00     0.00  Onull
  0.03     38.38     0.01    58210     0.00     0.00  Onumge
  0.03     38.40     0.01    27206     0.00     0.00  tvtbl_asgn
  0.03     38.41     0.01    25048     0.00     0.00  Otoby
  0.03     38.41     0.01    15488     0.00     0.00  hmake
  0.03     38.42     0.01       26     0.38     0.41  Opowr
  0.03     38.44     0.01                             Orandom
  0.03     38.45     0.01                             cnv_cset_1
  0.03     38.45     0.01                             rtos
  0.01     38.46     0.01  2186145     0.00     0.00  neg
  0.01     38.47     0.01   454303     0.00     0.00  pollevent
  0.01     38.47     0.01    81191     0.00     0.00  alctvtbl_0
  0.01     38.48     0.01     3876     0.00     0.00  div3
  0.01     38.48     0.01        1     5.00     5.00  ston
  0.01     38.48     0.01                             Onumber
  0.01     38.49     0.01                             Otabmat
  0.01     38.49     0.01                             alcselem_1
  0.01     38.50     0.01                             alctelem_1
  0.01     38.51     0.01                             cnv_real_1
  0.01     38.51     0.01                             handle_misc
  0.01     38.52     0.01                             order
  0.01     38.52     0.01                             printable
  0.00     38.52     0.00   735547     0.00     0.00  def_c_int
  0.00     38.52     0.00   221203     0.00     0.00  Onumle
  0.00     38.52     0.00   145157     0.00     0.00  Ononnull
  0.00     38.52     0.00   127352     0.00     0.00  Zput
  0.00     38.52     0.00   115683     0.00     0.00  reserve_0
  0.00     38.52     0.00   114371     0.00     0.00  hchain
  0.00     38.52     0.00    99580     0.00     0.00  alclist_raw_0
  0.00     38.52     0.00    88898     0.00     0.00  tmp_str
  0.00     38.52     0.00    87358     0.00     0.00  hash
  0.00     38.52     0.00    58899     0.00     0.00  Ominus
  0.00     38.52     0.00    40499     0.00     0.00  subs_asgn
  0.00     38.52     0.00    39852     0.00     0.00  Onumgt
  0.00     38.52     0.00    27206     0.00     0.00  alctelem_0
  0.00     38.52     0.00    27013     0.00     0.00  Zchar
  0.00     38.52     0.00    25485     0.00     0.00  postqual
  0.00     38.52     0.00    22740     0.00     0.00  markptr
  0.00     38.52     0.00    15494     0.00     0.00  alcsegment_0
  0.00     38.52     0.00    15488     0.00     0.00  alchash_0
  0.00     38.52     0.00    15487     0.00     0.00  Ztable
  0.00     38.52     0.00    15076     0.00     0.00  markblock
  0.00     38.52     0.00    13587     0.00     0.00  mvc
  0.00     38.52     0.00     9755     0.00     0.00  Omult
  0.00     38.52     0.00     9164     0.00     0.00  mul
  0.00     38.52     0.00     8996     0.00     0.00  Oswap
  0.00     38.52     0.00     8183     0.00     0.00  def_tstr
  0.00     38.52     0.00     8175     0.00     0.00  putstr
  0.00     38.52     0.00     6521     0.00     0.00  cnv_c_dbl
  0.00     38.52     0.00     5686     0.00     0.00  Zmember
  0.00     38.52     0.00     4466     0.00     0.01  Odivide
  0.00     38.52     0.00     3876     0.00     0.00  mod3
  0.00     38.52     0.00     3589     0.00     0.00  alcreal_0
  0.00     38.52     0.00     2346     0.00     0.00  Ktime
  0.00     38.52     0.00     1764     0.00     0.00  Zget
  0.00     38.52     0.00     1764     0.00     0.00  c_get
  0.00     38.52     0.00     1764     0.00     0.00  cpslots
  0.00     38.52     0.00     1230     0.00     0.00  Zwrite
  0.00     38.52     0.00     1181     0.00     0.00  Zreal
  0.00     38.52     0.00     1181     0.00     0.00  cnv_real_0
  0.00     38.52     0.00     1171     0.00     0.00  Zpull
  0.00     38.52     0.00      903     0.00     0.00  Onumne
  0.00     38.52     0.00      594     0.00     0.00  Zrepl
  0.00     38.52     0.00      591     0.00     0.00  Oescan
  0.00     38.52     0.00      591     0.00     0.00  Zinteger
  0.00     38.52     0.00      591     0.00     0.00  Zstring
  0.00     38.52     0.00      591     0.00     0.00  Zwrites
  0.00     38.52     0.00      591     0.00     0.00  cnv_int_0
  0.00     38.52     0.00      588     0.00     0.00  Olconcat
  0.00     38.52     0.00      588     0.00     0.00  alclist_0
  0.00     38.52     0.00      588     0.00     0.00  cplist_0
  0.00     38.52     0.00      519     0.00     0.00  alclstb_0
  0.00     38.52     0.00      481     0.00     0.00  Zinsert
  0.00     38.52     0.00      481     0.00     0.00  addmem
  0.00     38.52     0.00      481     0.00     0.00  alcselem_0
  0.00     38.52     0.00      294     0.00     0.00  Zmap
  0.00     38.52     0.00      141     0.00     0.00  dp_pnmcmp
  0.00     38.52     0.00       81     0.00     0.00  deallocate_0
  0.00     38.52     0.00       26     0.00     0.00  ripow
  0.00     38.52     0.00       25     0.00     0.00  cofree
  0.00     38.52     0.00       25     0.00    19.20  collect
  0.00     38.52     0.00       25     0.00     0.00  findgap
  0.00     38.52     0.00       25     0.00     0.00  markprogram
  0.00     38.52     0.00       25     0.00     0.00  mmrefresh
  0.00     38.52     0.00       25     0.00    19.20  reclaim
  0.00     38.52     0.00       25     0.00     0.00  scollect
  0.00     38.52     0.00       25     0.00     0.00  sweep
  0.00     38.52     0.00       25     0.00     0.00  sweep_stk
  0.00     38.52     0.00       22     0.00     0.00  bi_strprc
  0.00     38.52     0.00       22     0.00     0.00  qsearch
  0.00     38.52     0.00       10     0.00     0.00  dgetc
  0.00     38.52     0.00       10     0.00     0.00  env_int
  0.00     38.52     0.00       10     0.00     0.00  fdgets
  0.00     38.52     0.00        8     0.00     0.00  Zright
  0.00     38.52     0.00        6     0.00     0.00  hgrow
  0.00     38.52     0.00        5     0.00     0.00  Zlist
  0.00     38.52     0.00        3     0.00     0.00  Zread
  0.00     38.52     0.00        3     0.00     0.00  getstrg
  0.00     38.52     0.00        2     0.00     0.00  Kdateline
  0.00     38.52     0.00        1     0.00     0.00  EVInit
  0.00     38.52     0.00        1     0.00     0.00  Zset
  0.00     38.52     0.00        1     0.00     0.00  alcactiv
  0.00     38.52     0.00        1     0.00     0.00  c_exit
  0.00     38.52     0.00        1     0.00     0.00  check_version
  0.00     38.52     0.00        1     0.00     0.00  datainit
  0.00     38.52     0.00        1     0.00     0.00  envset
  0.00     38.52     0.00        1     0.00     0.00  gzlongread
  0.00     38.52     0.00        1     0.00     0.01  icon_init
  0.00     38.52     0.00        1     0.00     0.00  icon_setup
  0.00     38.52     0.00        1     0.00     0.00  initalloc
  0.00     38.52     0.00        1     0.00     0.00  physicalmemorysize
  0.00     38.52     0.00        1     0.00     0.00  pushact
  0.00     38.52     0.00        1     0.00     0.00  readhdr
  0.00     38.52     0.00        1     0.00     0.01  resolve

 %         the percentage of the total running time of the
time       program used by this function.

cumulative a running sum of the number of seconds accounted
 seconds   for by this function and those listed above it.

 self      the number of seconds accounted for by this
seconds    function alone.  This is the major sort for this
           listing.

calls      the number of times this function was invoked, if
           this function is profiled, else blank.
 
 self      the average number of milliseconds spent in this
ms/call    function per call, if this function is profiled,
	   else blank.

 total     the average number of milliseconds spent in this
ms/call    function and its descendents per call, if this 
	   function is profiled, else blank.

name       the name of the function.  This is the minor sort
           for this listing. The index shows the location of
	   the function in the gprof listing. If the index is
	   in parenthesis it shows where it would appear in
	   the gprof listing if it were to be printed.

		     Call graph (explanation follows)


granularity: each sample hit covers 4 byte(s) for 0.03% of 38.52 seconds

index % time    self  children    called     name
                                                 
[1]     99.2    0.00   38.20                 main [1]
               26.08   12.12       1/1           interp_0  [3]
                0.00    0.00       1/1           icon_init [108]
                0.00    0.00       1/1           icon_setup [162]
                0.00    0.00       1/1           c_exit [157]
-----------------------------------------------
[2]     99.2   26.08   12.12       1+13037195  [2]
               25.09   11.25 9876086             interp_0  [3]
                0.50    0.34 1355071             Zfind  [10]
                0.11    0.03  459321             Ztab  [35]
                0.02    0.03  184281             Obscan  [45]
                0.01    0.01  274449             Zmove  [58]
                0.01    0.00   25048             Otoby  [64]
                0.00    0.00       2             Kdateline  [112]
                0.00    0.00     591             Oescan  [135]
-----------------------------------------------
                                   2             Kdateline  [112]
                                 591             Oescan  [135]
                              184281             Obscan  [45]
                              254212             Otoby  [64]
                              274449             Zmove  [58]
                              459321             Ztab  [35]
                              721346             Zfind  [10]
                             7981883             Obang  [12]
               26.08   12.12       1/1           main [1]
[3]     94.3   25.09   11.25 9876086         interp_0  [3]
                1.40    0.51 8472811/8472811     invoke [5]
                0.86    0.81 17074006/17074006     Oplus [6]
                1.45    0.01 61341591/108318639     deref_0 [4]
                0.92    0.22 28907412/28907412     Oasgn [7]
                0.44    0.44 12019549/12019549     Onumeq [9]
                0.22    0.62 14175397/14175397     Oeqv [11]
                0.19    0.31 5398727/5398727     Olexeq [15]
                0.05    0.41  870748/870748      Ocater [20]
                0.14    0.32 1715559/1715559     Osect [21]
                0.35    0.08 3273189/3273189     Ofield [22]
                0.01    0.40   97223/98987       Ollist [23]
                0.14    0.18 1405720/1405720     Osubsc [26]
                0.15    0.00 4091331/4091331     Osize [33]
                0.05    0.06 1088962/1088962     Olexne [36]
                0.04    0.06 1005214/1005214     Omkrec [37]
                0.04    0.05 2186145/2186145     Oneg [39]
                0.00    0.07   15487/15487       Ztable [42]
                0.04    0.01  482109/482109      retderef [46]
                0.03    0.02  341945/341945      Onumlt [48]
                0.00    0.03    4466/4466        Odivide [51]
                0.01    0.01   58210/58210       Onumge [53]
                0.00    0.02   58899/58899       Ominus [54]
                0.02    0.00  634739/634739      Kletters [55]
                0.00    0.01    9755/9755        Omult [61]
                0.01    0.00   85123/85123       Onull [63]
                0.01    0.00      26/26          Opowr [65]
                0.00    0.01  221203/221203      Onumle [72]
                0.01    0.00  454303/454303      pollevent [74]
                0.00    0.00  145157/145157      Ononnull [86]
                0.00    0.00     588/588         Olconcat [87]
                0.00    0.00   39852/39852       Onumgt [90]
                0.00    0.00   27013/27013       Zchar [91]
                0.00    0.00    5686/5686        Zmember [92]
                0.00    0.00    8996/8996        Oswap [93]
                0.00    0.00     594/594         Zrepl [94]
                0.00    0.00     294/294         Zmap [96]
                0.00    0.00     591/591         Zstring [97]
                0.00    0.00    1230/1230        Zwrite [98]
                0.00    0.00     591/591         Zwrites [99]
                0.00    0.00     481/481         Zinsert [100]
                0.00    0.00    1764/1764        Zget [101]
                0.00    0.00     903/903         Onumne [102]
                0.00    0.00       5/5           Zlist [103]
                0.00    0.00       3/3           Zread [104]
                0.00    0.00       1/1           Zset [110]
                0.00    0.00       8/8           Zright [111]
                0.00    0.00  127352/127352      Zput [114]
                0.00    0.00    2346/2346        Ktime [129]
                0.00    0.00    1181/1181        Zreal [132]
                0.00    0.00    1171/1171        Zpull [134]
                0.00    0.00     591/591         Zinteger [136]
                             1355071             Zfind  [10]
                              862347             Obang  [12]
                              459321             Ztab  [35]
                              274449             Zmove  [58]
                              184281             Obscan  [45]
                               25048             Otoby  [64]
                                 591             Oescan  [135]
                                   2             Kdateline  [112]
-----------------------------------------------
                             18831966             deref_0 [4]
                0.00    0.00   17992/108318639     Oswap [93]
                0.00    0.00   40499/108318639     subs_asgn [71]
                0.00    0.00   85123/108318639     Onull [63]
                0.00    0.00  145157/108318639     Ononnull [86]
                0.00    0.00  184281/108318639     Obscan  [45]
                0.01    0.00  482109/108318639     retderef [46]
                0.06    0.00 2583420/108318639     Osect [21]
                0.06    0.00 2715935/108318639     Osubsc [26]
                0.08    0.00 3265455/108318639     Ofield [22]
                0.19    0.00 7978330/108318639     Obang  [12]
                0.20    0.00 8297681/108318639     Oasgn [7]
                0.50    0.00 21181066/108318639     invoke [5]
                1.45    0.01 61341591/108318639     interp_0  [3]
[4]      6.7    2.55    0.01 108318639+18831966 deref_0 [4]
                0.01    0.00   80998/114371      memb [62]
                             18831966             deref_0 [4]
-----------------------------------------------
                1.40    0.51 8472811/8472811     interp_0  [3]
[5]      5.0    1.40    0.51 8472811         invoke [5]
                0.50    0.00 21181066/108318639     deref_0 [4]
                0.00    0.01    1764/98987       Ollist [23]
-----------------------------------------------
                0.86    0.81 17074006/17074006     interp_0  [3]
[6]      4.3    0.86    0.81 17074006         Oplus [6]
                0.62    0.00 34147421/61891780     cnv_ec_int [8]
                0.17    0.00 17073415/17073415     add [31]
                0.01    0.00     591/3277        cnv_eint [43]
                0.00    0.00    1182/6521        cnv_c_dbl [126]
                0.00    0.00     591/3589        alcreal_0 [128]
-----------------------------------------------
                0.92    0.22 28907412/28907412     interp_0  [3]
[7]      3.0    0.92    0.22 28907412         Oasgn [7]
                0.20    0.00 8297681/108318639     deref_0 [4]
                0.01    0.00   27206/27206       tvtbl_asgn [60]
                0.00    0.01   40499/40499       subs_asgn [71]
-----------------------------------------------
                0.00    0.00      26/61891780     Opowr [65]
                0.00    0.00    1806/61891780     Onumne [102]
                0.00    0.00    8932/61891780     Odivide [51]
                0.00    0.00   18919/61891780     Omult [61]
                0.00    0.00   50096/61891780     Otoby  [64]
                0.00    0.00   79704/61891780     Onumgt [90]
                0.00    0.00  115829/61891780     Onumge [53]
                0.00    0.00  117798/61891780     Ominus [54]
                0.01    0.00  442406/61891780     Onumle [72]
                0.01    0.00  683600/61891780     Onumlt [48]
                0.04    0.00 2186145/61891780     Oneg [39]
                0.44    0.00 24039098/61891780     Onumeq [9]
                0.62    0.00 34147421/61891780     Oplus [6]
[8]      2.9    1.13    0.01 61891780         cnv_ec_int [8]
                0.01    0.00       1/1           ston [77]
-----------------------------------------------
                0.44    0.44 12019549/12019549     interp_0  [3]
[9]      2.3    0.44    0.44 12019549         Onumeq [9]
                0.44    0.00 24039098/61891780     cnv_ec_int [8]
-----------------------------------------------
                             1355071             interp_0  [3]
[10]     2.2    0.50    0.34 1355071         Zfind  [10]
                0.03    0.31 2252003/4179269     cnv_str_0 [13]
                              721346             interp_0  [3]
-----------------------------------------------
                0.22    0.62 14175397/14175397     interp_0  [3]
[11]     2.2    0.22    0.62 14175397         Oeqv [11]
                0.62    0.00 14175397/14237739     equiv [14]
-----------------------------------------------
                              862347             interp_0  [3]
[12]     2.1    0.34    0.46  862347         Obang  [12]
                0.27    0.00 7940505/10561077     alcsubs_0 [25]
                0.19    0.00 7978330/108318639     deref_0 [4]
                             7981883             interp_0  [3]
-----------------------------------------------
                0.00    0.00       8/4179269     Zright [111]
                0.00    0.00     296/4179269     Zmap [96]
                0.00    0.00     591/4179269     Zstring [97]
                0.00    0.00     594/4179269     Zrepl [94]
                0.00    0.03  184281/4179269     Obscan  [45]
                0.02    0.24 1741496/4179269     Ocater [20]
                0.03    0.31 2252003/4179269     Zfind  [10]
[13]     1.7    0.06    0.58 4179269         cnv_str_0 [13]
                0.47    0.00  634739/634739      cstos [19]
                0.11    0.00  636485/1562097     alcstr_0 [27]
                0.00    0.00    1746/90644       itos [66]
-----------------------------------------------
                0.00    0.00   62342/14237739     memb [62]
                0.62    0.00 14175397/14237739     Oeqv [11]
[14]     1.6    0.62    0.00 14237739         equiv [14]
-----------------------------------------------
                0.19    0.31 5398727/5398727     interp_0  [3]
[15]     1.3    0.19    0.31 5398727         Olexeq [15]
                0.22    0.00 5392265/6147174     lexcmp [28]
                0.07    0.01 5398727/6579734     cnv_tstr_0 [38]
-----------------------------------------------
                0.00    0.00       3/115683      Zread [104]
                0.00    0.00       6/115683      alcrecd_0 [44]
                0.00    0.00      18/115683      alcsubs_0 [25]
                0.00    0.00     588/115683      alclist_0 [88]
                0.00    0.06   15488/115683      hmake [41]
                0.00    0.41   99580/115683      alclist_raw_0 [24]
[16]     1.2    0.00    0.48  115683         reserve_0 [16]
                0.00    0.48      25/25          collect [17]
                0.00    0.00      25/25          findgap [144]
-----------------------------------------------
                0.00    0.48      25/25          reserve_0 [16]
[17]     1.2    0.00    0.48      25         collect [17]
                0.00    0.48      25/25          reclaim [18]
                0.00    0.00      50/1700        markblock  [122]
                0.00    0.00      50/25485       postqual [118]
                0.00    0.00      25/25          markprogram [145]
                0.00    0.00      25/25          mmrefresh [146]
-----------------------------------------------
                0.00    0.48      25/25          collect [17]
[18]     1.2    0.00    0.48      25         reclaim [18]
                0.25    0.00      25/25          adjust [29]
                0.23    0.00      25/25          compact [30]
                0.00    0.00      25/25          cofree [143]
                0.00    0.00      25/25          scollect [147]
-----------------------------------------------
                0.47    0.00  634739/634739      cnv_str_0 [13]
[19]     1.2    0.47    0.00  634739         cstos [19]
-----------------------------------------------
                0.05    0.41  870748/870748      interp_0  [3]
[20]     1.2    0.05    0.41  870748         Ocater [20]
                0.02    0.24 1741496/4179269     cnv_str_0 [13]
                0.15    0.00  841141/1562097     alcstr_0 [27]
-----------------------------------------------
                0.14    0.32 1715559/1715559     interp_0  [3]
[21]     1.2    0.14    0.32 1715559         Osect [21]
                0.11    0.00 3431118/5214968     cvpos [32]
                0.09    0.00 3431118/5542081     cnv_c_int [34]
                0.06    0.00 2583420/108318639     deref_0 [4]
                0.06    0.00 1714971/10561077     alcsubs_0 [25]
                0.00    0.00     588/588         cplist_0 [89]
-----------------------------------------------
                0.35    0.08 3273189/3273189     interp_0  [3]
[22]     1.1    0.35    0.08 3273189         Ofield [22]
                0.08    0.00 3265455/108318639     deref_0 [4]
-----------------------------------------------
                0.00    0.01    1764/98987       invoke [5]
                0.01    0.40   97223/98987       interp_0  [3]
[23]     1.1    0.01    0.41   98987         Ollist [23]
                0.00    0.41   98987/99580       alclist_raw_0 [24]
-----------------------------------------------
                0.00    0.00       5/99580       Zlist [103]
                0.00    0.00     588/99580       Olconcat [87]
                0.00    0.41   98987/99580       Ollist [23]
[24]     1.1    0.00    0.41   99580         alclist_raw_0 [24]
                0.00    0.41   99580/115683      reserve_0 [16]
-----------------------------------------------
                0.03    0.00  905601/10561077     Osubsc [26]
                0.06    0.00 1714971/10561077     Osect [21]
                0.27    0.00 7940505/10561077     Obang  [12]
[25]     0.9    0.36    0.00 10561077         alcsubs_0 [25]
                0.00    0.00      18/115683      reserve_0 [16]
-----------------------------------------------
                0.14    0.18 1405720/1405720     interp_0  [3]
[26]     0.8    0.14    0.18 1405720         Osubsc [26]
                0.06    0.00 2715935/108318639     deref_0 [4]
                0.04    0.00 1324529/5214968     cvpos [32]
                0.03    0.00 1324529/5542081     cnv_c_int [34]
                0.03    0.00  905601/10561077     alcsubs_0 [25]
                0.01    0.00   81191/81191       alctvtbl_0 [75]
                0.00    0.00   81191/87358       hash [116]
-----------------------------------------------
                0.00    0.00       2/1562097     Kdateline  [112]
                0.00    0.00       3/1562097     Zread [104]
                0.00    0.00       8/1562097     Zright [111]
                0.00    0.00     294/1562097     Zmap [96]
                0.00    0.00     594/1562097     Zrepl [94]
                0.01    0.00   40499/1562097     subs_asgn [71]
                0.01    0.00   43071/1562097     Olexne [36]
                0.11    0.00  636485/1562097     cnv_str_0 [13]
                0.15    0.00  841141/1562097     Ocater [20]
[27]     0.7    0.28    0.00 1562097         alcstr_0 [27]
-----------------------------------------------
                0.00    0.00     141/6147174     dp_pnmcmp [105]
                0.03    0.00  754768/6147174     Olexne [36]
                0.22    0.00 5392265/6147174     Olexeq [15]
[28]     0.7    0.26    0.00 6147174         lexcmp [28]
-----------------------------------------------
                0.25    0.00      25/25          reclaim [18]
[29]     0.6    0.25    0.00      25         adjust [29]
-----------------------------------------------
                0.23    0.00      25/25          reclaim [18]
[30]     0.6    0.23    0.00      25         compact [30]
                0.00    0.00   13587/13587       mvc [123]
-----------------------------------------------
                0.17    0.00 17073415/17073415     Oplus [6]
[31]     0.5    0.17    0.00 17073415         add [31]
-----------------------------------------------
                0.01    0.00  459321/5214968     Ztab  [35]
                0.04    0.00 1324529/5214968     Osubsc [26]
                0.11    0.00 3431118/5214968     Osect [21]
[32]     0.4    0.17    0.00 5214968         cvpos [32]
-----------------------------------------------
                0.15    0.00 4091331/4091331     interp_0  [3]
[33]     0.4    0.15    0.00 4091331         Osize [33]
-----------------------------------------------
                0.00    0.00     594/5542081     Zrepl [94]
                0.00    0.00   25048/5542081     Otoby  [64]
                0.00    0.00   27013/5542081     Zchar [91]
                0.02    0.00  733779/5542081     def_c_int [57]
                0.03    0.00 1324529/5542081     Osubsc [26]
                0.09    0.00 3431118/5542081     Osect [21]
[34]     0.4    0.14    0.00 5542081         cnv_c_int [34]
-----------------------------------------------
                              459321             interp_0  [3]
[35]     0.4    0.11    0.03  459321         Ztab  [35]
                0.01    0.00  459321/5214968     cvpos [32]
                0.00    0.01  459321/735547      def_c_int [57]
                              459321             interp_0  [3]
-----------------------------------------------
                0.05    0.06 1088962/1088962     interp_0  [3]
[36]     0.3    0.05    0.06 1088962         Olexne [36]
                0.03    0.00  754768/6147174     lexcmp [28]
                0.02    0.00 1132327/6579734     cnv_tstr_0 [38]
                0.01    0.00   43071/1562097     alcstr_0 [27]
-----------------------------------------------
                0.04    0.06 1005214/1005214     interp_0  [3]
[37]     0.3    0.04    0.06 1005214         Omkrec [37]
                0.06    0.00 1005214/1005214     alcrecd_0 [44]
-----------------------------------------------
                0.00    0.00    8181/6579734     def_tstr [95]
                0.00    0.00   40499/6579734     subs_asgn [71]
                0.02    0.00 1132327/6579734     Olexne [36]
                0.07    0.01 5398727/6579734     Olexeq [15]
[38]     0.3    0.09    0.01 6579734         cnv_tstr_0 [38]
                0.00    0.01   88898/88898       tmp_str [70]
-----------------------------------------------
                0.04    0.05 2186145/2186145     interp_0  [3]
[39]     0.2    0.04    0.05 2186145         Oneg [39]
                0.04    0.00 2186145/61891780     cnv_ec_int [8]
                0.01    0.00 2186145/2186145     neg [73]
-----------------------------------------------
                                                 
[40]     0.2    0.07    0.00                 deref_1 [40]
-----------------------------------------------
                0.00    0.00       1/15488       Zset [110]
                0.01    0.06   15487/15488       Ztable [42]
[41]     0.2    0.01    0.06   15488         hmake [41]
                0.00    0.06   15488/115683      reserve_0 [16]
                0.00    0.00   15488/15488       alchash_0 [121]
                0.00    0.00   15488/15494       alcsegment_0 [120]
-----------------------------------------------
                0.00    0.07   15487/15487       interp_0  [3]
[42]     0.2    0.00    0.07   15487         Ztable [42]
                0.01    0.06   15487/15488       hmake [41]
-----------------------------------------------
                0.00    0.00      26/3277        Opowr [65]
                0.01    0.00     298/3277        Onumlt [48]
                0.01    0.00     591/3277        Omult [61]
                0.01    0.00     591/3277        Oplus [6]
                0.01    0.00     591/3277        Onumge [53]
                0.03    0.00    1180/3277        Odivide [51]
[43]     0.2    0.07    0.00    3277         cnv_eint [43]
-----------------------------------------------
                0.06    0.00 1005214/1005214     Omkrec [37]
[44]     0.2    0.06    0.00 1005214         alcrecd_0 [44]
                0.00    0.00       6/115683      reserve_0 [16]
-----------------------------------------------
                              184281             interp_0  [3]
[45]     0.1    0.02    0.03  184281         Obscan  [45]
                0.00    0.03  184281/4179269     cnv_str_0 [13]
                0.00    0.00  184281/108318639     deref_0 [4]
                              184281             interp_0  [3]
-----------------------------------------------
                0.04    0.01  482109/482109      interp_0  [3]
[46]     0.1    0.04    0.01  482109         retderef [46]
                0.01    0.00  482109/108318639     deref_0 [4]
-----------------------------------------------
                                                 
[47]     0.1    0.05    0.00                 Olexlt [47]
-----------------------------------------------
                0.03    0.02  341945/341945      interp_0  [3]
[48]     0.1    0.03    0.02  341945         Onumlt [48]
                0.01    0.00  683600/61891780     cnv_ec_int [8]
                0.01    0.00     298/3277        cnv_eint [43]
                0.00    0.00     588/6521        cnv_c_dbl [126]
                0.00    0.00      19/3589        alcreal_0 [128]
-----------------------------------------------
                                                 
[49]     0.1    0.04    0.00                 Oneqv [49]
-----------------------------------------------
                                                 
[50]     0.1    0.04    0.00                 cnv_tstr_1 [50]
-----------------------------------------------
                0.00    0.03    4466/4466        interp_0  [3]
[51]     0.1    0.00    0.03    4466         Odivide [51]
                0.03    0.00    1180/3277        cnv_eint [43]
                0.01    0.00    3876/3876        div3 [76]
                0.00    0.00    8932/61891780     cnv_ec_int [8]
                0.00    0.00    1180/6521        cnv_c_dbl [126]
                0.00    0.00     590/3589        alcreal_0 [128]
-----------------------------------------------
                                                 
[52]     0.1    0.03    0.00                 alcsubs_1 [52]
-----------------------------------------------
                0.01    0.01   58210/58210       interp_0  [3]
[53]     0.1    0.01    0.01   58210         Onumge [53]
                0.01    0.00     591/3277        cnv_eint [43]
                0.00    0.00  115829/61891780     cnv_ec_int [8]
                0.00    0.00    1182/6521        cnv_c_dbl [126]
                0.00    0.00     591/3589        alcreal_0 [128]
-----------------------------------------------
                0.00    0.02   58899/58899       interp_0  [3]
[54]     0.1    0.00    0.02   58899         Ominus [54]
                0.02    0.00   58899/58899       sub [56]
                0.00    0.00  117798/61891780     cnv_ec_int [8]
-----------------------------------------------
                0.02    0.00  634739/634739      interp_0  [3]
[55]     0.1    0.02    0.00  634739         Kletters [55]
-----------------------------------------------
                0.02    0.00   58899/58899       Ominus [54]
[56]     0.1    0.02    0.00   58899         sub [56]
-----------------------------------------------
                0.00    0.00       5/735547      Zlist [103]
                0.00    0.00       8/735547      Zright [111]
                0.00    0.00    1764/735547      Zget [101]
                0.00    0.01  274449/735547      Zmove  [58]
                0.00    0.01  459321/735547      Ztab  [35]
[57]     0.0    0.00    0.02  735547         def_c_int [57]
                0.02    0.00  733779/5542081     cnv_c_int [34]
-----------------------------------------------
                              274449             interp_0  [3]
[58]     0.0    0.01    0.01  274449         Zmove  [58]
                0.00    0.01  274449/735547      def_c_int [57]
                              274449             interp_0  [3]
-----------------------------------------------
                                                 
[59]     0.0    0.01    0.00                 Orefresh [59]
-----------------------------------------------
                0.01    0.00   27206/27206       Oasgn [7]
[60]     0.0    0.01    0.00   27206         tvtbl_asgn [60]
                0.00    0.00   27206/114371      memb [62]
                0.00    0.00   27206/27206       alctelem_0 [117]
                0.00    0.00      81/81          deallocate_0 [141]
                0.00    0.00       2/6           hgrow [153]
-----------------------------------------------
                0.00    0.01    9755/9755        interp_0  [3]
[61]     0.0    0.00    0.01    9755         Omult [61]
                0.01    0.00     591/3277        cnv_eint [43]
                0.00    0.00   18919/61891780     cnv_ec_int [8]
                0.00    0.00    9164/9164        mul [124]
                0.00    0.00    1182/6521        cnv_c_dbl [126]
                0.00    0.00     591/3589        alcreal_0 [128]
-----------------------------------------------
                0.00    0.00     481/114371      Zinsert [100]
                0.00    0.00    5686/114371      Zmember [92]
                0.00    0.00   27206/114371      tvtbl_asgn [60]
                0.01    0.00   80998/114371      deref_0 [4]
[62]     0.0    0.01    0.00  114371         memb [62]
                0.00    0.00   62342/14237739     equiv [14]
                0.00    0.00  114371/114371      hchain [115]
-----------------------------------------------
                0.01    0.00   85123/85123       interp_0  [3]
[63]     0.0    0.01    0.00   85123         Onull [63]
                0.00    0.00   85123/108318639     deref_0 [4]
-----------------------------------------------
                               25048             interp_0  [3]
[64]     0.0    0.01    0.00   25048         Otoby  [64]
                0.00    0.00   50096/61891780     cnv_ec_int [8]
                0.00    0.00   25048/5542081     cnv_c_int [34]
                              254212             interp_0  [3]
-----------------------------------------------
                0.01    0.00      26/26          interp_0  [3]
[65]     0.0    0.01    0.00      26         Opowr [65]
                0.00    0.00      26/3277        cnv_eint [43]
                0.00    0.00      26/61891780     cnv_ec_int [8]
                0.00    0.00      26/6521        cnv_c_dbl [126]
                0.00    0.00      26/26          ripow [142]
-----------------------------------------------
                0.00    0.00    1746/90644       cnv_str_0 [13]
                0.01    0.00   88898/90644       tmp_str [70]
[66]     0.0    0.01    0.00   90644         itos [66]
-----------------------------------------------
                                                 
[67]     0.0    0.01    0.00                 Orandom [67]
-----------------------------------------------
                                                 
[68]     0.0    0.01    0.00                 cnv_cset_1 [68]
-----------------------------------------------
                                                 
[69]     0.0    0.01    0.00                 rtos [69]
-----------------------------------------------
                0.00    0.01   88898/88898       cnv_tstr_0 [38]
[70]     0.0    0.00    0.01   88898         tmp_str [70]
                0.01    0.00   88898/90644       itos [66]
-----------------------------------------------
                0.00    0.01   40499/40499       Oasgn [7]
[71]     0.0    0.00    0.01   40499         subs_asgn [71]
                0.01    0.00   40499/1562097     alcstr_0 [27]
                0.00    0.00   40499/108318639     deref_0 [4]
                0.00    0.00   40499/6579734     cnv_tstr_0 [38]
-----------------------------------------------
                0.00    0.01  221203/221203      interp_0  [3]
[72]     0.0    0.00    0.01  221203         Onumle [72]
                0.01    0.00  442406/61891780     cnv_ec_int [8]
-----------------------------------------------
                0.01    0.00 2186145/2186145     Oneg [39]
[73]     0.0    0.01    0.00 2186145         neg [73]
-----------------------------------------------
                0.01    0.00  454303/454303      interp_0  [3]
[74]     0.0    0.01    0.00  454303         pollevent [74]
-----------------------------------------------
                0.01    0.00   81191/81191       Osubsc [26]
[75]     0.0    0.01    0.00   81191         alctvtbl_0 [75]
-----------------------------------------------
                0.01    0.00    3876/3876        Odivide [51]
[76]     0.0    0.01    0.00    3876         div3 [76]
                0.00    0.00    3876/3876        mod3 [127]
-----------------------------------------------
                0.01    0.00       1/1           cnv_ec_int [8]
[77]     0.0    0.01    0.00       1         ston [77]
-----------------------------------------------
                                                 
[78]     0.0    0.01    0.00                 Onumber [78]
-----------------------------------------------
                                                 
[79]     0.0    0.01    0.00                 Otabmat [79]
-----------------------------------------------
                                                 
[80]     0.0    0.01    0.00                 alcselem_1 [80]
-----------------------------------------------
                                                 
[81]     0.0    0.01    0.00                 alctelem_1 [81]
-----------------------------------------------
                                                 
[82]     0.0    0.01    0.00                 cnv_real_1 [82]
-----------------------------------------------
                                                 
[83]     0.0    0.01    0.00                 handle_misc [83]
-----------------------------------------------
                                                 
[84]     0.0    0.01    0.00                 order [84]
-----------------------------------------------
                                                 
[85]     0.0    0.01    0.00                 printable [85]
-----------------------------------------------
                0.00    0.00  145157/145157      interp_0  [3]
[86]     0.0    0.00    0.00  145157         Ononnull [86]
                0.00    0.00  145157/108318639     deref_0 [4]
-----------------------------------------------
                0.00    0.00     588/588         interp_0  [3]
[87]     0.0    0.00    0.00     588         Olconcat [87]
                0.00    0.00     588/99580       alclist_raw_0 [24]
                0.00    0.00    1176/1764        cpslots [131]
-----------------------------------------------
                0.00    0.00     588/588         cplist_0 [89]
[88]     0.0    0.00    0.00     588         alclist_0 [88]
                0.00    0.00     588/115683      reserve_0 [16]
-----------------------------------------------
                0.00    0.00     588/588         Osect [21]
[89]     0.0    0.00    0.00     588         cplist_0 [89]
                0.00    0.00     588/588         alclist_0 [88]
                0.00    0.00     588/1764        cpslots [131]
-----------------------------------------------
                0.00    0.00   39852/39852       interp_0  [3]
[90]     0.0    0.00    0.00   39852         Onumgt [90]
                0.00    0.00   79704/61891780     cnv_ec_int [8]
-----------------------------------------------
                0.00    0.00   27013/27013       interp_0  [3]
[91]     0.0    0.00    0.00   27013         Zchar [91]
                0.00    0.00   27013/5542081     cnv_c_int [34]
-----------------------------------------------
                0.00    0.00    5686/5686        interp_0  [3]
[92]     0.0    0.00    0.00    5686         Zmember [92]
                0.00    0.00    5686/114371      memb [62]
                0.00    0.00    5686/87358       hash [116]
-----------------------------------------------
                0.00    0.00    8996/8996        interp_0  [3]
[93]     0.0    0.00    0.00    8996         Oswap [93]
                0.00    0.00   17992/108318639     deref_0 [4]
-----------------------------------------------
                0.00    0.00     594/594         interp_0  [3]
[94]     0.0    0.00    0.00     594         Zrepl [94]
                0.00    0.00     594/1562097     alcstr_0 [27]
                0.00    0.00     594/4179269     cnv_str_0 [13]
                0.00    0.00     594/5542081     cnv_c_int [34]
-----------------------------------------------
                0.00    0.00       8/8183        Zright [111]
                0.00    0.00    3825/8183        Zwrites [99]
                0.00    0.00    4350/8183        Zwrite [98]
[95]     0.0    0.00    0.00    8183         def_tstr [95]
                0.00    0.00    8181/6579734     cnv_tstr_0 [38]
-----------------------------------------------
                0.00    0.00     294/294         interp_0  [3]
[96]     0.0    0.00    0.00     294         Zmap [96]
                0.00    0.00     294/1562097     alcstr_0 [27]
                0.00    0.00     296/4179269     cnv_str_0 [13]
-----------------------------------------------
                0.00    0.00     591/591         interp_0  [3]
[97]     0.0    0.00    0.00     591         Zstring [97]
                0.00    0.00     591/4179269     cnv_str_0 [13]
-----------------------------------------------
                0.00    0.00    1230/1230        interp_0  [3]
[98]     0.0    0.00    0.00    1230         Zwrite [98]
                0.00    0.00    4350/8183        def_tstr [95]
                0.00    0.00    4350/8175        putstr [125]
-----------------------------------------------
                0.00    0.00     591/591         interp_0  [3]
[99]     0.0    0.00    0.00     591         Zwrites [99]
                0.00    0.00    3825/8183        def_tstr [95]
                0.00    0.00    3825/8175        putstr [125]
-----------------------------------------------
                0.00    0.00     481/481         interp_0  [3]
[100]    0.0    0.00    0.00     481         Zinsert [100]
                0.00    0.00     481/114371      memb [62]
                0.00    0.00     481/87358       hash [116]
                0.00    0.00     481/481         alcselem_0 [140]
                0.00    0.00     481/481         addmem [139]
                0.00    0.00       4/6           hgrow [153]
-----------------------------------------------
                0.00    0.00    1764/1764        interp_0  [3]
[101]    0.0    0.00    0.00    1764         Zget [101]
                0.00    0.00    1764/735547      def_c_int [57]
                0.00    0.00    1764/1764        c_get [130]
-----------------------------------------------
                0.00    0.00     903/903         interp_0  [3]
[102]    0.0    0.00    0.00     903         Onumne [102]
                0.00    0.00    1806/61891780     cnv_ec_int [8]
-----------------------------------------------
                0.00    0.00       5/5           interp_0  [3]
[103]    0.0    0.00    0.00       5         Zlist [103]
                0.00    0.00       5/99580       alclist_raw_0 [24]
                0.00    0.00       5/735547      def_c_int [57]
-----------------------------------------------
                0.00    0.00       3/3           interp_0  [3]
[104]    0.0    0.00    0.00       3         Zread [104]
                0.00    0.00       3/115683      reserve_0 [16]
                0.00    0.00       3/1562097     alcstr_0 [27]
                0.00    0.00       3/3           getstrg [154]
-----------------------------------------------
                0.00    0.00     141/141         qsearch [107]
[105]    0.0    0.00    0.00     141         dp_pnmcmp [105]
                0.00    0.00     141/6147174     lexcmp [28]
-----------------------------------------------
                0.00    0.00      22/22          resolve [109]
[106]    0.0    0.00    0.00      22         bi_strprc [106]
                0.00    0.00      22/22          qsearch [107]
-----------------------------------------------
                0.00    0.00      22/22          bi_strprc [106]
[107]    0.0    0.00    0.00      22         qsearch [107]
                0.00    0.00     141/141         dp_pnmcmp [105]
-----------------------------------------------
                0.00    0.00       1/1           main [1]
[108]    0.0    0.00    0.00       1         icon_init [108]
                0.00    0.00       1/1           resolve [109]
                0.00    0.00       1/1           physicalmemorysize [164]
                0.00    0.00       1/1           datainit [159]
                0.00    0.00       1/1           readhdr [166]
                0.00    0.00       1/1           envset [160]
                0.00    0.00       1/1           initalloc [163]
                0.00    0.00       1/1           alcactiv [156]
                0.00    0.00       1/1           pushact [165]
                0.00    0.00       1/1           check_version [158]
                0.00    0.00       1/1           gzlongread [161]
                0.00    0.00       1/1           EVInit [155]
-----------------------------------------------
                0.00    0.00       1/1           icon_init [108]
[109]    0.0    0.00    0.00       1         resolve [109]
                0.00    0.00      22/22          bi_strprc [106]
-----------------------------------------------
                0.00    0.00       1/1           interp_0  [3]
[110]    0.0    0.00    0.00       1         Zset [110]
                0.00    0.00       1/15488       hmake [41]
-----------------------------------------------
                0.00    0.00       8/8           interp_0  [3]
[111]    0.0    0.00    0.00       8         Zright [111]
                0.00    0.00       8/1562097     alcstr_0 [27]
                0.00    0.00       8/4179269     cnv_str_0 [13]
                0.00    0.00       8/735547      def_c_int [57]
                0.00    0.00       8/8183        def_tstr [95]
-----------------------------------------------
                                   2             interp_0  [3]
[112]    0.0    0.00    0.00       2         Kdateline  [112]
                0.00    0.00       2/1562097     alcstr_0 [27]
                                   2             interp_0  [3]
-----------------------------------------------
[113]    0.0    0.00    0.00    1700+36166    [113]
                0.00    0.00   15076+4840        markblock  [122]
                0.00    0.00      25             sweep  [148]
                0.00    0.00      25             sweep_stk  [149]
-----------------------------------------------
                0.00    0.00  127352/127352      interp_0  [3]
[114]    0.0    0.00    0.00  127352         Zput [114]
                0.00    0.00     519/519         alclstb_0 [138]
-----------------------------------------------
                0.00    0.00  114371/114371      memb [62]
[115]    0.0    0.00    0.00  114371         hchain [115]
-----------------------------------------------
                0.00    0.00     481/87358       Zinsert [100]
                0.00    0.00    5686/87358       Zmember [92]
                0.00    0.00   81191/87358       Osubsc [26]
[116]    0.0    0.00    0.00   87358         hash [116]
-----------------------------------------------
                0.00    0.00   27206/27206       tvtbl_asgn [60]
[117]    0.0    0.00    0.00   27206         alctelem_0 [117]
-----------------------------------------------
                0.00    0.00      31/25485       sweep  [148]
                0.00    0.00      50/25485       collect [17]
                0.00    0.00      50/25485       markprogram [145]
                0.00    0.00     567/25485       sweep_stk  [149]
                0.00    0.00    9904/25485       markblock  [122]
                0.00    0.00   14883/25485       markptr  [119]
[118]    0.0    0.00    0.00   25485         postqual [118]
-----------------------------------------------
                               21349             markptr  [119]
                               22740             markblock  [122]
[119]    0.0    0.00    0.00   22740+21349   markptr  [119]
                0.00    0.00   14883/25485       postqual [118]
                               12633             markblock  [122]
                               21349             markptr  [119]
-----------------------------------------------
                0.00    0.00       6/15494       hgrow [153]
                0.00    0.00   15488/15494       hmake [41]
[120]    0.0    0.00    0.00   15494         alcsegment_0 [120]
-----------------------------------------------
                0.00    0.00   15488/15488       hmake [41]
[121]    0.0    0.00    0.00   15488         alchash_0 [121]
-----------------------------------------------
                                4840             markblock  [122]
                                  24             sweep  [148]
                                 719             sweep_stk  [149]
                               12633             markptr  [119]
                0.00    0.00      50/1700        collect [17]
                0.00    0.00    1650/1700        markprogram [145]
[122]    0.0    0.00    0.00   15076+4840    markblock  [122]
                0.00    0.00    9904/25485       postqual [118]
                               22740             markptr  [119]
                                  25             sweep  [148]
                                4840             markblock  [122]
-----------------------------------------------
                0.00    0.00   13587/13587       compact [30]
[123]    0.0    0.00    0.00   13587         mvc [123]
-----------------------------------------------
                0.00    0.00    9164/9164        Omult [61]
[124]    0.0    0.00    0.00    9164         mul [124]
-----------------------------------------------
                0.00    0.00    3825/8175        Zwrites [99]
                0.00    0.00    4350/8175        Zwrite [98]
[125]    0.0    0.00    0.00    8175         putstr [125]
-----------------------------------------------
                0.00    0.00      26/6521        Opowr [65]
                0.00    0.00     588/6521        Onumlt [48]
                0.00    0.00    1180/6521        Odivide [51]
                0.00    0.00    1181/6521        cnv_real_0 [133]
                0.00    0.00    1182/6521        Omult [61]
                0.00    0.00    1182/6521        Oplus [6]
                0.00    0.00    1182/6521        Onumge [53]
[126]    0.0    0.00    0.00    6521         cnv_c_dbl [126]
-----------------------------------------------
                0.00    0.00    3876/3876        div3 [76]
[127]    0.0    0.00    0.00    3876         mod3 [127]
-----------------------------------------------
                0.00    0.00      19/3589        Onumlt [48]
                0.00    0.00      26/3589        ripow [142]
                0.00    0.00     590/3589        Odivide [51]
                0.00    0.00     591/3589        Omult [61]
                0.00    0.00     591/3589        Oplus [6]
                0.00    0.00     591/3589        Onumge [53]
                0.00    0.00    1181/3589        cnv_real_0 [133]
[128]    0.0    0.00    0.00    3589         alcreal_0 [128]
-----------------------------------------------
                0.00    0.00    2346/2346        interp_0  [3]
[129]    0.0    0.00    0.00    2346         Ktime [129]
-----------------------------------------------
                0.00    0.00    1764/1764        Zget [101]
[130]    0.0    0.00    0.00    1764         c_get [130]
-----------------------------------------------
                0.00    0.00     588/1764        cplist_0 [89]
                0.00    0.00    1176/1764        Olconcat [87]
[131]    0.0    0.00    0.00    1764         cpslots [131]
-----------------------------------------------
                0.00    0.00    1181/1181        interp_0  [3]
[132]    0.0    0.00    0.00    1181         Zreal [132]
                0.00    0.00    1181/1181        cnv_real_0 [133]
-----------------------------------------------
                0.00    0.00    1181/1181        Zreal [132]
[133]    0.0    0.00    0.00    1181         cnv_real_0 [133]
                0.00    0.00    1181/6521        cnv_c_dbl [126]
                0.00    0.00    1181/3589        alcreal_0 [128]
-----------------------------------------------
                0.00    0.00    1171/1171        interp_0  [3]
[134]    0.0    0.00    0.00    1171         Zpull [134]
-----------------------------------------------
                                 591             interp_0  [3]
[135]    0.0    0.00    0.00     591         Oescan  [135]
                                 591             interp_0  [3]
-----------------------------------------------
                0.00    0.00     591/591         interp_0  [3]
[136]    0.0    0.00    0.00     591         Zinteger [136]
                0.00    0.00     591/591         cnv_int_0 [137]
-----------------------------------------------
                0.00    0.00     591/591         Zinteger [136]
[137]    0.0    0.00    0.00     591         cnv_int_0 [137]
-----------------------------------------------
                0.00    0.00     519/519         Zput [114]
[138]    0.0    0.00    0.00     519         alclstb_0 [138]
-----------------------------------------------
                0.00    0.00     481/481         Zinsert [100]
[139]    0.0    0.00    0.00     481         addmem [139]
-----------------------------------------------
                0.00    0.00     481/481         Zinsert [100]
[140]    0.0    0.00    0.00     481         alcselem_0 [140]
-----------------------------------------------
                0.00    0.00      81/81          tvtbl_asgn [60]
[141]    0.0    0.00    0.00      81         deallocate_0 [141]
-----------------------------------------------
                0.00    0.00      26/26          Opowr [65]
[142]    0.0    0.00    0.00      26         ripow [142]
                0.00    0.00      26/3589        alcreal_0 [128]
-----------------------------------------------
                0.00    0.00      25/25          reclaim [18]
[143]    0.0    0.00    0.00      25         cofree [143]
-----------------------------------------------
                0.00    0.00      25/25          reserve_0 [16]
[144]    0.0    0.00    0.00      25         findgap [144]
-----------------------------------------------
                0.00    0.00      25/25          collect [17]
[145]    0.0    0.00    0.00      25         markprogram [145]
                0.00    0.00    1650/1700        markblock  [122]
                0.00    0.00      50/25485       postqual [118]
-----------------------------------------------
                0.00    0.00      25/25          collect [17]
[146]    0.0    0.00    0.00      25         mmrefresh [146]
-----------------------------------------------
                0.00    0.00      25/25          reclaim [18]
[147]    0.0    0.00    0.00      25         scollect [147]
-----------------------------------------------
                                  25             markblock  [122]
[148]    0.0    0.00    0.00      25         sweep  [148]
                0.00    0.00      31/25485       postqual [118]
                                  25             sweep_stk  [149]
                                  24             markblock  [122]
-----------------------------------------------
                                  25             sweep  [148]
[149]    0.0    0.00    0.00      25         sweep_stk  [149]
                0.00    0.00     567/25485       postqual [118]
                                 719             markblock  [122]
-----------------------------------------------
                0.00    0.00      10/10          readhdr [166]
[150]    0.0    0.00    0.00      10         dgetc [150]
-----------------------------------------------
                0.00    0.00      10/10          envset [160]
[151]    0.0    0.00    0.00      10         env_int [151]
-----------------------------------------------
                0.00    0.00      10/10          readhdr [166]
[152]    0.0    0.00    0.00      10         fdgets [152]
-----------------------------------------------
                0.00    0.00       2/6           tvtbl_asgn [60]
                0.00    0.00       4/6           Zinsert [100]
[153]    0.0    0.00    0.00       6         hgrow [153]
                0.00    0.00       6/15494       alcsegment_0 [120]
-----------------------------------------------
                0.00    0.00       3/3           Zread [104]
[154]    0.0    0.00    0.00       3         getstrg [154]
-----------------------------------------------
                0.00    0.00       1/1           icon_init [108]
[155]    0.0    0.00    0.00       1         EVInit [155]
-----------------------------------------------
                0.00    0.00       1/1           icon_init [108]
[156]    0.0    0.00    0.00       1         alcactiv [156]
-----------------------------------------------
                0.00    0.00       1/1           main [1]
[157]    0.0    0.00    0.00       1         c_exit [157]
-----------------------------------------------
                0.00    0.00       1/1           icon_init [108]
[158]    0.0    0.00    0.00       1         check_version [158]
-----------------------------------------------
                0.00    0.00       1/1           icon_init [108]
[159]    0.0    0.00    0.00       1         datainit [159]
-----------------------------------------------
                0.00    0.00       1/1           icon_init [108]
[160]    0.0    0.00    0.00       1         envset [160]
                0.00    0.00      10/10          env_int [151]
-----------------------------------------------
                0.00    0.00       1/1           icon_init [108]
[161]    0.0    0.00    0.00       1         gzlongread [161]
-----------------------------------------------
                0.00    0.00       1/1           main [1]
[162]    0.0    0.00    0.00       1         icon_setup [162]
-----------------------------------------------
                0.00    0.00       1/1           icon_init [108]
[163]    0.0    0.00    0.00       1         initalloc [163]
-----------------------------------------------
                0.00    0.00       1/1           icon_init [108]
[164]    0.0    0.00    0.00       1         physicalmemorysize [164]
-----------------------------------------------
                0.00    0.00       1/1           icon_init [108]
[165]    0.0    0.00    0.00       1         pushact [165]
-----------------------------------------------
                0.00    0.00       1/1           icon_init [108]
[166]    0.0    0.00    0.00       1         readhdr [166]
                0.00    0.00      10/10          fdgets [152]
                0.00    0.00      10/10          dgetc [150]
-----------------------------------------------

 This table describes the call tree of the program, and was sorted by
 the total amount of time spent in each function and its children.

 Each entry in this table consists of several lines.  The line with the
 index number at the left hand margin lists the current function.
 The lines above it list the functions that called this function,
 and the lines below it list the functions this one called.
 This line lists:
     index	A unique number given to each element of the table.
		Index numbers are sorted numerically.
		The index number is printed next to every function name so
		it is easier to look up where the function in the table.

     % time	This is the percentage of the `total' time that was spent
		in this function and its children.  Note that due to
		different viewpoints, functions excluded by options, etc,
		these numbers will NOT add up to 100%.

     self	This is the total amount of time spent in this function.

     children	This is the total amount of time propagated into this
		function by its children.

     called	This is the number of times the function was called.
		If the function called itself recursively, the number
		only includes non-recursive calls, and is followed by
		a `+' and the number of recursive calls.

     name	The name of the current function.  The index number is
		printed after it.  If the function is a member of a
		cycle, the cycle number is printed between the
		function's name and the index number.


 For the function's parents, the fields have the following meanings:

     self	This is the amount of time that was propagated directly
		from the function into this parent.

     children	This is the amount of time that was propagated from
		the function's children into this parent.

     called	This is the number of times this parent called the
		function `/' the total number of times the function
		was called.  Recursive calls to the function are not
		included in the number after the `/'.

     name	This is the name of the parent.  The parent's index
		number is printed after it.  If the parent is a
		member of a cycle, the cycle number is printed between
		the name and the index number.

 If the parents of the function cannot be determined, the word
 `' is printed in the `name' field, and all the other
 fields are blank.

 For the function's children, the fields have the following meanings:

     self	This is the amount of time that was propagated directly
		from the child into the function.

     children	This is the amount of time that was propagated from the
		child's children to the function.

     called	This is the number of times the function called
		this child `/' the total number of times the child
		was called.  Recursive calls by the child are not
		listed in the number after the `/'.

     name	This is the name of the child.  The child's index
		number is printed after it.  If the child is a
		member of a cycle, the cycle number is printed
		between the name and the index number.

 If there are any cycles (circles) in the call graph, there is an
 entry for the cycle-as-a-whole.  This entry shows who called the
 cycle (as parents) and the members of the cycle (as children.)
 The `+' recursive calls entry shows the number of function calls that
 were internal to the cycle, and the calls entry for each member shows,
 for that member, how many times it was called from other members of
 the cycle.


Index by function name

 [155] EVInit                [111] Zright                 [76] div3
 [112] Kdateline             [110] Zset                  [105] dp_pnmcmp
  [55] Kletters               [97] Zstring               [151] env_int
 [129] Ktime                  [35] Ztab                  [160] envset
   [7] Oasgn                  [42] Ztable                 [14] equiv
  [12] Obang                  [98] Zwrite                [152] fdgets
  [45] Obscan                 [99] Zwrites               [144] findgap (ralc.r)
  [20] Ocater                 [31] add                   [154] getstrg
  [51] Odivide               [139] addmem                [161] gzlongread
  [11] Oeqv                   [29] adjust (rmemmgt.r)     [83] handle_misc
 [135] Oescan                [156] alcactiv              [116] hash
  [22] Ofield                [121] alchash_0             [115] hchain
  [87] Olconcat               [88] alclist_0             [153] hgrow
  [15] Olexeq                 [24] alclist_raw_0          [41] hmake
  [47] Olexlt                [138] alclstb_0             [108] icon_init
  [36] Olexne                [128] alcreal_0             [162] icon_setup
  [23] Ollist                 [44] alcrecd_0             [163] initalloc
  [54] Ominus                [120] alcsegment_0            [3] interp_0
  [37] Omkrec                [140] alcselem_0              [5] invoke
  [61] Omult                  [80] alcselem_1             [66] itos (cnv.r)
  [39] Oneg                   [27] alcstr_0               [28] lexcmp
  [49] Oneqv                  [25] alcsubs_0             [122] markblock (rmemmgt.r)
  [86] Ononnull               [52] alcsubs_1             [145] markprogram (rmemmgt.r)
  [63] Onull                 [117] alctelem_0            [119] markptr (rmemmgt.r)
  [78] Onumber                [81] alctelem_1             [62] memb
   [9] Onumeq                 [75] alctvtbl_0            [146] mmrefresh
  [53] Onumge                [106] bi_strprc             [127] mod3
  [90] Onumgt                [157] c_exit                [124] mul
  [72] Onumle                [130] c_get                 [123] mvc (rmemmgt.r)
  [48] Onumlt                [158] check_version          [73] neg
 [102] Onumne                [126] cnv_c_dbl              [84] order
   [6] Oplus                  [34] cnv_c_int             [164] physicalmemorysize
  [65] Opowr                  [68] cnv_cset_1             [74] pollevent
  [67] Orandom                 [8] cnv_ec_int            [118] postqual (rmemmgt.r)
  [59] Orefresh               [43] cnv_eint               [85] printable
  [21] Osect                 [137] cnv_int_0             [165] pushact
  [33] Osize                 [133] cnv_real_0            [125] putstr
  [26] Osubsc                 [82] cnv_real_1            [107] qsearch
  [93] Oswap                  [13] cnv_str_0             [166] readhdr (init.r)
  [79] Otabmat                [38] cnv_tstr_0             [18] reclaim (rmemmgt.r)
  [64] Otoby                  [50] cnv_tstr_1             [16] reserve_0
  [91] Zchar                 [143] cofree (rmemmgt.r)    [109] resolve
  [10] Zfind                  [17] collect                [46] retderef
 [101] Zget                   [30] compact (rmemmgt.r)   [142] ripow
 [100] Zinsert                [89] cplist_0               [69] rtos
 [136] Zinteger              [131] cpslots               [147] scollect (rmemmgt.r)
 [103] Zlist                  [19] cstos (cnv.r)          [77] ston (cnv.r)
  [96] Zmap                   [32] cvpos                  [56] sub
  [92] Zmember               [159] datainit               [71] subs_asgn
  [58] Zmove                 [141] deallocate_0          [148] sweep (rmemmgt.r)
 [134] Zpull                  [57] def_c_int             [149] sweep_stk (rmemmgt.r)
 [114] Zput                   [95] def_tstr               [70] tmp_str (cnv.r)
 [104] Zread                   [4] deref_0                [60] tvtbl_asgn
 [132] Zreal                  [40] deref_1                 [2] 
  [94] Zrepl                 [150] dgetc                 [113]