really long merge time on big networks

[goldhoorn]

On some cases the network generation tooks really edges.

I uploaded a logfile http://auv.informatik.uni-bremen.de/framework/logs/long-reconfiguration-time/ which shows a 15 seconds time for generating the new network.

The CPU load on this single CPU quadcore I7 system is roughly 1.00 the normal vehile processes took not more than 40% each. Only ruby jumps to ~100% if the event occurs.

In the attached logfile the iteration is 2084 at 16:09:30 where the pipeline detector detecs a pipe and therefore the statemachines switches to follow pipe. This is part of the avalon-profile "find_pipe_with_localiation" in this file: https://github.com/auv-avalon/bundle/blob/interrim_working/models/actions/core.rb

[doudou]

Could you make a list of all the definitions / requirements that are present before and after the transition ? It would help creating a testcase to profile what goes wrong.

[goldhoorn]

Running thought a controller:

sysmon_dev!
modem_dev!
depth_reader_dev!
depth_reader_rear_dev!
depth_fusion_def!
joystick_control_def!
lights_def!
low_level_def!
front_camera_dev!
bottom_camera_dev!
sonar_dev!

Startet in the syskit-shell:

minimal_demo!

the statemachine minimal_demo was in state

s1 = state find_pipe_with_localization(:check_pipe_angle => true)

then the event "align_auv" happen, which causes a success_event in find_pipe_with_localization, which should start in minimal_demo this state:

pipeline1 = state pipeline_def(:depth=> -7.1, :heading => 0, :speed_x => 0.5, :turn_dir=> 1, :timeout => 120)

[doudou]

I need to know which definitions were running before AND after the transition. What is the last running definition of find_pipe_with_localization ? Are there global / local dependencies in the state machine(s) ?

[goldhoorn]

You mean also all resolved definition by syskit? -> this could be a LOT (including instance requirements?)

the state machine find_pipe_with_localization finished and was in state pipe_detector, (which is the only state of this machine btw)

Or how do i figure out what you mean with definitions?

[doudou]

I mean instance requirements that are active at the time of the switch.

Basically, I want to know what syskit had deployed before the transition and what he had to deploy afterwards.

The problem is with before the transition (since it uses a sub-statemachine). After the transition, it is simply pipeline_def (and all the "permanent" tasks you already listed).

2014-07-04 16:13 GMT+02:00 Matthias Goldhoorn notifications@github.com:

You mean also all resolved definition by syskit? -> this could be a LOT (including instance requirements?)

the state machine find_pipe_with_localization finished and was in state pipe_detector, (which is the only state of this machine btw)

Or how do i figure out what you mean with definitions?

— Reply to this email directly or view it on GitHub https://github.com/rock-core/tools-roby/issues/5#issuecomment-48048119.

[goldhoorn]

How i can gather these information?

do i have to extract them out of the roby-logs?

Best, Matthias

On 04.07.2014 16:27, Sylvain Joyeux wrote:

I mean instance requirements that are active at the time of the switch.

Basically, I want to know what syskit had deployed before the transition and what he had to deploy afterwards.

The problem is with before the transition (since it uses a sub-statemachine). After the transition, it is simply pipeline_def (and all the "permanent" tasks you already listed).

2014-07-04 16:13 GMT+02:00 Matthias Goldhoorn notifications@github.com:

You mean also all resolved definition by syskit? -> this could be a LOT (including instance requirements?)

the state machine find_pipe_with_localization finished and was in state pipe_detector, (which is the only state of this machine btw)

Or how do i figure out what you mean with definitions?

— Reply to this email directly or view it on GitHub

https://github.com/rock-core/tools-roby/issues/5#issuecomment-48048119.

— Reply to this email directly or view it on GitHub https://github.com/rock-core/tools-roby/issues/5#issuecomment-48050170.

[doudou]

Well, you can get them by looking at your state machine definitions. They are basically the last state of find_pipe_with_localization plus any depends_on you have declared plus the ones you start manually.

[goldhoorn]

Öhm, you are confusing me, this is what i wrote in the third comment. But i not resolved there the statemachine. Nevertheless, here are again what should run before:

sysmon_dev
modem_dev
depth_reader_dev
depth_reader_rear_dev
depth_fusion_def
joystick_control_def
lights_def
low_level_def
front_camera_dev
bottom_camera_dev
sonar_dev
#In statemachine:
target_move_def(:finish_when_reached => false , :heading => 1, :depth => -6, :x => -6.5, :y => --0.5, :timeout => 180)
#with depends_on:
pipeline_detector_def

and after

sysmon_dev
modem_dev
depth_reader_dev
depth_reader_rear_dev
depth_fusion_def
joystick_control_def
lights_def
low_level_def
front_camera_dev
bottom_camera_dev
sonar_dev
#In statemachine:
pipeline_def(:depth=> -7.1, :heading => 0, :speed_x => 0.5, :turn_dir=> 1, :timeout => 120)

[goldhoorn]

Okay we got a new negative record. Same setup than above but we activated logs.

This caused a reconfiguration of 2 Minutes, and make after that the SV become completly insane. This is absolutly unusable now for us. The Roby-log can be found here: http://auv.informatik.uni-bremen.de/framework/logs/20140710-avalon-events-take-2min.log

The Text output was:

15:37:48.282 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.99) heading=(-18.01 deg, -0.31 rad) target z=(0.00 m)
15:37:49.302 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.98) heading=(-1.88 deg, -0.03 rad) target z=(0.00 m)
Syskit[WARN]: Cannot compute the period information for the output port
Syskit[WARN]:    tProxy(AvalonControl::PositionControlTask:0x7f3b0a3abc58){orocos_name => position_control, conf => [default]}:motion_commands
Syskit[WARN]:    This is needed to compute the policy to connect to
Syskit[WARN]:    tProxy(Logger::Logger:0x6693560){orocos_name => avalon_back_base_control_Logger, conf => [default]}:position_control.motion_commands
Syskit[WARN]:    The fallback policy {type => buffer, size => 25} will be used
Syskit[WARN]: Cannot compute the period information for the output port
Syskit[WARN]:    tProxy(AvalonControl::RelFakeWriter:0x7f3b044515c8){orocos_name => fake_rel_writer, conf => [default]}:position_command
Syskit[WARN]:    This is needed to compute the policy to connect to
Syskit[WARN]:    tProxy(Logger::Logger:0x6693560){orocos_name => avalon_back_base_control_Logger, conf => [default]}:fake_rel_writer.position_command
Syskit[WARN]:    The fallback policy {type => buffer, size => 25} will be used

15:39:05.613 (avalon) interrupting AvalonControl::RelFakeWriter:0x7f3b044515c8
15:39:05.680 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.96) heading=(7.07 deg, 0.12 rad) target z=(0.00 m)
Syskit[WARN]: got 201 state updates for UwParticleLocalization::OrientationCorrection:0x64e1348{orocos_name => orientation_correction, conf => [default]}[], we might have lost some state updates in the process
Syskit[WARN]: got 203 state updates for DepthReader::DepthAndOrientationFusion:0x7f3b086687b8{orocos_name => depth_orientation_fusion, conf => [default]}[], we might have lost some state updates in the process
Syskit[WARN]: got 200 state updates for AvalonControl::MotionControlTask:0x7f3b08fc5130{orocos_name => motion_control, conf => [default]}[], we might have lost some state updates in the process
Syskit[WARN]: got 202 state updates for AvalonControl::PositionControlTask:0x7f3b0a3abc58{orocos_name => position_control, conf => [default]}[], we might have lost some state updates in the process
15:39:07.775 (avalon) stopped AvalonControl::RelFakeWriter:0x7f3b044515c8{orocos_name => fake_rel_writer, conf => [default]}[]
15:39:07.795 (Roby) Internal Error: #emit_without_propagation emitted a LocalizedError exception. This is unsupported and will become a fatal error in the future. You should usually replace raise with engine.add_error
15:39:07.795 (Roby) 
15:39:07.797 (Roby) = Roby::TaskEventNotExecutable: emit(follow_pipe) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/follow_pipe which is a non-executable event
15:39:07.797 (Roby) | follow_pipe event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.798 (Roby) = Backtrace
15:39:07.798 (Roby) | 
15:39:07.798 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:268:in `refine_emit_exception'
15:39:07.799 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:231:in `rescue in check_emission_validity'
15:39:07.799 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:229:in `check_emission_validity'
15:39:07.799 (Roby) |   /home/auv/dev/tools/roby/lib/roby/event_generator.rb:622:in `emit_without_propagation'
15:39:07.799 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1017:in `block (2 levels) in event_propagation_step'
15:39:07.799 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:648:in `propagation_context'
15:39:07.799 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1015:in `block in event_propagation_step'
15:39:07.799 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:559:in `block in gather_propagation'
15:39:07.799 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:648:in `propagation_context'
15:39:07.799 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:559:in `gather_propagation'
15:39:07.800 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1014:in `event_propagation_step'
15:39:07.800 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:783:in `block in event_propagation_phase'
15:39:07.800 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:761:in `gather_errors'
15:39:07.800 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:779:in `event_propagation_phase'
15:39:07.801 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1426:in `process_events'
15:39:07.801 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1940:in `block (2 levels) in event_loop'
15:39:07.801 (Roby) |   /home/auv/dev/tools/roby/lib/roby/support.rb:176:in `synchronize'
15:39:07.801 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1939:in `block in event_loop'
15:39:07.801 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1917:in `loop'
15:39:07.801 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1917:in `event_loop'
15:39:07.801 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1797:in `block (3 levels) in run'
15:39:07.802 (Roby) = 
15:39:07.804 (Roby) Internal Error: #emit_without_propagation emitted a LocalizedError exception. This is unsupported and will become a fatal error in the future. You should usually replace raise with engine.add_error
15:39:07.804 (Roby) 
15:39:07.804 (Roby) = Roby::TaskEventNotExecutable: emit(align_auv) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/align_auv which is a non-executable event
15:39:07.805 (Roby) | align_auv event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.805 (Roby) = Backtrace
15:39:07.805 (Roby) | 
15:39:07.805 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:268:in `refine_emit_exception'
15:39:07.805 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:231:in `rescue in check_emission_validity'
15:39:07.805 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:229:in `check_emission_validity'
15:39:07.805 (Roby) |   /home/auv/dev/tools/roby/lib/roby/event_generator.rb:622:in `emit_without_propagation'
15:39:07.806 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1017:in `block (2 levels) in event_propagation_step'
15:39:07.806 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:648:in `propagation_context'
15:39:07.806 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1015:in `block in event_propagation_step'
15:39:07.806 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:559:in `block in gather_propagation'
15:39:07.806 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:648:in `propagation_context'
15:39:07.806 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:559:in `gather_propagation'
15:39:07.806 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1014:in `event_propagation_step'
15:39:07.806 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:783:in `block in event_propagation_phase'
15:39:07.806 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:761:in `gather_errors'
15:39:07.807 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:779:in `event_propagation_phase'
15:39:07.807 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1426:in `process_events'
15:39:07.807 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1940:in `block (2 levels) in event_loop'
15:39:07.807 (Roby) |   /home/auv/dev/tools/roby/lib/roby/support.rb:176:in `synchronize'
15:39:07.807 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1939:in `block in event_loop'
15:39:07.807 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1917:in `loop'
15:39:07.807 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1917:in `event_loop'
15:39:07.808 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1797:in `block (3 levels) in run'
15:39:07.808 (Roby) = 
15:39:07.810 (Roby) Internal Error: #emit_without_propagation emitted a LocalizedError exception. This is unsupported and will become a fatal error in the future. You should usually replace raise with engine.add_error
15:39:07.810 (Roby) 
15:39:07.811 (Roby) = Roby::TaskEventNotExecutable: emit(lost_pipe) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/lost_pipe which is a non-executable event
15:39:07.811 (Roby) | lost_pipe event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.811 (Roby) = Backtrace
15:39:07.811 (Roby) | 
15:39:07.811 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:268:in `refine_emit_exception'
15:39:07.812 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:231:in `rescue in check_emission_validity'
15:39:07.812 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:229:in `check_emission_validity'
15:39:07.812 (Roby) |   /home/auv/dev/tools/roby/lib/roby/event_generator.rb:622:in `emit_without_propagation'
15:39:07.812 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1017:in `block (2 levels) in event_propagation_step'
15:39:07.813 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:648:in `propagation_context'
15:39:07.813 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1015:in `block in event_propagation_step'
15:39:07.813 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:559:in `block in gather_propagation'
15:39:07.813 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:648:in `propagation_context'
15:39:07.813 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:559:in `gather_propagation'
15:39:07.813 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1014:in `event_propagation_step'
15:39:07.813 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:783:in `block in event_propagation_phase'
15:39:07.813 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:761:in `gather_errors'
15:39:07.813 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:779:in `event_propagation_phase'
15:39:07.814 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1426:in `process_events'
15:39:07.814 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1940:in `block (2 levels) in event_loop'
15:39:07.814 (Roby) |   /home/auv/dev/tools/roby/lib/roby/support.rb:176:in `synchronize'
15:39:07.814 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1939:in `block in event_loop'
15:39:07.814 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1917:in `loop'
15:39:07.814 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1917:in `event_loop'
15:39:07.814 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1797:in `block (3 levels) in run'
15:39:07.814 (Roby) = 
15:39:07.816 (Roby) Internal Error: #emit_without_propagation emitted a LocalizedError exception. This is unsupported and will become a fatal error in the future. You should usually replace raise with engine.add_error
15:39:07.816 (Roby) 
15:39:07.817 (Roby) = Roby::TaskEventNotExecutable: emit(search_pipe) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/search_pipe which is a non-executable event
15:39:07.817 (Roby) | search_pipe event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.817 (Roby) = Backtrace
15:39:07.817 (Roby) | 
15:39:07.817 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:268:in `refine_emit_exception'
15:39:07.818 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:231:in `rescue in check_emission_validity'
15:39:07.818 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:229:in `check_emission_validity'
15:39:07.818 (Roby) |   /home/auv/dev/tools/roby/lib/roby/event_generator.rb:622:in `emit_without_propagation'
15:39:07.818 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1017:in `block (2 levels) in event_propagation_step'
15:39:07.818 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:648:in `propagation_context'
15:39:07.818 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1015:in `block in event_propagation_step'
15:39:07.818 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:559:in `block in gather_propagation'
15:39:07.818 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:648:in `propagation_context'
15:39:07.818 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:559:in `gather_propagation'
15:39:07.819 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1014:in `event_propagation_step'
15:39:07.819 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:783:in `block in event_propagation_phase'
15:39:07.819 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:761:in `gather_errors'
15:39:07.819 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:779:in `event_propagation_phase'
15:39:07.819 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1426:in `process_events'
15:39:07.819 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1940:in `block (2 levels) in event_loop'
15:39:07.819 (Roby) |   /home/auv/dev/tools/roby/lib/roby/support.rb:176:in `synchronize'
15:39:07.819 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1939:in `block in event_loop'
15:39:07.819 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1917:in `loop'
15:39:07.820 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1917:in `event_loop'
15:39:07.820 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1797:in `block (3 levels) in run'
15:39:07.820 (Roby) = 
15:39:07.822 (Roby) Internal Error: #emit_without_propagation emitted a LocalizedError exception. This is unsupported and will become a fatal error in the future. You should usually replace raise with engine.add_error
15:39:07.822 (Roby) 
15:39:07.822 (Roby) = Roby::TaskEventNotExecutable: emit(check_candidate) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/check_candidate which is a non-executable event
15:39:07.822 (Roby) | check_candidate event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.823 (Roby) = Backtrace
15:39:07.823 (Roby) | 
15:39:07.823 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:268:in `refine_emit_exception'
15:39:07.823 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:231:in `rescue in check_emission_validity'
15:39:07.823 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:229:in `check_emission_validity'
15:39:07.825 (Roby) |   /home/auv/dev/tools/roby/lib/roby/event_generator.rb:622:in `emit_without_propagation'
15:39:07.826 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1017:in `block (2 levels) in event_propagation_step'
15:39:07.826 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:648:in `propagation_context'
15:39:07.826 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1015:in `block in event_propagation_step'
15:39:07.826 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:559:in `block in gather_propagation'
15:39:07.826 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:648:in `propagation_context'
15:39:07.826 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:559:in `gather_propagation'
15:39:07.826 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1014:in `event_propagation_step'
15:39:07.827 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:783:in `block in event_propagation_phase'
15:39:07.827 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:761:in `gather_errors'
15:39:07.827 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:779:in `event_propagation_phase'
15:39:07.827 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1426:in `process_events'
15:39:07.827 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1940:in `block (2 levels) in event_loop'
15:39:07.827 (Roby) |   /home/auv/dev/tools/roby/lib/roby/support.rb:176:in `synchronize'
15:39:07.827 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1939:in `block in event_loop'
15:39:07.827 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1917:in `loop'
15:39:07.828 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1917:in `event_loop'
15:39:07.828 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1797:in `block (3 levels) in run'
15:39:07.828 (Roby) = 
15:39:07.830 (Roby) Internal Error: #emit_without_propagation emitted a LocalizedError exception. This is unsupported and will become a fatal error in the future. You should usually replace raise with engine.add_error
15:39:07.830 (Roby) 
15:39:07.830 (Roby) = Roby::TaskEventNotExecutable: emit(found_pipe) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/found_pipe which is a non-executable event
15:39:07.831 (Roby) | found_pipe event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.831 (Roby) = Backtrace
15:39:07.831 (Roby) | 
15:39:07.831 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:268:in `refine_emit_exception'
15:39:07.831 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:231:in `rescue in check_emission_validity'
15:39:07.832 (Roby) |   /home/auv/dev/tools/roby/lib/roby/task_event_generator.rb:229:in `check_emission_validity'
15:39:07.832 (Roby) |   /home/auv/dev/tools/roby/lib/roby/event_generator.rb:622:in `emit_without_propagation'
15:39:07.832 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1017:in `block (2 levels) in event_propagation_step'
15:39:07.832 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:648:in `propagation_context'
15:39:07.832 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1015:in `block in event_propagation_step'
15:39:07.832 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:559:in `block in gather_propagation'
15:39:07.832 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:648:in `propagation_context'
15:39:07.832 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:559:in `gather_propagation'
15:39:07.832 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1014:in `event_propagation_step'
15:39:07.833 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:783:in `block in event_propagation_phase'
15:39:07.833 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:761:in `gather_errors'
15:39:07.833 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:779:in `event_propagation_phase'
15:39:07.833 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1426:in `process_events'
15:39:07.833 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1940:in `block (2 levels) in event_loop'
15:39:07.833 (Roby) |   /home/auv/dev/tools/roby/lib/roby/support.rb:176:in `synchronize'
15:39:07.833 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1939:in `block in event_loop'
15:39:07.833 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1917:in `loop'
15:39:07.834 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1917:in `event_loop'
15:39:07.834 (Roby) |   /home/auv/dev/tools/roby/lib/roby/execution_engine.rb:1797:in `block (3 levels) in run'
15:39:07.834 (Roby) = 
15:39:07.840 (Roby) Roby::TaskEventNotExecutable: emit(follow_pipe) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/follow_pipe which is a non-executable event
15:39:07.840 (Roby) follow_pipe event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.843 (Roby) Roby::TaskEventNotExecutable: emit(align_auv) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/align_auv which is a non-executable event
15:39:07.843 (Roby) align_auv event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.845 (Roby) Roby::TaskEventNotExecutable: emit(lost_pipe) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/lost_pipe which is a non-executable event
15:39:07.845 (Roby) lost_pipe event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.852 (Roby) Roby::TaskEventNotExecutable: emit(search_pipe) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/search_pipe which is a non-executable event
15:39:07.852 (Roby) search_pipe event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.854 (Roby) Roby::TaskEventNotExecutable: emit(check_candidate) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/check_candidate which is a non-executable event
15:39:07.854 (Roby) check_candidate event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.855 (Roby) Roby::TaskEventNotExecutable: emit(found_pipe) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/found_pipe which is a non-executable event
15:39:07.855 (Roby) found_pipe event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.857 (Roby) mission failed: Main::AdvancedDemo:0x6516020{}[]
15:39:07.857 (Roby) Roby::TaskEventNotExecutable: emit(follow_pipe) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/follow_pipe which is a non-executable event
15:39:07.857 (Roby) follow_pipe event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.859 (Roby) mission failed: Main::AdvancedDemo:0x6516020{}[]
15:39:07.859 (Roby) Roby::TaskEventNotExecutable: emit(align_auv) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/align_auv which is a non-executable event
15:39:07.859 (Roby) align_auv event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.860 (Roby) mission failed: Main::AdvancedDemo:0x6516020{}[]
15:39:07.860 (Roby) Roby::TaskEventNotExecutable: emit(lost_pipe) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/lost_pipe which is a non-executable event
15:39:07.860 (Roby) lost_pipe event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.861 (Roby) mission failed: Main::AdvancedDemo:0x6516020{}[]
15:39:07.861 (Roby) Roby::TaskEventNotExecutable: emit(search_pipe) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/search_pipe which is a non-executable event
15:39:07.861 (Roby) search_pipe event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.862 (Roby) mission failed: Main::AdvancedDemo:0x6516020{}[]
15:39:07.862 (Roby) Roby::TaskEventNotExecutable: emit(check_candidate) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/check_candidate which is a non-executable event
15:39:07.862 (Roby) check_candidate event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.863 (Roby) mission failed: Main::AdvancedDemo:0x6516020{}[]
15:39:07.863 (Roby) Roby::TaskEventNotExecutable: emit(found_pipe) called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[] which is not executable: #emit called on Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360{depth => -7, heading => 0, speed_x => 0.5, turn_dir => 1, timeout => 120}[]/found_pipe which is a non-executable event
15:39:07.863 (Roby) found_pipe event of Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360the task has NOT been garbage collected
15:39:07.864 (Roby) will kill the following 2 tasks because of unhandled exceptions:
15:39:07.864 (Roby) Pipeline::Follower/[controller.is_a?(Base::AUVRelativeMotionControllerSrv), controlled_system.is_a?(Base::AUVRelativeMotionControlledSystemSrv)]:0x7f3b0a09b360
15:39:07.864 (Roby)   owners: Roby::Distributed
15:39:07.864 (Roby)   arguments: :depth => -7,
15:39:07.864 (Roby)   :heading => 0,
15:39:07.864 (Roby)   :speed_x => 0.5,
15:39:07.864 (Roby)   :turn_dir => 1,
15:39:07.864 (Roby)   :timeout => 120
15:39:07.864 (Roby) Main::AdvancedDemo:0x6516020   owners: Roby::Distributed arguments: 
15:39:07.907 (avalon) interrupting AvalonControl::PositionControlTask:0x7f3b0a3abc58
15:39:07.941 (avalon) interrupting Hbridge::SensorReader:0x62c9970
15:39:07.943 (avalon) interrupting Hbridge::CommandWriter:0x66ccc20
15:39:07.944 (avalon) interrupting PipelineInspection::Inspection:0x7f3b0a6f6ae8
15:39:07.944 (avalon) interrupting OffshorePipelineDetector::Task:0x7f3b0ac16190
15:39:08.092 (avalon) interrupting LineScanner::Task:0x7f3b0ad9a1d8
15:39:08.120 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.97) heading=(56.50 deg, 0.99 rad) target z=(0.00 m)
15:39:08.296 (avalon) stopped Hbridge::SensorReader:0x62c9970{orocos_name => hbridge_reader, conf => [default], device_dev => device(Dev::Sensors::Hbridge, :as => actuatorss_sensors)}[]
15:39:08.298 (avalon) stopped Hbridge::CommandWriter:0x66ccc20{orocos_name => hbridge_writer, conf => [default], device_dev => device(Dev::Actuators::Hbridge, :as => actuatorss_actuators)}[]
15:39:08.300 (avalon) stopped AvalonControl::PositionControlTask:0x7f3b0a3abc58{orocos_name => position_control, conf => [default]}[]
15:39:08.301 (avalon) stopped PipelineInspection::Inspection:0x7f3b0a6f6ae8{orocos_name => inspection, conf => [default]}[]
15:39:08.302 (avalon) stopped OffshorePipelineDetector::Task:0x7f3b0ac16190{orocos_name => pipeline_follower, conf => [default]}[]
15:39:08.303 (avalon) stopped LineScanner::Task:0x7f3b0ad9a1d8{orocos_name => line_scanner, conf => [default]}[]
Syskit[WARN]: while disconnecting #<TaskContext: Orocos::TaskContext//bottom_camera>:frame => #<TaskContext: Orocos::TaskContext//pipeline_follower>:frame returned false
Syskit[WARN]: I assume that the ports are disconnected, but this should not have happened
15:39:10.040 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.97) heading=(56.72 deg, 0.99 rad) target z=(0.00 m)
Syskit[WARN]: got 201 state updates for DepthReader::DepthAndOrientationFusion:0x7f3b086687b8{orocos_name => depth_orientation_fusion, conf => [default]}[], we might have lost some state updates in the process
15:39:10.068 (avalon) cleaning up Logger::Logger:0x7f3b08834880{orocos_name => auv_rel_pos_controller_Logger, conf => [default]}[]
15:39:10.121 (avalon) applied configuration [default] to /auv_rel_pos_controller_Logger
15:39:10.155 (avalon) setting up Logger::Logger:0x7f3b08834880{orocos_name => auv_rel_pos_controller_Logger, conf => [default]}[]
15:39:10.165 (avalon) starting Logger::Logger:0x7f3b08834880{orocos_name => auv_rel_pos_controller_Logger, conf => [default]}[] (auv_rel_pos_controller_Logger)
15:39:10.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.97) heading=(61.42 deg, 1.07 rad) target z=(0.00 m)
15:39:11.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.96) heading=(62.80 deg, 1.10 rad) target z=(0.00 m)
15:39:12.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.92) heading=(64.08 deg, 1.12 rad) target z=(0.00 m)
15:39:14.055 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.87) heading=(65.52 deg, 1.14 rad) target z=(0.00 m)
15:39:14.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.82) heading=(66.37 deg, 1.16 rad) target z=(0.00 m)
15:39:15.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.76) heading=(67.09 deg, 1.17 rad) target z=(0.00 m)
15:39:16.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.69) heading=(67.49 deg, 1.18 rad) target z=(0.00 m)
15:39:17.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.62) heading=(67.54 deg, 1.18 rad) target z=(0.00 m)
15:39:19.059 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.54) heading=(67.18 deg, 1.17 rad) target z=(0.00 m)
15:39:19.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.48) heading=(66.75 deg, 1.16 rad) target z=(0.00 m)
15:39:20.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.36) heading=(66.05 deg, 1.15 rad) target z=(0.00 m)
15:39:21.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.26) heading=(65.43 deg, 1.14 rad) target z=(0.00 m)
15:39:22.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.16) heading=(64.76 deg, 1.13 rad) target z=(0.00 m)
15:39:23.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.08) heading=(64.04 deg, 1.12 rad) target z=(0.00 m)
15:39:24.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-5.00) heading=(63.45 deg, 1.11 rad) target z=(0.00 m)
15:39:25.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-4.90) heading=(62.71 deg, 1.09 rad) target z=(0.00 m)
15:39:26.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-4.74) heading=(61.87 deg, 1.08 rad) target z=(0.00 m)
15:39:27.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-4.64) heading=(60.93 deg, 1.06 rad) target z=(0.00 m)
15:39:28.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-4.55) heading=(59.89 deg, 1.05 rad) target z=(0.00 m)
15:39:29.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-4.46) heading=(59.12 deg, 1.03 rad) target z=(0.00 m)
15:39:30.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-4.35) heading=(58.40 deg, 1.02 rad) target z=(0.00 m)
15:39:31.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-4.27) heading=(57.87 deg, 1.01 rad) target z=(0.00 m)
15:39:32.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-4.18) heading=(57.54 deg, 1.00 rad) target z=(0.00 m)
15:39:33.982 (avalon) state=5 sub-state=4 pos=(x=0.00 y=0.00 z=-4.05) heading=(57.39 deg, 1.00 rad) target z=(0.00 m)

[goldhoorn]

To correct myself, we used another state-machine, but this part of the other statemachine is the same then in the old explained one...

And i have the patch as poroposed in #3 active.

[doudou]

Well .. correct yourself one more time.

Yes, syskit takes really too long to compute these changes. But syskit's algorithm is deterministic. You ask him the same transition, it is going to take the same time +/- 10% .... So I went looking somewhere else and found out that I am logging CPU time spent in Roby/Syskit.

From the Roby logs, it seems that you are starving the syskit/roby process. In the 75s cycle in which the switch happened, syskit only took 21s of CPU time (which matches your current - bad - experience with long switches). You can generate this data with

roby-log stats --csv avalon-events.log

You'll have to remove the first lines that are not CSV-compliant before you can feed that into localc or something equivalent.

The orogen_loaders branch take 1.8s to switch on a system that is roughly equivalent to yours (Core i7 2.0 GHz). I don't think it is worth our collective time that we continue discussing on this thread until we get orogen_loaders to work for you.

The patch in #3 is wrong (broken, as you can see in the output you just posted). I'll answer directly there.

[goldhoorn]

Well for the same transision syskit indeed the same time. The relevant point was that i added the loggers, with logger it took two minutes...

Nevertheless, i fully agree that we spend out concentration to orogen-loader and fix them soon instead triing to debug this old. We can posprune this issue after the orogen_loader merge if the merge will not fix this issue...

Best, Matthias

[doudou]

Yeah ... and did you consider that maybe adding the loggers could have some effect on the I/O ? Given that Roby only used 21s of CPU, that would definitely be my guess. If you have not turned off debug logging during the merge, that would definitely hit you. It could also make the main Roby thread wait for the logger. Try doing a x10 to x20 on LOGGED_EVENTS_QUEUE_SIZE and see if it improves the situation.

Bottom line: the 2 minutes switch is most probably not a syskit problem, and I would even argue that it is not a Roby one. This is a system problem, you're getting low on some ressource and starving the roby process one way or the other.

[doudou]

I'm closing this. This particular issue got a lot better, even though the merge algorithm has still some complexity problems for graphs with a lot of redundant loops.