patchGNU Octave - Patches: patch #8539, Reduce profiling overhead using...

 
 

patch #8539: Reduce profiling overhead using inlining and templates

Submitter:  Julien Bect <jbect>
Submitted:  Fri 19 Sep 2014 06:37:36 PM UTC
   
 
Category:  None Priority:  5 - Normal
Status:  Done Privacy:  Public
Assigned to:  rik5 Open/Closed:  Closed
* Mandatory Fields

Add a New Comment Rich Markup
   

Jump to the original submission

Sat 06 Dec 2014 01:02:16 PM UTC, comment #12: 

Hello Rik,

I think this bug report can be closed now.

@++
Julien

Julien Bect <jbect>
Wed 12 Nov 2014 09:18:19 PM UTC, comment #11: 

@Julien: Thanks a lot.  The new patch avoids the segfault I was getting.  I will check it in as soon as I am able.  Right now, I can't reach the Mercurial archive for some reason.

Rik <rik5>
Group administrator
Wed 12 Nov 2014 08:24:24 AM UTC, comment #10: 

Some explanations about my latest patch.

The segfault problem probably comes from the fact that acc->enter_function () is not called in enter::enter () if profiler_name () returns "". In this case, the block should be marked inactive (is_active = FALSE) to prevent enter::~enter () from calling acc->exit_function ().

The latest patch only differs from the earlier one by the following piece of code

if (fcn == "")
  is_active = false;  // Inactive profiling block
else
  acc.enter_function (fcn);

which should do the trick.

Julien Bect <jbect>
Tue 11 Nov 2014 11:11:24 AM UTC, comment #9: 

Ok, here it is. Finger crossed.

(file #32416)

Julien Bect <jbect>
Tue 11 Nov 2014 09:28:10 AM UTC, comment #8: 

Ooops, I inadvertently attached an unpolished and untested patch to the previous post. Don't bother looking at this one, if it's ok I will post a better patch later today (based on your amended patch).

Julien Bect <jbect>
Tue 11 Nov 2014 09:22:48 AM UTC, comment #7: 

Hello Rik,

A about gcc's version number: perhaps, I don't know. I use gcc 4.8.2 and I have not seen the problem yet (with or without -O2).

But I have an idea... I have prepared I patch and I am testing it right now. I will post it later today.

@++
Julien

(file #32414)

Julien Bect <jbect>
Mon 10 Nov 2014 10:49:17 PM UTC, comment #6: 

Is it possible that different versions of gcc might produce the difference between segfaulting and not?  I'm using 4.6.3.

Rik <rik5>
Group administrator
Thu 30 Oct 2014 10:17:43 PM UTC, comment #5: 

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=...,
    eof=@0x7fffffffc36f: false) at util/cmd-edit.cc:278
#18 0x00007ffff62bb302 in command_editor::readline (prompt=..., eof=@0x7fffffffc36f: false)
    at util/cmd-edit.cc:1062
#19 0x00007ffff75adac0 in gnu_readline (s=..., eof=@0x7fffffffc36f: false) at corefcn/input.cc:186
#20 0x00007ffff75adc7c in interactive_input (s=..., eof=@0x7fffffffc36f: 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---
    eof=@0x7fffffffc36f: false) at corefcn/input.cc:254
#22 0x00007ffff75af3c1 in octave_terminal_reader::get_input (this=0xb74a40,
    eof=@0x7fffffffc36f: false) at corefcn/input.cc:624
#23 0x00007ffff7312079 in octave_input_reader::get_input (this=0xbc0388, eof=@0x7fffffffc36f: 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.




Rik <rik5>
Group administrator
Thu 30 Oct 2014 09:39:00 PM UTC, comment #4: 

Julien,

I forgot to upload my patch, but I've done that now.  I'm running the development branch at cset 238522618904.  The only compile option I am using are -O2.  I will try a 'make maintainer-clean' and start over to see if that helps.

(file #32345)

Rik <rik5>
Group administrator
Thu 30 Oct 2014 09:09:35 PM UTC, comment #3: 

Hello Rik,

I have just compiled the default branch with my patch, and I don't see the problem that you report:


octave:1> profile on
octave:2> x = rand (1000);  y = rand (1000);   z = x * y;
octave:3> profile off
octave:4> profshow
   #            Function Attr     Time (s)   Time (%)        Calls
------------------------------------------------------------------
   2            binary *             0.483      86.44            1
   1                rand             0.076      13.54            2
   3             profile             0.000       0.02            1
   6               false             0.000       0.00            1
   4              nargin             0.000       0.00            1
   5           binary !=             0.000       0.00            1
   7 __profiler_enable__             0.000       0.00            1
octave:5>


Btw, where did you upload the patch ?

Julien Bect <jbect>
Thu 30 Oct 2014 07:55:04 AM UTC, comment #2: 

I will look into this...

Julien Bect <jbect>
Wed 29 Oct 2014 10:03:26 PM UTC, comment #1: 

@Julien: I modified your patch slightly to remove tabs in favor of spaces for indentation, and to remove ';' and the end of the expansion of macros.  I've uploaded the patch.

But, when I compile the code, either with your patch or my amended one, the profiler causes an assertion and segfault.


octave:1> profile on
octave:2> corefcn/profiler.cc:388: void profile_data_accumulator::add_current_time(): Assertion `last_time >= 0.0 && last_time <= t' failed.
Abort




Rik <rik5>
Group administrator
Fri 19 Sep 2014 06:37:36 PM UTC, original submission:  
Julien Bect <jbect>

 

(Note: upload size limit is set to 16384 kB, after insertion of the required escape characters.)

Attach Files:
   
   
Comment:
   

Attached Files
file #32416:  jbProfilerTemplate_3.patch added by jbect (10KiB - text/x-patch)
file #32414:  jbProfilerTemplate_2.patch added by jbect (9KiB - text/x-patch)
file #32345:  profiler.cset added by rik5 (9KiB - application/octet-stream)
file #32138:  jbProfilerTemplate.patch added by jbect (9KiB - text/x-patch)

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by rik5 (Posted a comment)
  • -email is unavailable- added by jbect (Submitted the item)
  •  

    There are 0 votes so far. Votes easily highlight which items people would like to see resolved in priority, independently of the priority of the item set by tracker managers.

    Only logged-in users can vote.

     

    Follow 8 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2014-12-06 rik5 StatusIn Progress Done
        Open/ClosedOpen Closed
    2014-11-12 rik5 StatusNone In Progress
        Assigned toNone rik5
    2014-11-11 jbect Attached File- Added jbProfilerTemplate_3.patch, #32416
    2014-11-11 jbect Attached File- Added jbProfilerTemplate_2.patch, #32414
    2014-10-30 rik5 Attached File- Added profiler.cset, #32345
    2014-09-19 jbect Attached File- Added jbProfilerTemplate.patch, #32138

    Back to the top

    Powered by Savane 3.13-f8d8.
    Corresponding source code