profiling core shows incorrect filenames.

[coke]

Build partcl and parrot latest.

parrot -Rprofiling tcl.pbc -e "proc a {} {return [expr 3+2]}; puts [a]"

Running this through pprof2cg.pl and callgrind_annotate, it eventually generates:

2,653,413,335  TGE.pir:Tree;_eval_cell []
2,651,600,256  TGE.pir:Tree;get []
1,751,295,801  compilers/pge/PGE/builtins_gen.pir:Perl6Regex;compile_perl6regex []
  487,226,246  runtime/tcllib.pir:_tcl;compileTcl []
  344,259,720  compilers/pge/PGE/Match.pir:Match;new []
  315,921,655  src/mathops.pir:tcl;&proc []
  198,936,456  runtime/tcllib.pir:Grammar;variable_substitution []
  171,552,334  runtime/tcllib.pir:Grammar;substitution []
   82,759,893  compilers/pge/PGE/Perl6Regex.pir:Exp;compile []
   76,454,973  runtime/tcllib.pir:Grammar;command_substitution []
   60,460,450  runtime/parrot/library/PGE/Text.pir:Text;bracketed []
   59,894,312  EVAL_5:parrot; []
   59,009,773  EVAL_19:tcl;_anon []
   58,250,240  runtime/tcllib.pir:_tcl;backslash_newline_subst []
   53,960,805  compilers/pge/PGE/OPTable.pir:Match;_failcut []
   51,425,943  src/tclsh.pir:tcl;load_init_tcl []
   51,337,804  TGE.pir:Tree;_install_action []
   47,639,102  TGE.pir:Tree;_scan_node []
   32,292,648  TGE.pir:Tree;_lookup_id []
   31,136,702  EVAL_3:tcl;_anon []
   24,122,933  src/tclsh.pir:tcl;_main []
   21,742,458  EVAL_10:tcl;compiled_tcl_sub_234 []
   17,559,531  TGE.pir:Rule;__init []
   17,264,913  src/grammar/expr/past2pir.pir:TclProc;create []
   16,667,841  runtime/builtin/lsort.pir:Grammar;_PAST::StaticCommand_pir []
   14,808,954  runtime/parrot/library/P6object.pir:P6metaclass;register []
   14,240,281  runtime/tcllib.pir:_tcl;splitNamespace []
   12,817,745  runtime/tcllib.pir:Grammar;backslash_substitution []
   12,079,378  runtime/builtin/concat.pir:Grammar;_TclExpr;Grammar_dispatch []
   11,928,699  runtime/builtin/file.pir:Grammar;_array_past []
   11,170,253  runtime/builtin/lindex.pir:Grammar;_PAST::Val_pir []
   10,828,125  runtime/parrot/library/P6object.pir:P6metaclass;new_class []
    8,550,324  compilers/pge/PGE/Regex.pir:OPTable;newtok []
    8,315,627  runtime/builtin/scan.pir:PAST::Node;init []
    8,266,923  compilers/pge/PGE/OPTable.pir:Match;Str []
    7,908,723  EVAL_1:Grammar; []
    7,398,635  runtime/builtin/flush.pir:Grammar;_command_past []
    5,941,079  compilers/pge/PGE/OPTable.pir:Match;to []
    5,819,350  runtime/tcllib.pir:Grammar;quoted_word []
    5,767,097  runtime/tcllib.pir:Grammar;expand []
    5,684,590  runtime/tcllib.pir:Grammar;ws []
    5,636,690  runtime/tcllib.pir:Grammar;braced_word []
    5,589,555  compilers/pge/PGE/Exp.pir:OPTable;parse []
    5,282,048  src/grammar/expr/pge2past.pir:tcl;mapping []
    5,158,426  runtime/tcllib.pir:Grammar;command []
    5,131,963  runtime/tcllib.pir:_tcl;findVar []
    5,101,549  src/grammar/expr/expression.pir:tcl;&info []
    5,032,391  EVAL_2:Grammar; []
    4,848,067  TGE.pir:Grammar;add_rule []
    4,348,342  compilers/pge/PGE/Match.pir:Match; []
    3,923,676  runtime/builtin/scan.pir:PAST::Node;set_node []
    3,880,130  EVAL_27:tcl;_anon []
    3,634,582  /home/coke/bird/lib/parrot/1.7.0-devel/library/config.pir:parrot;_config []
    3,342,833  runtime/builtin/scan.pir:PAST::Node;add_child []
    3,210,065  compilers/pge/PGE/OPTable.pir:Match; []
    2,699,492  runtime/builtin/info.pir:Grammar;init []
    2,607,796  runtime/builtin/dict.pir:Grammar;_program_past []
    2,530,875  src/class/tcllist.pir:TclConst;set_string_native []
    2,259,689  compilers/pge/PGE/builtins_gen.pir:Concat;reduce []
    2,238,602  src/grammar/expr/operators.pir:namespace;eval []
    2,233,470  compilers/pge/PGE/Perl6Regex.pir:Match;before []
    1,965,913  runtime/builtin/lappend.pir:Grammar;_PAST::Program_pir []
    1,881,329  compilers/pge/PGE/OPTable.pir:Match;get_bool []
    1,789,878  runtime/builtin/encoding.pir:Grammar;_braced_word_past []
    1,652,154  compilers/pge/PGE/OPTable.pir:Match;from []
    1,371,995  runtime/builtin/regsub.pir:Grammar;init []
    1,348,146  runtime/builtin/lrepeat.pir:Grammar;_PAST::Var_pir []
    1,270,440  runtime/parrot/library/P6object.pir:P6object;HOW []
    1,244,810  src/grammar/expr/past.pir:TclString;getListValue []
    1,059,955  TGE.pir:Tree;init []
    1,014,459  runtime/builtin/lsearch.pir:Grammar;_PAST::Op_pir []
      988,442  runtime/parrot/library/P6object.pir:P6metaclass;get_parrotclass []
      944,200  EVAL_2:Grammar;_regex14 []
      918,757  runtime/parrot/library/P6object.pir:P6metaclass;add_parent []
      903,730  runtime/builtin/dict.pir:Grammar;_operator_past []
      893,281  EVAL_1:Grammar;_regex10 []
      806,099  TGE.pir:Grammar;init []
      802,820  runtime/tcllib.pir:_tcl;select_option []
 <SNIP>

Many of these lines are reporting the wrong file, e.g.

      903,730  runtime/builtin/dict.pir:Grammar;_operator_past []
    3,342,833  runtime/builtin/scan.pir:PAST::Node;add_child []
  315,921,655  src/mathops.pir:tcl;&proc []
    1,371,995  runtime/builtin/regsub.pir:Grammar;init []
    1,244,810  src/grammar/expr/past.pir:TclString;getListValue []

[coke]

This is still an issue -a run a few moments ago shows Parrot; TclConst; class_init as living in tcllist.pir (when it's really in tclconst.pir)

class_init is a common sub name in partcl - is it collapsing by shortname and ignoring the namespace?

[cotto]

When looking at tcllib.pbc, it appears that something's generating an incorrect packfile debug segment. TclConst::class_init (in this instance, ymmv) lives at bytecode offsets 407 -> 417. The bytecode debug segment says that tcllist.pir is responsible for this part of the bytecode. The line numbers look correct, so fixing the debug segment and making sure we have a test to expose and cover this bug should make profiles much more useful.

Since I'm responsible for the profiling runcore, consider this as much as note to myself as anything else. ;]

constants table:

    # 43:
    [ 'PFC_PMC', {
                FLAGS    => 0x4500228 (private3,private5,is_PMC,custom_GC,report,needs_early_gc)
                class => Sub,
                start_offs => 407,
                end_offs => 417,
                name    => 'class_init',
                subid   => 'class_init',
                method  => '',
                nsentry => 'class_init',
                namespace => 'TclConst'
                HLL_id => 0,
    } ],

debug segment:

    #6
    [
        OFFSET => 278,
        FILENAME => src/class/tcllist.pir
    ],
    #7
    [
        OFFSET => 491,
        FILENAME => src/class/tclproc.pir
    ],

[cotto]

I have something resembling a minimal test case for this. It's not exactly tiny but it's still considerably smaller than the whole of partcl. Below is a demo of the bug using pbc_dump to pick apart the pbc and show that the location of the const sub for TclConst;class_init is inconsistent with what file the debug segment says it should be in. I'll try cooking this down some more tomorrow. This bug's days may be numbered.

cotto@feather:/usr/src/partcl-old\ 0 $ cat proftest
#!/bin/bash

echo "building..."
/usr/local/parrot-svn/bin/parrot --output=runtime/tcllib.pbc runtime/tcllib.pir
let tclconst_start=`pbc_dump runtime/tcllib.pbc |grep tclconst.pir \
    -B1|grep OFFSET|sed -e 's/.*=> //' -e 's/,.*//'`
let tclconst_end="`pbc_dump runtime/tcllib.pbc |grep tclconst.pir \
    -A4|grep OFFSET|sed -e 's/.*=> //' -e 's/,.*//'`-1"
let tclconst_class_init=`pbc_dump runtime/tcllib.pbc |grep "namespace => 'TclConst'" \
    -B6|grep class_init -B 3|head -n1|sed -e 's/.*start_offs => //' -e 's/,.*//g'`
echo "tclconst range (debug segment): $tclconst_start -> $tclconst_end"
echo "TclConst;class_init starts at $tclconst_class_init"
if [ $tclconst_class_init > tclconst_end ]
then
    echo "pbc is broken"
else
    echo "pbc might not be broken"
fi
cotto@feather:/usr/src/partcl-old\ 0 $ cat runtime/tcllib.pir
.include 'src/class/tclarray.pir'
.include 'src/class/tclconst.pir'
.include 'src/class/tcldict.pir'
cotto@feather:/usr/src/partcl-old\ 0 $ cat src/class/tclarray.pir
.sub does :vtable
  .param string provides
.end

cotto@feather:/usr/src/partcl-old\ 0 $ cat src/class/tclconst.pir
.namespace [ 'TclConst' ]

.sub class_init :anon :load
  $P0 = get_class 'String'
.end

cotto@feather:/usr/src/partcl-old\ 0 $ cat src/class/tcldict.pir
.namespace [ 'TclDict' ]
.sub class_init :anon :load
    say "wut"
.end
cotto@feather:/usr/src/partcl-old\ 0 $ ./proftest
building...
tclconst range (debug segment): 3 -> 5
TclConst;class_init starts at 7
pbc is broken

[cotto]

This bug was fixed in r48211. Thanks for filing this and being persistent in getting me to fix it. As a result, Parrot's profiling runcore is now more useful.