Profiling Parrot

[Will Coleda]

Now that partcl can run 'tcltest.tcl' and chug through some of the
larger tests, speed is becoming an obstacle.

http://code.google.com/p/partcl/source/browse/trunk/docs/spectest-progress.csv

shows that it's currently taking about 3 hours on my dual-core intel
os x box to run 'make spectest' for tcl. As more tests files parse,
this will just go up and up...

It is hard to diagnose what, exactly is slow; Having callgrind output,
(http://rt.perl.org/rt3/Ticket/Display.html?id=58250) would definitely
help, even if it was only a first cut.

If I run partcl's t/cmd_expr.t with parrot's -p option, I see the
following entries (where total is > 0.5) ; this is on a file that
takes about 30s to process. (And, to be clear, isn't one of the
spectest files)

Calibration: overhead = 0.000110 ms/op
 Code J Name                         Calls  Total/s       Avg/ms
   -5 - DOD_mark_next                  123    2.971066   24.155008
   33 - invokecc_p                  176087    2.928808    0.016633
   -4 - DOD_collect_PMC                123    2.846327   23.140870
  290 - lt_p_ic_ic                  153172    2.395632    0.015640
  308 - le_p_ic_ic                  135162    2.307548    0.017072
   41 - get_params_pc              1019790    2.161294    0.002119
  757 - callmethodcc_p_sc           824411    1.867045    0.002265
  845 - new_p_sc                   1515372    1.163961    0.000768
  776 - isa_i_p_pc                  188584    1.160712    0.006155
  816 - getattribute_p_p_sc        1598660    0.955629    0.000598
   -2 - GC                             123    0.904643    7.354822
  822 - setattribute_p_sc_p        1726873    0.822047    0.000476
  850 - new_p_p                     188607    0.743157    0.003940
   42 - set_returns_pc             1144861    0.666446    0.000582
   -3 - DOD_collect_buffers            123    0.637082    5.179525
  851 - new_p_pc                     81955    0.571143    0.006969


All the GC/DOD items cover about 25% of my total run time.

The lt_p_ic_ic and le_p_ic_ic are, i -think-, from PGE code that is
using an attribute to keep track of an integer, and so are forced to
compare a PMC against an INT. they account for 10% of my runtime. This
is just a guess as to the source of those opcodes, though.

It's also entirely possible that my slowdown come from code in partcl
itself, but it's hard to sort things that way.

Anyone have any suggestions on how to profile parrot?

-- 
Will "Coke" Coleda