resizing states takes much time

[franzlst]

If a hierarchy state with several states and transitions is resized, many "meta change waypoints" events are created in the modification history which lead to waiting times of > 1 sec

Originally created by @sebastian-brunner ([email protected]) at 2017-03-14 12:12:25+00:00 (moved from RMC internal repository)

[franzlst]

Do you wrote already a script to test on this waiting time and can I have it?

Originally created by @Rbelder at 2017-03-14 12:14:06+00:00 (moved from RMC internal repository)

[franzlst]

So the issue is connected to missing unit-test for the GaphasEditor. So this issue needs a representation in #175 or a own performance test for gaphas. It has close to nothing to do with the modification history. Easiest this can be seen if you disable the modification history by the HISTORY_ENABLED=False flag.

Gaphas is emiting meta change signals but the delay seems to result from the asynchronous drawing methods. Also it is not clear where all the meta_signals come from because those are not documented.
This signals need and representation in the notification test in a way like this:

• where those signals are emitted
• how often those signals should be emitted
• which element should be reached with them and are those element like the modification history are reached.

... and all this according every use case (e.g. different types of resizing).

@sebastian-brunner The "meta change events" how you call them are emitted by the graphical gaphas editor.

And considering the lack of more then a second, every notification to the modification history consumes at the moment approximately 20ms.
Therefore an example, see below, in which can be seen that the state machine re-size (STRG pressed) of "Drill multiple taught holes" (181 states and 276 transitions) generates approximately 20 signals for waypoints and resize so 400ms lack in the modification history, spent 140ms in the on_button_press method and 420ms in respective release method of MoveHandleTool. Anyway the time from starting the press method and finishing the release method is 1,7 seconds so that there are 700ms spent somewhere we even don't know yet. (I made the mouse movement as fast I can, usually this needs around 400ms)

At the moment the meta data that arrives at the modification history from this resize actions of gaphas are not consistent so I can ignore them if that should be the way to deal with them.
I think we really need a concept like described above.

16:29:14:    DEBUG - rafcon.gui.views.utils.editor:  The editor style 'rafcon-dark' is not supported. Using the default 'classic'
16:29:15:     INFO - rafcon.gui.mygaphas.tools:  5END on_button_press MoveHandleTool -> actual time 1489591755.06 time since start -0.1325070858
16:29:16:     INFO - rafcon.gui.mygaphas.tools:  START on_button_release MoveHandleTool 1489591756.2
16:29:16:     INFO - rafcon.gui.mygaphas.tools:  emit transition
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.2
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.22 time since start -0.0220839977264
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.22
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.25 time since start -0.0249021053314
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.25
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.27 time since start -0.0267879962921
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.27
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.3 time since start -0.0236668586731
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.3
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.32 time since start -0.0252711772919
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.32
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.35 time since start -0.0252850055695
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.35
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.37 time since start -0.0172181129456
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.37
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.39 time since start -0.018942117691
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.39
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.41 time since start -0.0191509723663
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.41
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.43 time since start -0.0193350315094
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.43
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.45 time since start -0.0208740234375
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.45
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.47 time since start -0.0208151340485
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.47
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.49 time since start -0.0204770565033
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.49
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.51 time since start -0.0208840370178
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.51
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.54 time since start -0.0215530395508
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.54
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.56 time since start -0.0234439373016
MetaSignalMsg(origin='graphical_editor_gaphas', change='waypoints', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.56
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.58 time since start -0.0237309932709
MetaSignalMsg(origin='graphical_editor_gaphas', change='size', affects_children=True, notification=None)
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.59
16:29:16:     INFO - rafcon.gui.models.modification_history:  2END meta_changed_notify_after -> actual 1489591756.59 time since start -0.000149965286255
16:29:16:     INFO - rafcon.gui.models.modification_history:  START meta_changed_notify_after: 1489591756.59
16:29:16:     INFO - rafcon.gui.models.modification_history:  6END meta_changed_notify_after -> actual 1489591756.62 time since start -0.0387759208679
16:29:16:     INFO - rafcon.gui.mygaphas.tools:  END on_button_release MoveHandleTool -> actual time 1489591756.63 time since start -0.426713943481 since start press -1.69826698303

Originally created by @Rbelder at 2017-03-15 16:18:47+00:00 (moved from RMC internal repository)

[franzlst]

The logger messages shown in the last comment can be used in the gaphas_improve_reliability_and_tests branch. I would start the development in the separate branch to avoid to influence development in the develop branch.

I also added the logger messages in the same way for OpenGL. We can see that OpenGL performs is close to the same as Gaphas if doing complex resize actions with state machines of the size named out above. In state machines with 10-40 states it is much better. The state machine therefore can be modified much faster. As long as the bridge between OpenGL meta data and Gaphas data has been improved this is even of advantage, too (e.g. modifying the state machine in both editors).

Originally created by @Rbelder at 2017-03-16 15:23:39+00:00 (moved from RMC internal repository)

[franzlst]

So this issue has improved at least a bit by pull-request #489 which combines meta data changed signals of an complex action in on signal. How the rest of the field has improved needs new testing and best a test so lets see. I will try to test on it the next weeks to provide some measurement.

Originally created by @Rbelder at 2018-03-01 15:36:35+00:00 (moved from RMC internal repository)