bugGNU Octave - Bugs: bug #55908, Closing plots much slower in...

 
 

bug #55908: Closing plots much slower in Octave 5.1.0

Submitted by:  None
Submitted on:  Wed 13 Mar 2019 09:22:10 AM UTC  
 
Category:  Performance Severity:  3 - Normal
Priority:  5 - Normal Item Group:  Regression
Status:  In Progress Assigned to:  None
Originator Name:  Originator Email:  -email is unavailable-
Open/Closed:  Open Release:  5.1.0
Operating System:  Any

Add a New Comment (Rich Markup)
   

You are not logged in

Please log in, so followups can be emailed to you.

 

( Jump to the original submission)

Mon 29 Jul 2019 09:58:35 AM UTC, comment #31: 

Thanks Markus, I confirm the error described in comments #27 and #29 has now disappeared. Sadly, it is not as fast as it has been for a few months but it's bearable and a much needed improvement from the initial report.

Guillaume <gyom>
Mon 22 Jul 2019 06:09:56 PM UTC, comment #30: 

Revisiting the logic for freeing graphics objects, I believe I broke it with the previous changes in this bug report.
I pushed a patch here that hopefully fixes it on default:
http://hg.savannah.gnu.org/hgweb/octave/rev/8d30dc86e5d9

But I still think it needs some more revisiting.

With this change, closing the original example takes 0.9 seconds on my PC (compared to about 10 milliseconds with the broken "fix"). But I think we were leaking graphics objects massively.
Compared to the original 10 seconds, this is still an improvement.

Since the changes here have been grafted to stable, we probably should fix it there, too.
Re-opening as in progress.

Markus Mützel <mmuetzel>
Project Member
Thu 06 Jun 2019 10:16:32 AM UTC, comment #29: 

I found a simple example illustrating the problem:

f = figure ();
u = uimenu (f,'label','Menu','tag','mytag');
uimenu (u,'label','one','tag','mytag');
uimenu (u,'label','two','tag','mytag');

o = findobj (f,'tag','mytag');
delete (o)

The parent menu is deleted first and when the children are to be deleted, the error "base_graphics_toolkit::update: invalid graphics toolkit" appears instead of being silently ignored.

Guillaume <gyom>
Thu 28 Mar 2019 10:37:51 AM UTC, comment #28: 

My intention was that the new (faster) code path is only taken when a graphics object is deleted from groot. In the other cases, the same code should be executed as before. (At least this is what I was trying to do).
From your description it sounds like this isn't working as expected.
I am currently a little short on time that I could dedicate to Octave. But it would definitely help if you can manage to find a minimum example that reproduces the issue.

Markus Mützel <mmuetzel>
Project Member
Thu 28 Mar 2019 09:58:16 AM UTC, comment #27: 

I don't have a toy example illustrating the problem yet but, since this changeset:

https://hg.savannah.gnu.org/hgweb/octave/rev/ead8f91c5556

I get the error message:

error: base_graphics_toolkit::update: invalid graphics toolkit
execution error in graphics callback function

It happens when I resize a figure containing several ui* elements. The resize callback deletes a uimenu then rebuilds it. The error seems to come from the delete() call. I don't manage to reproduce it with a simple example so it might be a race condition when there are many elements.

Guillaume <gyom>
Tue 26 Mar 2019 10:47:00 PM UTC, comment #26: 

I pushed this changeset:

http://hg.savannah.gnu.org/hgweb/octave/rev/232102b1e920

With stable and default I now see

octave:1> test stem
PASSES 10 out of 10 tests
octave:2> gcbo
ans = [](0x0)

on both stable and default.  And the original example takes a fraction of a second instead of 10+ on my system.

Closing this report as fixed.

John W. Eaton <jwe>
Project Administrator
Tue 26 Mar 2019 09:00:38 PM UTC, comment #25: 

I think the data member needs to stay on the stable branch even if you apply the change so that it's no longer used. This ensures that the sizes and offsets of all the classes and their data members stays the same from code compiled against the header files in version 5.1.

Mike Miller <mtmiller>
Project Administrator
Tue 26 Mar 2019 08:59:16 PM UTC, comment #24: 

@jwe: Correct on needing the second changeset as well.  On stable, I ran

test stem
gcbo

and it now incorrectly reports a callback object as existing.

Rik <rik5>
Project Administrator
Tue 26 Mar 2019 08:12:32 PM UTC, comment #23: 

I pushed the change here:

http://hg.savannah.gnu.org/hgweb/octave/rev/8d7265e353a0

It should be identical to Markus' change except in the method of handling optional arguments.

In the changeset on stable, there are only additions to the public interface so I think this is safe.

We'll also need my additional change for the callback stack, correct?  It's this change:

http://hg.savannah.gnu.org/hgweb/octave/rev/10cc5bf3dbb1

Is it OK to remove the data member from the class declaration?  It's private, and only used inside the .cc file so I would think yes, but I'm not an expert.  If not, the data member can stay, we just won't use it.  Let me know and I can make that change as well.

John W. Eaton <jwe>
Project Administrator
Tue 26 Mar 2019 08:01:31 PM UTC, comment #22: 

I'm working on a patch that does what Mike suggests in comment #21.

John W. Eaton <jwe>
Project Administrator
Tue 26 Mar 2019 07:51:10 PM UTC, comment #21: 

A less intrusive way to make the same effective change would be to add overload functions instead of adding a new argument with a default value.

IOW, instead of changing "properties::remove_child(const graphics_handle&)" to "properties::remove_child(const graphics_handle&, bool)", keep the original function and add an overload. The original function can be redefined to call the new function, preserving the original behavior, but its definition must stay in graphics.cc if that's where it was defined before, it can't be moved to an inline function.

I believe if only new symbols are added to liboctinterp, but no symbols are deleted, the library can be considered backwards compatible.

Mike Miller <mtmiller>
Project Administrator
Tue 26 Mar 2019 07:16:11 PM UTC, comment #20: 

There is a project somewhere about trying to tighten the list of exported symbols.  I started on it a long time ago and then gave it up.  Not for any particular reason, but it was a lot of work and there were more interesting things to work on.

So how frequent are large, complicated graphics plots like the one from the original poster?  If they are relatively uncommon we could wait until next year and 6.1 release.

Otherwise, this is clearly a regression that should be fixed and we should determine the least impactful way to do it.  If it is only incrementing a variable in configure.ac that doesn't sound too onerous.  Is it just the definition of OCTAVE_API_VERSION?

Rik <rik5>
Project Administrator
Tue 26 Mar 2019 06:30:00 PM UTC, comment #19: 

They are exposed symbols in the interface of liboctinterp. Even if they are private, for example do_delete_children, the public method delete_children calls do_delete_children, and it's inline, so that method is directly linked into the user application.

If you want a public method example, then properties::remove_child has a new signature, which means the old method is no longer in the library.

If you could guarantee that no external code links with any of the classes in graphics.h, then you could make a case for not needing to bump the library number. But most are tagged OCTINTERP_API, so they are intentionally public symbols. With my Debian packaging hat on, I would diff the list of symbols exported by the library and say this definitely needs a soname bump.

If we want to get better at this, maybe we need to use linker scripts and tighten down the list of symbols that are actually intentionally exported by liboctave and liboctinterp. But as it is in Octave 5 right now, Markus' change is not safe for stable.

Mike Miller <mtmiller>
Project Administrator
Tue 26 Mar 2019 05:52:34 PM UTC, comment #18: 

The do_delete_children and do_free functions are private.  Do changes to them count?  I don't see how an application could reference them directly.

John W. Eaton <jwe>
Project Administrator
Tue 26 Mar 2019 05:35:01 PM UTC, comment #17: 

No, those changes do break the current Octave ABI. It's possible that an application linked with liboctinterp has a reference to the symbol children_property::do_delete_children(bool), and that symbol was deleted in the first change. That needs a library ABI soname bump.

Mike Miller <mtmiller>
Project Administrator
Tue 26 Mar 2019 05:21:08 PM UTC, comment #16: 

It would be fine with me to move the changes to stable.  Does it introduce any binary incompatibility with the previous version?  I guess not since the new parameters have default values?

John W. Eaton <jwe>
Project Administrator
Tue 26 Mar 2019 04:17:44 PM UTC, comment #15: 

@jwe: Thanks, everything seems to work now.

Final note, this bug was reported as a regression in performance for version 5.1.0.  However, both Markus's and jwe's patches were made to the development branch.  Should they be hg graft'ed back to stable?

I just tried the original code on the stable branch and it took 6.5 seconds on my machine to close the figure.

Rik <rik5>
Project Administrator
Tue 26 Mar 2019 05:06:30 AM UTC, comment #14: 

Rik:  Thanks, having the simpler test made debugging less painful.

I pushed the following changeset:

http://hg.savannah.gnu.org/hgweb/octave/rev/10cc5bf3dbb1

It seems to fix the problem for me.  I think it's OK to manage the stack of callback objects in the gh_manager class since it is used there and the callbackobject property is read-only so it should not be possible for a user to interfere with the internal management of the current callback object.

John W. Eaton <jwe>
Project Administrator
Mon 25 Mar 2019 04:15:53 AM UTC, comment #13: 

Using the clue that there was a "basevalue" property I traced things backs to stem.m and created a minimal example.

hf = figure ("visible", "off");
h = stem ([1 2; 1.5 2.5], [1 1;2 2]);
bv = 0.3;
set (h(1), "basevalue", bv);
close (hf);

After this, try "gcbo" and you will find that it is not empty.  The script above is attached as tst_gcbo.m

(file #46632)

Rik <rik5>
Project Administrator
Fri 22 Mar 2019 07:39:28 PM UTC, comment #12: 

I noticed the gcbo failure but didn't think to look at this bug report.  Bisecting showed

The first bad revision is:
changeset:   26935:ead8f91c5556
user:        Markus M?tzel <markus.muetzel@gmx.de>
date:        Sat Mar 16 22:21:26 2019 +0100
summary:     Improve performance when closing figures (bug #55908).

While trying to find the problem, I also found that I could duplicate the error with

plot_src_dir = "/my/src/dir/octave/scripts/plot";
dirs = {"appearance", "draw", "util"};
for i = 1:3
  runtests (fullfile (plot_src_dir, dirs{i}));
end

That helped to significantly speed up bisecting.

I also tried looking at the parents of the graphics object that gcbo returns in the test but unlike what Rik notes in comment #10, calling get on the first parent causes Octave to crash with a segfault.

To see what the parent objects were, I changed the test to

%!test
%! wtf = gcbo ();
%! if (! isempty (wtf))
%!   get (wtf)
%!   p = get (wtf, 'parent');
%!   while (! isempty (p))
%!     get (p)
%!     p = get (p, 'parent')
%!   end
%! end
%! assert (isempty (wtf));

Here is the output I see:

  gcbo.m ......................................................ans =

  scalar structure containing the fields:

    basevalue =  0.30000
    beingdeleted = off
    busyaction = queue
    buttondownfcn = [](0x0)
    children = [](0x1)
    clipping = on
    createfcn = [](0x0)
    deletefcn = [](0x0)
    handlevisibility = off
    hittest = on
    interruptible = on
    parent = -4117.9
    pickableparts = visible
    selected = off
    selectionhighlight = on
    tag =
    type = line
    uicontextmenu = [](0x0)
    userdata = [](0x0)
    visible = on
    color =

       0   0   0

    displayname =
    linejoin = round
    linestyle = -
    linewidth =  0.50000
    marker = none
    markeredgecolor = auto
    markerfacecolor = none
    markersize =  6
    xdata =

       1   3

    xdatasource =
    ydata =

       0.30000   0.30000

    ydatasource =
    zdata = [](0x0)
    zdatasource =

fatal: caught signal Segmentation fault -- stopping myself...
Segmentation fault

It looks like a graphics handle is being deleted but not removed from the list of handles?  Maybe tracing the handles that are created and deleted for this series of tests with and without the patch could help with debugging?  Limit the tracing to objects that could be returned by gcbo?

John W. Eaton <jwe>
Project Administrator
Wed 20 Mar 2019 12:20:11 PM UTC, comment #11: 

I tested the patch and it works well for now.

The time for closing the example figure is now < 0.1 s.

Thanks!

Roland Baudin <roland65>
Mon 18 Mar 2019 04:32:36 AM UTC, comment #10: 

This is very strange.  I changed the BIST test in gcbo to

%!test
%! h = gcbo ();
%! if (! isempty (h))
%!   keyboard;
%! endif
%! assert (isempty (gcbo));

and then ran 'make check'.  It does stop at the keyboard statement and I can check the handle which is valid, according to ishghandle().  The "type" of the handle is "line", but  if I look at the properties I see it contains one called "basevalue".  This is not a property that a default line object has.  A stem, bar, or area graph might have a basevalue property which may mean it is left over from one of those BIST tests.

If I check the root object, I see that the "callbackobject" property does contain this handle.  However, gcbf returns [] so there is no active figure.  I wonder if something is going wrong with deleting/closing figures and the root object is not being updated properly.

If I follow the hierarchy up.  The parent of the "line" object is an axes object which is valid.  The parent of the axes object is the figure object 1.  And the figure is not valid, so how the axes exists is unknown.

Rik <rik5>
Project Administrator
Sun 17 Mar 2019 04:47:30 PM UTC, comment #9: 

I just re-run "make check" on the buildbot console and it is
still failing at those two. Yet running those tests interactively passes.

Dmitri.
--

Dmitri A. Sergatskov <dasergatskov>
Sun 17 Mar 2019 01:10:12 PM UTC, comment #8: 

Since this change the tests for gcbo and movegui are failing on the buildbots. They are not failing if I run the tests individually.
To be honest I don't understand what is going on. Are the tests in the test suite run differently from what is done in the GUI or CLI?

Markus Mützel <mmuetzel>
Project Member
Sun 17 Mar 2019 09:41:36 AM UTC, comment #7: 

I run the dump_plot_demos script and apart from some unrelated issues (probably bug #55895) the results look good. So I pushed the patch here:
http://hg.savannah.gnu.org/hgweb/octave/rev/ead8f91c5556

Marking as ready for test.

Markus Mützel <mmuetzel>
Project Member
Sat 16 Mar 2019 09:30:20 PM UTC, comment #6: 

Thanks for bisecting.
The problem seems to be that calling the remove_children callbacks is slow. But it isn't necessary to call these functions if the figure is going to be closed anyway (I think).
The attached patch skips executing the remove_children callbacks in that case.
The time for closing the figure from the example in comment #0 reduces from just above 10 seconds to about 10 milliseconds for me.
Further testing is still necessary.

(file #46561)

Markus Mützel <mmuetzel>
Project Member
Fri 15 Mar 2019 09:39:40 AM UTC, comment #5: 

Hi there, I am the author of the bug report (don't know why it's tagged "Anonymous" ?).

More information about the bug: I have a simulation with several contour plots (with a lot of graphic elements) and 3D mesh.

The slowness problem is more apparent when closing the contour plots that have a lot of graphic elements, thus my example.

Roland Baudin <roland65>
Wed 13 Mar 2019 11:35:40 PM UTC, comment #4: 

Sorry, trying again:

I bisected using the original example and the cset that triggers most of the slowdown for me is

changeset:   25423:13b1b9a0d9c5
user:        Markus Mützel <markus.muetzel@gmx.de>
date:        Sun Jun 03 19:51:11 2018 +0200
summary:     Move management of lights in axes from GL to graphics backend.

Ccing markus to see if he understands what is going on.

Pantxo Diribarne <pantxo>
Project Member
Wed 13 Mar 2019 11:34:21 PM UTC, comment #3: 

I bisected using the original example and the cset that triggers most of the slowdown for me is

Pantxo Diribarne <pantxo>
Project Member
Wed 13 Mar 2019 08:38:17 PM UTC, comment #2: 

I think that a small delay may have been introduced in the deletion of graphics objects to work around cross-thread issues between the GUI and the main interpreter thread.  But that might be completely off.

In any case, this happens for both 2-D and 3-D plots so I have changed the Summary to reflect that.

For the 2-D case, I used

clf;
hl = plot (rand (2, 1000));
tic; close; toc

For version 4.4.1 this takes 60 milliseconds, but 340 milliseconds with 5.1.0.  That is approximately a factor of 5 slowdown.  That isn't as bad as the reporter's 60X slowdown for a 3-D scene, but still bad.

Rik <rik5>
Project Administrator
Wed 13 Mar 2019 01:29:26 PM UTC, comment #1: 

Confirmed. This doesn't on the toolkit the toolkit (both gnuplot and qt take ~28s closing the figure on my system) but it is rather related to the deletion of the large amount of graphics objects.

Pantxo Diribarne <pantxo>
Project Member
Wed 13 Mar 2019 09:22:10 AM UTC, original submission:  

For 2D plots, closing a figure takes a very long time in Octave 5.1.0, while it only takes a fraction of second in Octave 4.4.1.

Here is a test, to reproduce the issue:

1. Plot a (rather complex) 2D figure with contours and labels:

x = [-1 : 0.05 : 10];
y = [-1 : 0.05 : 10];
z = sin(x') * cos(y);

figure(1);
[c, h] = contour(x, y, z, [-1 : 0.03 : 1]);
clabel(c, h, 'FontSize', 15, 'Color', 'k');

2. Close the figure:
tic; close(1); toc

Here are the timings for close():

Octave 4.4.1
------------

Windows 7 64 bits => 0.1 s
Ubuntu Linux 18.04 64 bits => 0.2 s

Octave 5.1.0
------------

Windows 7 64 bits => 14 s
Ubuntu Linux 18.04 64 bits => 12 s

As you see, closing the figure is nearly 100 times slower in Octave 5.1.0.

I also noticed that plotting the figure is ~20% slower in Octave 5.1.0.

Closing a simple 1D plot, doesn't have the issue, as far I can tell...

 
Anonymous

 

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

Attach Files:
   
   
Comment:
   

Attached Files
file #46632:  tst_gcbo.m added by rik5 (121B - text/x-matlab)
file #46561:  bug55908_delete_from_groot.patch added by mmuetzel (11KiB - application/octet-stream)

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by gyom (Posted a comment)
  • -email is unavailable- added by jwe (Posted a comment)
  • -email is unavailable- added by dasergatskov (Posted a comment)
  • -email is unavailable- added by mmuetzel (Updated the item)
  • -email is unavailable- added by roland65 (Posted a comment)
  • -email is unavailable- added by pantxo
  • -email is unavailable- added by rik5 (Posted a comment)
  • -email is unavailable- added by pantxo (Posted a comment)
  •  

    Do you think this task is very important?
    If so, you can add your encouragement to it.
    This task has 0 encouragements so far.

    Only project members can vote.

     

     

     

    Follow 13 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2019-07-22 mmuetzel Open/ClosedClosed => Open
    2019-07-22 mmuetzel StatusFixed => In Progress
    2019-03-26 jwe Open/ClosedOpen => Closed
    2019-03-26 rik5 CategoryPlotting => Performance
        Item GroupNone => Regression
    2019-03-26 rik5 StatusReady For Test => Fixed
    2019-03-25 rik5 Attached File- => Added tst_gcbo.m, #46632
    2019-03-17 mmuetzel StatusPatch Submitted => Ready For Test
    2019-03-16 mmuetzel StatusConfirmed => Patch Submitted
    2019-03-16 mmuetzel Attached File- => Added bug55908_delete_from_groot.patch, #46561
    2019-03-13 pantxo Carbon-Copy- => Added mmuetzel
    2019-03-13 rik5 SummaryClosing 2D plots much slower in Octave 5.1.0 => Closing plots much slower in Octave 5.1.0
    2019-03-13 pantxo StatusNone => Confirmed

    Back to the top


    Powered by Savane 3.5