bugGNU Octave - Bugs: bug #46315, Assertion Failed - profiler crash...

 
 

bug #46315: Assertion Failed - profiler crash on every 2nd time execution halts

Submitter:  Nicholas Jankowski <nrjank>
Submitted:  Wed 28 Oct 2015 04:07:17 PM UTC
   
 
Category:  Octave Function Severity:  4 - Important
Priority:  5 - Normal Item Group:  Segfault, Bus Error, etc.
Status:  Fixed Assigned to:  lachlan
Originator Name:  Nicholas Jankowski Open/Closed:  * Closed
Release:  * dev Operating System:  * Any
Fixed Release:  None Planned Release:  None
* Mandatory Fields

Add a New Comment Rich Markup
   

Jump to the original submission

Sun 07 Aug 2016 01:55:35 PM UTC, comment #13: 

Works for me.

Robert Jenssen <morgawr>
Fri 05 Aug 2016 02:25:50 PM UTC, comment #12: 

I checked in a changeset for the failing test:

http://hg.savannah.gnu.org/hgweb/octave/rev/8358b9ef5def

Can this bug report be closed now?

John W. Eaton <jwe>
Group administrator
Sat 23 Jul 2016 11:21:21 AM UTC, comment #11: 

As noted by Comment #10, the second check of info.Hierarchical needs a TotalTime field:


diff -r b3ced5e3cebb scripts/profiler/profile.m
--- a/scripts/profiler/profile.m        Fri Mar 25 14:28:40 2016 +1100
+++ b/scripts/profiler/profile.m        Sat Jul 23 21:18:15 2016 +1000
@@ -143,7 +143,7 @@
 %! assert (fieldnames (ftbl), {"FunctionName"; "TotalTime"; "NumCalls"; "IsRecursive"; "Parents"; "Children"});
 %! hier = info.Hierarchical;
 %! assert (size (hier), [0, 1]);
-%! assert (fieldnames (hier), {"Index"; "SelfTime"; "NumCalls"; "Children"});
+%! assert (fieldnames (hier), {"Index"; "SelfTime"; "TotalTime"; "NumCalls"; "Children"});

 ## Test input validation
 %!error profile ()


Robert Jenssen <morgawr>
Tue 19 Jul 2016 07:11:51 PM UTC, comment #10: 

With this change, I get a new test failure in profile.m:


>>>>> processing profile.m
***** test
 on_struct.ProfilerStatus = "on";
 off_struct.ProfilerStatus = "off";
 profile ("on");
 result = logm (rand (200) + 10 * eye (200));
 assert (profile ("status"), on_struct);
 profile ("off");
 assert (profile ("status"), off_struct);
 profile ("resume");
 result = logm (rand (200) + 10 * eye (200));
 profile ("off");
 assert (profile ("status"), off_struct);
 info = profile ("info");
 assert (isstruct (info));
 assert (size (info), [1, 1]);
 assert (fieldnames (info), {"FunctionTable"; "Hierarchical"});
 ftbl = info.FunctionTable;
 assert (fieldnames (ftbl), {"FunctionName"; "TotalTime"; "NumCalls"; "IsRecursive"; "Parents"; "Children"});
 hier = info.Hierarchical;
 assert (fieldnames (hier), {"Index"; "SelfTime"; "TotalTime"; "NumCalls"; "Children"});
 profile ("clear");
 info = profile ("info");
 assert (isstruct (info));
 assert (size (info), [1, 1]);
 assert (fieldnames (info), {"FunctionTable"; "Hierarchical"});
 ftbl = info.FunctionTable;
 assert (size (ftbl), [0, 1]);
 assert (fieldnames (ftbl), {"FunctionName"; "TotalTime"; "NumCalls"; "IsRecursive"; "Parents"; "Children"});
 hier = info.Hierarchical;
 assert (size (hier), [0, 1]);
 assert (fieldnames (hier), {"Index"; "SelfTime"; "NumCalls"; "Children"});
!!!!! test failed
ASSERT errors for:  assert (fieldnames (hier),{"Index"; "SelfTime"; "NumCalls"; "Children"})

  Location  |  Observed  |  Expected  |  Reason
     .          O(5x1)       E(4x1)      Dimensions don't match


The info.Hierarchical struct now has an extra field, TotalTime.

Mike Miller <mtmiller>
Group Member
Mon 18 Jul 2016 06:05:38 PM UTC, comment #9: 

I pushed the changeset here:

http://hg.savannah.gnu.org/hgweb/octave/rev/fdbe2eab2aef

This needs some more testing to ensure that it is actually timing the right things when profiling is turned on or off from inside a script or function.

Also, should the profile function itself be counted in the results?

John W. Eaton <jwe>
Group administrator
Fri 15 Jul 2016 10:17:20 PM UTC, comment #8: 

I think it should be possible to turn the profiler on or off anywhere.  What does Matlab allow?  We should probably follow that.

How about the attached patch?  It attempts to clean up the initialization and use of the accumulator object so that call_tree is always initialized and and active_fcn isn't accessed unless it is valid.  I'm not sure this is quite right yet, but it seems to avoid crashes for the test cases I tried.


(file #37904)

John W. Eaton <jwe>
Group administrator
Sat 09 Jul 2016 11:29:40 AM UTC, comment #7: 

The issue has nothing to do with the error in the inline function.

It can be reproduced by creating the file  errtest_script  containing


profile off
profile on


and then typing "profile on; errtest_script".

Nir was right that the problem is that profile off doesn't clean up all of the state.

The profiler works by creating an automatic object (i.e., on the C++ stack) for each profilable block, whether or not the profiler is active.  The object stores whether or not the profiler is active when it is created.  It then cleans up on exit.  It keeps a call stack in order to track times of descendants.  If the clean up is called for a function that is not a descendant of the function that activated the profiler, then the stack is emptied and a null pointer gets dereferenced.

To prevent this, the attached patch aborts profile mode when exiting the profilable block that enabled the profiler.

(file #37782)

Lachlan Andrew <lachlan>
Sat 09 Jul 2016 05:21:58 AM UTC, comment #6: 

I think that the attached patch fixes the bug -- it certainly allows the sample script to run on my system -- but I don't quite understand why every second time is different.

For some reason, every second time, an extra destructor profile_data_accumulator::enter::~enter is called.  This causes an additional call to exit_function, which used to cause active_fcn to become NULL while the profile was still flagged as "active".

Retagging "confirmed" -> "in progress"

Lachlan Andrew <lachlan>
Fri 08 Jul 2016 04:04:43 PM UTC, comment #5: 

The problem seems to be related to bug #39587.  There used to be an


assert (active_fcn != call_tree);


in profile_data_accumulator::exit_function, but that was removed to avoid the above bug.  If the latter function is called when the profiler is active, whatever triggered bug #39587 will trigger the current bug.

The simple work-around of replacing


  if (is_active ())
    add_current_time ();


in profile_data_accumulator::exit_function by


  if (is_active () && active_fcn != call_tree)
    add_current_time ();


prevents the assertion from being triggered, but for some reason the second call to errtest_script has an extra call to exit_function(), which sets active_fcn = 0.  This causes a seg fault the third time the script is run.

Time for some sleep now...

Lachlan Andrew <lachlan>
Fri 08 Jul 2016 03:11:37 PM UTC, comment #4: 

I'll have a go at this.

Note that the function named "func_with_syntax_error" doesn't actually have a syntax error.  It has a runtime error of being unable to find a variable.  Printing output before the assignment to retval shows that it is parsed correctly.

Lachlan Andrew <lachlan>
Thu 29 Oct 2015 07:38:04 PM UTC, comment #3: 

so, following up on Rik's comment:

So profiler throws a fit when it gets called again after being stopped short the first time. so it didn't seem to get the chance to 'reset itself'.

A couple questions:

1 - why a crash (with the odd text parsing) versus just an execution halt? Is that normal for his type of error?

2 - Calling 'profile off' from the command line before calling the offending function again does completely avoid the crash. Calling profile off as the first line within the offending script does not. I think one of the other bug reports mentioned something about 'profile' expecting to be called from the command line rather than in a script...

3 - removing the profile off line at the start of the script avoids the crash, but only because the 'profile on' call generates the usual 'Can't reset active profiler' error.

4 - removing both the off and on commands allows the profiler to run indefinitely. it never gets to a profile off statement, but never has any issue with the function with the syntax error, even or repeated calls.

it's #4 that seems a bit odd to me. it's specifically something about the profile off/profile on call that causes the crash, but only if the profile off is called within the script. So the profiler has no problem with the aborted execution in general. but trying to start a new profiler call (with the profile on), after a previous crash breaks things.

Is the profile off call not properly 'cleaning the slate' for the second profile on call?  What's left that is different?

Nicholas Jankowski <nrjank>
Group Member
Thu 29 Oct 2015 05:40:30 PM UTC, comment #2: 

<from the maintainers list>

The profiler records the time when it enters and exits a function and via subtraction is able to figure out how much time was spent in the function.  On entry the profiler records the time and then Octave core determines that the function has not been parsed so it reads it, but fails to parse it because of the syntax error.  This means no valid function is created.  When the code "exits" the function the profiler tries to add the running time to the profiler dataset  but runs into an assert statement in profiler.cc:391 on the development branch


assert (call_tree && active_fcn != call_tree);


So, I understand why this is happening, but I don't have a clear idea how to fix it.  It's not enough simply to remove the assert since there are other functions involved and other asserts.  Somehow, it would be best for the profiler to realize that there was a serious error and just abort collecting statistics on that function.

--Rik

Nicholas Jankowski <nrjank>
Group Member
Wed 28 Oct 2015 04:22:35 PM UTC, comment #1: 

possibly related to bug 39587
https://savannah.gnu.org/bugs/?39587

Nicholas Jankowski <nrjank>
Group Member
Wed 28 Oct 2015 04:07:17 PM UTC, original submission:  

running the following (and attached) script causes Octave to reliably crash on the second execution. (I made the function inline for cut/paste brevity, but the behavior is the same if the function is saved into its own file.


profile off;
profile on;

function retval = func_with_syntax_error(inputstring)
        retval = [inputstring,input_string];
endfunction

tval = 'this is a test';

retval = func_with_syntax_error(tval);

display(retval);

profile off;


the first execution generates an proper error about input_string being undefined.

octave:3> errtest_script
error: 'input_string' undefined near line 5 column 24
error: called from
    func_with_syntax_error at line 5 column 9
    errtest_script at line 10 column 8


the second execution produces the same error followed by an Assertion Failed! crash, as below (extra spaces deliberate)

octave:3> errtest_script
error: 'input_string' undefined near line 5 column 24
error: called from
    func_with_syntax_error at line 5 column 9
    errtest_script at line 10 column 8
A s s e r t i o n  f a i l e d !

 P r o g r a m :   c : \ O c t a v e \ o c t a v e - 4 . 0 . 0 \ b i n \ o c t a v e - c l i . e x e
 F i l e :   / s c r a t c h / j w e / s c r / m x e - o c t a v e / t m p - s t a b l e - o c t a v e / o c t a v e - 4 . 0 . 0 / l i b i n t e r p / c o r e f c n / p r o f i l e r . c c ,   L i n e   3 9 1

 E x p r e s s i o n :   c a l l _ t r e e   & &   a c t i v e _ f c n   ! =   c a l l _ t r e e

This application has requested the Runtime to terminate it in an unusual way. Please contact the applicaiton's support team for more information.
panic: Aborted -- stopping myself...
attempting to save variables to 'octave-workspace'...
save to 'octave-workspace' complete.


The error can be avoided by commenting out the 'profile off' from line 1.  this forces you to issue a manual 'profile off' before it will run a second time, and doing so fails to produce the same crash. running it several times this way, and then uncommenting the 'profile off' will crash on the next execution.

Nicholas Jankowski <nrjank>
Group Member

 

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

Attach Files:
   
   
Comment:
   

Attached Files
file #37904:  diffs.txt added by jwe (6KiB - text/plain)
file #35328:  errtest_script.m added by nrjank (242B - application/octet-stream)

 

Carbon-Copy List
  • -email is unavailable- added by morgawr (Posted a comment)
  • -email is unavailable- added by jwe (Updated the item)
  • -email is unavailable- added by lachlan (Posted a comment)
  • -email is unavailable- added by rik5 (Updated the item)
  • -email is unavailable- added by mtmiller (Updated the item)
  • -email is unavailable- added by nrjank (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 group members can vote.

     

    Follow 15 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2016-08-08 rik5 StatusReady For Test Fixed
        Open/ClosedOpen Closed
    2016-07-18 jwe StatusPatch Submitted Ready For Test
    2016-07-15 jwe Attached File- Added diffs.txt, #37904
    2016-07-09 lachlan Attached File- Added bug_46315_profile_crash.cset, #37782
        StatusIn Progress Patch Submitted
    2016-07-09 lachlan StatusConfirmed In Progress
    2016-07-08 lachlan Dependencies- Depends on bugs #39587
    2016-07-08 lachlan Assigned toNone lachlan
        Release4.0.0 dev
    2016-07-01 rik5 Severity3 - Normal 4 - Important
    2015-12-22 mtmiller CategoryNone Octave Function
        StatusNone Confirmed
        Operating SystemMicrosoft Windows Any
    2015-10-28 nrjank Attached File- Added errtest_script.m, #35328

    Back to the top

    Powered by Savane 3.13-d3ae.
    Corresponding source code