[Octave-patch-tracker] [patch #8539] Reduce profiling overhead using inlining and templates

[Rik]

Follow-up Comment #5, patch #8539 (project octave):

Here is the a backtrace from running under gdb.


#0  profile_data_accumulator::add_current_time (this=0x7ffff7dd92c0) at
corefcn/profiler.cc:388
#1  0x00007ffff76a45ea in profile_data_accumulator::exit_function
(this=0x7ffff7dd92c0, fcn=...)
    at corefcn/profiler.cc:250
#2  0x00007ffff7191231 in
profile_data_accumulator::enter<octave_builtin>::~enter (
    this=0x7fffffffba20, __in_chrg=<optimized out>) at corefcn/profiler.h:71
#3  0x00007ffff719008f in octave_builtin::do_multi_index_op (this=0xc56940,
nargout=0, args=..., 
    lvalue_list=0x0) at octave-value/ov-builtin.cc:143
#4  0x00007ffff72732b7 in octave_value::do_multi_index_op (this=0xc57150,
nargout=0, idx=..., 
    lvalue_list=0x0) at octave-value/ov.cc:1360
#5  0x00007ffff720b74d in octave_fcn_handle::do_multi_index_op (this=0xc57140,
nargout=0, args=..., 
    lvalue_list=0x0) at octave-value/ov-fcn-handle.cc:221
#6  0x00007ffff720b244 in octave_fcn_handle::do_multi_index_op (this=0xc57140,
nargout=0, args=...)
    at octave-value/ov-fcn-handle.cc:141
#7  0x00007ffff7273262 in octave_value::do_multi_index_op (this=0xc57090,
nargout=0, idx=...)
    at octave-value/ov.cc:1353
#8  0x00007ffff75ad5f9 in fcn_handle_hook_function::eval (this=0xc57070,
initial_args=...)
    at corefcn/hook-fcn.h:170
#9  0x00007ffff75b1b6a in hook_function::eval (this=0x7fffffffbe40,
initial_args=...)
    at corefcn/hook-fcn.h:105
#10 0x00007ffff75b1d27 in hook_function_list::run (this=0x7ffff7dd8020,
initial_args=...)
    at corefcn/hook-fcn.h:251
#11 0x00007ffff75b0a38 in internal_input_event_hook_fcn () at
corefcn/input.cc:1146
#12 0x00007ffff62bb19b in command_editor::event_handler () at
util/cmd-edit.cc:1031
#13 0x00007ffff0b525ab in rl_read_key () from
/lib/x86_64-linux-gnu/libreadline.so.6
#14 0x00007ffff0b3d251 in readline_internal_char () from
/lib/x86_64-linux-gnu/libreadline.so.6
#15 0x00007ffff0b3d795 in readline () from
/lib/x86_64-linux-gnu/libreadline.so.6
#16 0x00007ffff62f7a97 in octave_rl_readline (prompt=0xbc18c8 "octave:3> ")
    at util/oct-rl-edit.c:196
#17 0x00007ffff62b9d6e in gnu_readline::do_readline (this=0x79fea0,
prompt=..., 
    address@hidden: false) at util/cmd-edit.cc:278
#18 0x00007ffff62bb302 in command_editor::readline (prompt=...,
address@hidden: false)
    at util/cmd-edit.cc:1062
#19 0x00007ffff75adac0 in gnu_readline (s=..., address@hidden: false) at
corefcn/input.cc:186
#20 0x00007ffff75adc7c in interactive_input (s=..., address@hidden:
false)
    at corefcn/input.cc:214
#21 0x00007ffff75addd5 in octave_base_reader::octave_gets (this=0xb74a40, 
---Type <return> to continue, or q <return> to quit---
    address@hidden: false) at corefcn/input.cc:254
#22 0x00007ffff75af3c1 in octave_terminal_reader::get_input (this=0xb74a40, 
    address@hidden: false) at corefcn/input.cc:624
#23 0x00007ffff7312079 in octave_input_reader::get_input (this=0xbc0388,
address@hidden: false)
    at corefcn/input.h:262
#24 0x00007ffff7311a7b in octave_lexer::fill_flex_buffer (this=0xbc0100,
buf=0xc6e540 "", 
    max_size=8192) at lex.ll:3434
#25 0x00007ffff730ad3e in yy_get_next_buffer (yyscanner=0xbc2300) at
parse-tree/lex.cc:3428
#26 0x00007ffff730a89e in octave_lex (yylval_param=0x7fffffffc670,
yyscanner=0xbc2300)
    at parse-tree/lex.cc:3298
#27 0x00007ffff731775c in octave_pull_parse (yyps=0x0, parser=...) at
parse-tree/oct-parse.cc:4011
#28 0x00007ffff73176f3 in octave_parse (parser=...) at
parse-tree/oct-parse.cc:3981
#29 0x00007ffff7324e04 in octave_parser::run (this=0x7fffffffc6e0) at
oct-parse.yy:3788
#30 0x00007ffff77163ed in main_loop () at corefcn/toplev.cc:589
#31 0x00007ffff6e165f2 in octave_execute_interpreter () at octave.cc:887
#32 0x0000000000402d89 in main (argc=8, argv=0x7fffffffc988) at
main-cli.cc:42


The code in question is:


void
profile_data_accumulator::add_current_time (void)
{
  const double t = query_time ();
  assert (last_time >= 0.0 && last_time <= t);

  assert (call_tree && active_fcn != call_tree);
  active_fcn->add_time (t - last_time);
}


What I see using the command line is that last_time = -1, which is the reset
value.  From the call tree, I don't see where the "enter" class is actually
invoked to change the value of last_time.  Instead, just the destructor ~enter
is called.  This may be something particularly strange with the 'profile on'
command because when the function is entered, profiling is not active, but by
the time the function exits it has been turned on so the destructor in
profiler.h does get called.





    _______________________________________________________

Reply to this item at:

  <http://savannah.gnu.org/patch/?8539>

_______________________________________________
  Message sent via/by Savannah
  http://savannah.gnu.org/