Open joaobrittoneto opened 6 years ago
I use a composition to generate input commands for the auv_control
poll
is called at the periodicity of the Syskit event loop. Its periodicity is not guaranteed.
However, the plan generation is meant to be asynchronous, leaving the event loop free to react to things (and call poll
), The log you've just shown tends to prove otherwise - the 2s delay you're seeing seem to be related to the network generation since there are no timepoints related to the event loop within the 2s period. This is seems to be a Syskit performance / setup bug that needs to be investigated.
Moreover, ConstantGenerator
does the generation within a thread to guarantee a better periodicity. While this may be affected by the same issue, I would suggest to refactor ConstantGenerator into a ThreadedPortWriter abstract base class where most of the thread-handling would be done, and use this as a basis for your sinusoidal generator. This would definitely improve reactivity. However, it could also be affected by the same thread scheduling bug.
This is seems to be a Syskit performance / setup bug that needs to be investigated.
At this moment, syskit was starting the cameras. It seems that the camera driver has some sleeps in the startHook(1,2) and stopHook. Would it affect the syskit operation? Would Syskit wait for the start / stopHook to finalize?
Would Syskit wait for the start / stopHook to finalize?
The analysis I gave you comes from the log you sent. The network generation seem to be starving the main thread, which means that Syskit almost does not react to incoming events. This is purely internal to Syskit (probably a thread priority thing).
Syskit does not wait for configure/start/stop/cleanup (it waits for them to complete asynchronously).
The network generation seem to be starving the main thread, which means that Syskit almost does not react to incoming events
It seems to be the case. There are other cases where the poll block take some time to be called during a network generation.
Moreover, ConstantGenerator does the generation within a thread to guarantee a better periodicity. While this may be affected by the same issue, I would suggest to refactor ConstantGenerator into a ThreadedPortWriter abstract base class where most of the thread-handling would be done, and use this as a basis for your sinusoidal generator. This would definitely improve reactivity. However, it could also be affected by the same thread scheduling bug.
It could help. But I wonder if creating a component to provide a dynamic signal would not be a simpler and more robust solution (I imagine this kind of discussion had happened before )
It could help. But I wonder if creating a component to provide a dynamic signal would not be a simpler and more robust solution (I imagine this kind of discussion had happened before )
Generally speaking, creating a workflow that does not require a full blown C++ component for generating simple values definitely has some value (on both development and deployment time). But YMMV.
At this stage, Syskit is the limiting factor. If you don't have the resources/time to improve the situation, an orogen component will definitely work for your use case.
For the record, the Syskit bug must be fixed in any case since it affects its reactivity.
For the record, the Syskit bug must be fixed in any case since it affects its reactivity.
Agreed. I see this bug as a major bottle neck for Syskit.
It may be a dumb question, but is it not possible to use a different thread for the network generation, other than the main thread? In such a way, even if the network generation takes long, it would not affect the main thread (and the poll block of existing components). It would not be a definitive fix (the network generation would still need to be improved), but would mitigate the effects. Does it make sense?
Does it make sense?
Yes. That's actually why it is implemented this way already ;-) I would have called it a design flaw otherwise ;-) The bug is that the generation thread is starving the main thread. Which is the issue that needs to be investigated.
Ruby and Python (and some other VMs) actually run only one thread at a time. They still time-share a single CPU, but there seem to be an issue that I don't completely understand so far that leads to having multi-second starvation of the main execution thread.
Alright,
After reading a little bit about threads in ruby, it starts to make sense to me.
As there is only one thread in Ruby running, the other threads needs to time-share the CPU, and the thread's priority indicates which thread should run in the sequence.
So the generation thread (syskit-async-resolution
) probably has a higher priority than the main thread (MAIN
), or has methods that take long.
I tried the roby-log timepoints
in the same log.
The first field, I guess, is the time after start. The second field is not clear for me, but I guess the third field is the duration of the respective block, is that right?
So the 751 is equivalent to 16:28:51.
So the duration of a cycle (which call a pool block), from start to end, in normal case is ~0.1s, as expected.
752.002 0.000 0.100 cycle:end
But then, there are two cycles that take longer.
752.549 0.000 0.547 cycle:end
755.907 0.000 3.358 cycle:end
What seems to take really long in the second cycle:
752.979 0.429 0.429 TCPServer#process_pending_requests:end
754.205 1.201 1.201 syskit:update_task_states:end
755.766 0.006 1.543 syskit:apply_requirement_modifications:end
What does a cycle represent? I have the feeling that it is not a priority issue, since the pool block is called every cycle.
751.502 0.000 cycle:start
751.502 0.000 process_events:start
751.502 0.000 workers
751.502 0.000 syskit-transformer transformer broadcaster start:start
751.503 0.000 0.000 syskit-transformer transformer broadcaster start:end
751.503 0.000 each_cycle:start
751.503 0.000 0.000 each_cycle:end
751.503 0.000 TCPServer#process_pending_requests:start
751.503 0.000 0.000 TCPServer#process_pending_requests:end
751.503 0.000 syskit:update_deployment_states:start
751.503 0.000 0.000 syskit:update_deployment_states:end
751.503 0.000 syskit:update_task_states:start
751.510 0.007 0.007 syskit:update_task_states:end
751.510 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):start
751.510 0.000 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):end
751.510 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):start
751.510 0.000 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):end
751.510 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):start
751.511 0.000 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):end
751.511 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):start
751.511 0.000 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):end
751.511 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):start
751.511 0.000 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):end
751.511 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):start
751.511 0.000 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):end
751.511 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):start
751.511 0.000 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):end
751.511 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():start
751.511 0.000 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():end
751.511 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):start
751.511 0.000 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):end
751.511 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():start
751.511 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():end
751.511 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):start
751.511 0.000 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):end
751.511 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):start
751.511 0.000 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):end
751.511 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():start
751.511 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():end
751.511 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):start
751.512 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):end
751.512 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):start
751.513 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):end
751.513 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):start
751.515 0.002 0.002 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):end
751.515 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):start
751.516 0.002 0.002 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):end
751.516 0.000 external_events
751.517 0.001 scheduler
751.517 0.000 poll_state_events:start
751.517 0.000 0.000 poll_state_events:end
751.517 0.000 syskit:connection_management_update:start
751.518 0.001 0.001 syskit:connection_management_update:end
751.518 0.000 syskit:apply_requirement_modifications:start
751.519 0.000 0.000 syskit:apply_requirement_modifications:end
751.519 0.000 propagation_handlers
751.519 0.000 event_propagation_phase:start
751.519 0.000 0.000 event_propagation_phase:end
751.519 0.000 error_handling_phase:start
751.519 0.000 structure_check
751.519 0.000 exception_propagation
751.521 0.001 0.002 error_handling_phase:end
751.526 0.006 garbage_collect
751.526 0.000 0.024 process_events:end
751.600 0.074 sleep
751.600 0.000 at_cycle_end:start
751.602 0.001 0.001 at_cycle_end:end
751.603 0.001 0.101 cycle:end
751.603 0.000 cycle:start
751.603 0.000 process_events:start
751.603 0.000 workers
751.603 0.000 syskit-transformer transformer broadcaster start:start
751.603 0.000 0.000 syskit-transformer transformer broadcaster start:end
751.603 0.000 each_cycle:start
751.603 0.000 0.000 each_cycle:end
751.603 0.000 TCPServer#process_pending_requests:start
751.603 0.000 0.000 TCPServer#process_pending_requests:end
751.603 0.000 syskit:update_deployment_states:start
751.603 0.000 0.000 syskit:update_deployment_states:end
751.603 0.000 syskit:update_task_states:start
751.610 0.006 0.006 syskit:update_task_states:end
751.610 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):start
751.610 0.000 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):end
751.610 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):start
751.610 0.000 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):end
751.610 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):start
751.610 0.000 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):end
751.610 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):start
751.610 0.000 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):end
751.610 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):start
751.610 0.000 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):end
751.610 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):start
751.610 0.000 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):end
751.610 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):start
751.610 0.000 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):end
751.610 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():start
751.610 0.000 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():end
751.610 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):start
751.610 0.000 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):end
751.610 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():start
751.610 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():end
751.610 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):start
751.611 0.000 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):end
751.611 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):start
751.611 0.000 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):end
751.611 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():start
751.611 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():end
751.611 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):start
751.611 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):end
751.611 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):start
751.612 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):end
751.612 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):start
751.613 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):end
751.613 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):start
751.613 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):end
751.613 0.000 external_events
751.614 0.001 scheduler
751.614 0.000 poll_state_events:start
751.614 0.000 0.000 poll_state_events:end
751.614 0.000 syskit:connection_management_update:start
751.616 0.002 0.002 syskit:connection_management_update:end
751.616 0.000 syskit:apply_requirement_modifications:start
751.616 0.001 0.001 syskit:apply_requirement_modifications:end
751.616 0.000 propagation_handlers
751.616 0.000 event_propagation_phase:start
751.616 0.000 0.000 event_propagation_phase:end
751.616 0.000 error_handling_phase:start
751.616 0.000 structure_check
751.616 0.000 exception_propagation
751.617 0.001 0.001 error_handling_phase:end
751.622 0.005 garbage_collect
751.622 0.000 0.020 process_events:end
751.700 0.078 sleep
751.700 0.000 at_cycle_end:start
751.701 0.001 0.001 at_cycle_end:end
751.702 0.000 0.099 cycle:end
751.702 0.000 cycle:start
751.702 0.000 process_events:start
751.702 0.000 workers
751.702 0.000 syskit-transformer transformer broadcaster start:start
751.703 0.001 0.001 syskit-transformer transformer broadcaster start:end
751.703 0.000 each_cycle:start
751.703 0.000 0.000 each_cycle:end
751.703 0.000 TCPServer#process_pending_requests:start
751.703 0.000 0.000 TCPServer#process_pending_requests:end
751.703 0.000 syskit:update_deployment_states:start
751.703 0.000 0.000 syskit:update_deployment_states:end
751.703 0.000 syskit:update_task_states:start
751.709 0.006 0.006 syskit:update_task_states:end
751.709 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):start
751.709 0.000 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):end
751.709 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):start
751.709 0.000 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):end
751.709 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):start
751.709 0.000 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):end
751.709 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):start
751.709 0.000 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):end
751.709 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):start
751.710 0.001 0.001 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):end
751.710 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):start
751.710 0.000 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):end
751.710 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):start
751.710 0.000 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):end
751.710 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():start
751.710 0.000 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():end
751.710 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):start
751.710 0.000 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):end
751.710 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():start
751.711 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():end
751.711 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):start
751.711 0.000 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):end
751.711 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):start
751.711 0.000 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):end
751.711 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():start
751.711 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():end
751.711 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):start
751.711 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):end
751.711 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):start
751.712 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):end
751.712 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):start
751.713 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):end
751.713 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):start
751.713 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):end
751.713 0.000 external_events
751.714 0.001 scheduler
751.714 0.000 poll_state_events:start
751.714 0.000 0.000 poll_state_events:end
751.714 0.000 syskit:connection_management_update:start
751.716 0.002 0.002 syskit:connection_management_update:end
751.716 0.000 syskit:apply_requirement_modifications:start
751.716 0.000 0.000 syskit:apply_requirement_modifications:end
751.716 0.000 propagation_handlers
751.716 0.000 event_propagation_phase:start
751.716 0.000 0.000 event_propagation_phase:end
751.716 0.000 error_handling_phase:start
751.716 0.000 structure_check
751.717 0.000 exception_propagation
751.717 0.001 0.001 error_handling_phase:end
751.722 0.005 garbage_collect
751.722 0.000 0.020 process_events:end
751.800 0.078 sleep
751.800 0.000 at_cycle_end:start
751.801 0.001 0.001 at_cycle_end:end
751.802 0.000 0.100 cycle:end
751.802 0.000 cycle:start
751.802 0.000 process_events:start
751.802 0.000 workers
751.802 0.000 syskit-transformer transformer broadcaster start:start
751.803 0.001 0.001 syskit-transformer transformer broadcaster start:end
751.803 0.000 each_cycle:start
751.803 0.000 0.000 each_cycle:end
751.803 0.000 TCPServer#process_pending_requests:start
751.803 0.000 0.000 TCPServer#process_pending_requests:end
751.803 0.000 syskit:update_deployment_states:start
751.803 0.000 0.000 syskit:update_deployment_states:end
751.803 0.000 syskit:update_task_states:start
751.809 0.006 0.006 syskit:update_task_states:end
751.809 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):start
751.809 0.000 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):end
751.809 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):start
751.809 0.000 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):end
751.809 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):start
751.809 0.000 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):end
751.809 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):start
751.810 0.000 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):end
751.810 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):start
751.810 0.000 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):end
751.810 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):start
751.810 0.000 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):end
751.810 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):start
751.810 0.000 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):end
751.810 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():start
751.810 0.000 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():end
751.810 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):start
751.810 0.000 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):end
751.810 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():start
751.810 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():end
751.810 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):start
751.810 0.000 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):end
751.810 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):start
751.810 0.000 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):end
751.810 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():start
751.810 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():end
751.810 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):start
751.811 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):end
751.811 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):start
751.812 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):end
751.812 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):start
751.812 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):end
751.812 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):start
751.813 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):end
751.813 0.000 external_events
751.814 0.001 scheduler
751.814 0.000 poll_state_events:start
751.814 0.000 0.000 poll_state_events:end
751.814 0.000 syskit:connection_management_update:start
751.815 0.001 0.001 syskit:connection_management_update:end
751.815 0.000 syskit:apply_requirement_modifications:start
751.816 0.001 0.001 syskit:apply_requirement_modifications:end
751.816 0.000 propagation_handlers
751.816 0.000 event_propagation_phase:start
751.816 0.000 0.000 event_propagation_phase:end
751.816 0.000 error_handling_phase:start
751.816 0.000 structure_check
751.816 0.000 exception_propagation
751.817 0.001 0.001 error_handling_phase:end
751.822 0.005 garbage_collect
751.822 0.000 0.020 process_events:end
751.900 0.078 sleep
751.900 0.000 at_cycle_end:start
751.901 0.001 0.001 at_cycle_end:end
751.902 0.000 0.100 cycle:end
751.902 0.000 cycle:start
751.902 0.000 process_events:start
751.902 0.000 workers
751.902 0.000 syskit-transformer transformer broadcaster start:start
751.902 0.000 0.000 syskit-transformer transformer broadcaster start:end
751.902 0.000 each_cycle:start
751.902 0.000 0.000 each_cycle:end
751.902 0.000 TCPServer#process_pending_requests:start
751.902 0.000 0.000 TCPServer#process_pending_requests:end
751.902 0.000 syskit:update_deployment_states:start
751.902 0.000 0.000 syskit:update_deployment_states:end
751.902 0.000 syskit:update_task_states:start
751.909 0.006 0.006 syskit:update_task_states:end
751.909 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):start
751.909 0.000 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):end
751.909 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):start
751.909 0.000 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):end
751.909 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):start
751.909 0.000 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):end
751.909 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):start
751.909 0.000 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):end
751.909 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):start
751.909 0.000 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):end
751.909 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):start
751.909 0.000 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):end
751.909 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):start
751.909 0.000 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):end
751.909 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():start
751.909 0.000 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():end
751.909 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):start
751.909 0.000 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):end
751.909 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():start
751.909 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():end
751.909 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):start
751.909 0.000 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):end
751.909 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):start
751.910 0.000 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):end
751.910 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():start
751.910 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():end
751.910 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):start
751.910 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):end
751.910 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):start
751.911 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):end
751.911 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):start
751.912 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):end
751.912 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):start
751.912 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):end
751.912 0.000 external_events
751.913 0.001 scheduler
751.913 0.000 poll_state_events:start
751.913 0.000 0.000 poll_state_events:end
751.913 0.000 syskit:connection_management_update:start
751.914 0.001 0.001 syskit:connection_management_update:end
751.914 0.000 syskit:apply_requirement_modifications:start
751.914 0.000 0.000 syskit:apply_requirement_modifications:end
751.914 0.000 propagation_handlers
751.914 0.000 event_propagation_phase:start
751.914 0.000 0.000 event_propagation_phase:end
751.914 0.000 error_handling_phase:start
751.914 0.000 structure_check
751.914 0.000 exception_propagation
751.915 0.001 0.001 error_handling_phase:end
751.920 0.005 garbage_collect
751.920 0.000 0.018 process_events:end
752.000 0.080 sleep
752.000 0.000 at_cycle_end:start
752.001 0.001 0.001 at_cycle_end:end
752.002 0.000 0.100 cycle:end
752.002 0.000 cycle:start
752.002 0.000 process_events:start
752.002 0.000 workers
752.002 0.000 syskit-transformer transformer broadcaster start:start
752.002 0.000 0.000 syskit-transformer transformer broadcaster start:end
752.002 0.000 each_cycle:start
752.002 0.000 0.000 each_cycle:end
752.002 0.000 TCPServer#process_pending_requests:start
752.074 0.072 0.072 TCPServer#process_pending_requests:end
752.074 0.000 syskit:update_deployment_states:start
752.074 0.000 0.000 syskit:update_deployment_states:end
752.074 0.000 syskit:update_task_states:start
752.081 0.007 0.007 syskit:update_task_states:end
752.081 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):start
752.081 0.000 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):end
752.081 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):start
752.082 0.000 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):end
752.082 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):start
752.082 0.000 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):end
752.082 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):start
752.082 0.000 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):end
752.082 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):start
752.082 0.000 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):end
752.082 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):start
752.082 0.000 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):end
752.082 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):start
752.082 0.000 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):end
752.082 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():start
752.082 0.000 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():end
752.082 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):start
752.082 0.000 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):end
752.082 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():start
752.082 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():end
752.082 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):start
752.083 0.000 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):end
752.083 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):start
752.083 0.000 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):end
752.083 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():start
752.083 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():end
752.083 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):start
752.084 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):end
752.084 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):start
752.084 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):end
752.084 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):start
752.085 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):end
752.085 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):start
752.086 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):end
752.086 0.000 external_events
752.088 0.002 scheduler
752.088 0.000 poll_state_events:start
752.088 0.000 0.000 poll_state_events:end
752.088 0.000 propagation_handlers
752.088 0.000 event_propagation_phase:start
752.092 0.004 scheduler
752.092 0.000 poll_state_events:start
752.092 0.000 0.000 poll_state_events:end
752.092 0.000 syskit:connection_management_update:start
752.093 0.001 0.001 syskit:connection_management_update:end
752.093 0.000 syskit:apply_requirement_modifications:start
752.250 0.156 0.156 syskit:apply_requirement_modifications:end
752.250 0.000 0.162 event_propagation_phase:end
752.348 0.098 error_handling_phase:start
752.348 0.099 structure_check
752.348 0.000 exception_propagation
752.349 0.001 0.002 error_handling_phase:end
752.358 0.009 garbage_collect
752.358 0.000 0.356 process_events:end
752.358 0.000 sleep
752.358 0.000 at_cycle_end:start
752.549 0.190 0.190 at_cycle_end:end
752.549 0.000 0.547 cycle:end
752.549 0.000 cycle:start
752.549 0.000 process_events:start
752.549 0.000 workers
752.549 0.000 syskit-transformer transformer broadcaster start:start
752.549 0.000 0.000 syskit-transformer transformer broadcaster start:end
752.549 0.000 each_cycle:start
752.550 0.000 0.000 each_cycle:end
752.550 0.000 TCPServer#process_pending_requests:start
752.979 0.429 0.429 TCPServer#process_pending_requests:end
752.979 0.000 syskit:update_deployment_states:start
753.005 0.026 0.026 syskit:update_deployment_states:end
753.005 0.000 syskit:update_task_states:start
754.205 1.201 1.201 syskit:update_task_states:end
754.205 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):start
754.206 0.000 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):end
754.206 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):start
754.206 0.000 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):end
754.206 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):start
754.206 0.001 0.001 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):end
754.206 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):start
754.208 0.001 0.001 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):end
754.208 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):start
754.212 0.004 0.004 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):end
754.212 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):start
754.212 0.000 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):end
754.212 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):start
754.212 0.000 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):end
754.212 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():start
754.212 0.000 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():end
754.212 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):start
754.212 0.000 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):end
754.212 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():start
754.212 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():end
754.212 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):start
754.212 0.000 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):end
754.212 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):start
754.213 0.000 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):end
754.213 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():start
754.214 0.001 0.001 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():end
754.214 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):start
754.215 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):end
754.215 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):start
754.216 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):end
754.216 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):start
754.216 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):end
754.216 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):start
754.217 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):end
754.217 0.000 external_events
754.220 0.003 scheduler
754.220 0.000 poll_state_events:start
754.220 0.000 0.000 poll_state_events:end
754.220 0.000 propagation_handlers
754.220 0.000 event_propagation_phase:start
754.222 0.002 scheduler
754.222 0.000 poll_state_events:start
754.222 0.000 0.000 poll_state_events:end
754.222 0.000 syskit:connection_management_update:start
754.223 0.001 0.001 syskit:connection_management_update:end
754.223 0.000 syskit:apply_requirement_modifications:start
754.228 0.005 apply_deployed_network_to_plan:start
754.228 0.005 finalize_deployed_tasks:start
754.229 0.006 used_tasks
754.357 0.128 import_all_tasks_from_plan
754.359 0.002 all_tasks_cleanup
754.370 0.012 dataflow_graph_cleanup
754.427 0.056 existing_and_finished_deployments
754.834 0.408 select_deployments
754.849 0.014 reconfigure_tasks_on_static_port_modification
755.105 0.256 merge
755.105 0.000 0.876 finalize_deployed_tasks:end
755.105 0.001 apply_merged_to_dataflow_dynamics
755.195 0.090 postprocessing:#<Proc:0x00000002b9da00 (lambda)>
755.259 0.063 postprocessing:#<Proc:0x000000037ba720@/home/flatfish/dev.bir/install/lib/ruby/2.3.0/transformer/syskit/plugin.rb:319>
755.259 0.000 1.030 apply_deployed_network_to_plan:end
755.262 0.004 apply_merge_to_stored_instances
755.294 0.032 fix_toplevel_tasks
755.294 0.000 validate_final_network
755.761 0.466 commit_transaction
755.766 0.006 1.543 syskit:apply_requirement_modifications:end
755.771 0.005 scheduler
755.771 0.000 poll_state_events:start
755.771 0.000 0.000 poll_state_events:end
755.831 0.060 scheduler
755.831 0.000 poll_state_events:start
755.831 0.000 0.000 poll_state_events:end
755.831 0.000 syskit:connection_management_update:start
755.833 0.001 0.001 syskit:connection_management_update:end
755.833 0.000 syskit:apply_requirement_modifications:start
755.833 0.000 0.000 syskit:apply_requirement_modifications:end
755.833 0.000 1.613 event_propagation_phase:end
755.833 0.000 error_handling_phase:start
755.833 0.000 structure_check
755.833 0.000 exception_propagation
755.834 0.001 0.001 error_handling_phase:end
755.858 0.024 garbage_collect
755.858 0.000 3.309 process_events:end
755.858 0.000 sleep
755.858 0.000 at_cycle_end:start
755.907 0.048 0.048 at_cycle_end:end
755.907 0.000 3.358 cycle:end
755.907 0.000 cycle:start
755.907 0.000 process_events:start
755.907 0.000 workers
755.907 0.000 syskit-transformer transformer broadcaster start:start
755.908 0.000 0.000 syskit-transformer transformer broadcaster start:end
755.908 0.000 each_cycle:start
755.908 0.000 0.000 each_cycle:end
755.908 0.000 TCPServer#process_pending_requests:start
755.919 0.011 0.011 TCPServer#process_pending_requests:end
755.919 0.000 syskit:update_deployment_states:start
755.919 0.000 0.000 syskit:update_deployment_states:end
755.919 0.000 syskit:update_task_states:start
755.926 0.007 0.007 syskit:update_task_states:end
755.926 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):start
755.926 0.000 0.000 poll block of Dive::Compositions::Communication::IoDebug::Process:0x83bdca8<id:1912>(command_line: ["dumpcap", "-i", "any", "-q", "-f", "ip host 192.168.42.5", "-f", "port 49155", "-w", "debug_usbl.pcap"], working_directory: /home/flatfish/dev.bir/bundles/flat_fish/logs/20171205-1616):end
755.926 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):start
755.926 0.000 0.000 poll block of FlatFish::Tasks::Safety:0x5f3f660<id:2055>(auv_messaging: syskit_auv_messaging_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_network: network_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_surface: surface_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), coms_uw: uw_communication_def of profile:FlatFish::Actions::Live::Safety::Profile(), flatfishd_com: FlatFish::Actions::Live::Safety.flatfishd_communication()):end
755.926 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):start
755.926 0.000 0.000 poll block of FlatFish::Tasks::FlatfishdCommunication:0xf307898<id:2173>(flatfishd_port: 49201, heartbeat_period: 1, housing: nav, local_port: 49200):end
755.926 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):start
755.927 0.000 0.000 poll block for Dive::Compositions::Communication::ControlSourceLevel:0xee46d90<id:2508>(depth_threshold: -1, surface_threshold: -0.5):end
755.927 0.000 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):start
755.928 0.002 0.002 poll block for FlatFish::Compositions::SyskitAUVMessaging:0xedc1618<id:2510>(local_endpoint: AUV_MSG_ENDPOINT_ROCKENV_NAV, state_period_fast: 2, state_period_slow: 10):end
755.928 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):start
755.928 0.000 0.000 poll block of OroGen::Transformer::Task:0x80355b8<id:2488>(conf: ["default"], orocos_name: transformer_broadcaster):end
755.928 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):start
755.929 0.000 0.000 poll block for FlatFish::Tasks::RequireAutonomousMode:0x4f33910<id:3210>(period: 5, timeout: 10):end
755.929 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():start
755.929 0.000 0.000 poll block for Dive::Compositions::PoseEstimation::DeadReckoning:0x7f5aedfb1f40<id:4689>():end
755.929 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):start
755.929 0.000 0.000 poll block of FlatFish::Actions::ModelEstimation::LinearYModelEstimationWithSinusMovement:0xf5589f8<id:5929>(config_name: one_dof, estimator_timeout: 300, file: config/orogen/live/uwv_dynamic_model::Task.yml, initial_pose: {:x=>0.47048200226832804, :y=>-2.13343465528618, :z=>-3, :yaw=>0}, replace: true, signal: {:y=>{:amplitude=>2, :frequency=>0.2}}):end
755.929 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():start
755.929 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovementFromCurrentPose:0x7f5aec05cd20<id:6066>():end
755.929 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):start
755.929 0.000 0.000 poll block of FlatFish::Compositions::ModelEstimation::OneDofModelEstimationWithTimeout:0x7f5aed91e318<id:6152>(estimator_timeout: 300, mission_name: linear_y_model_estimation, timeout_action: FlatFish::Actions::Live::Navigation.mission_timeout(mission_name => linear_y_model_estimation, mission_timeout => 300)):end
755.929 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):start
755.929 0.000 0.000 poll block of FlatFish::Tasks::MissionTimeout:0x82b5a40<id:6213>(mission_name: linear_y_model_estimation, mission_timeout: 300):end
755.929 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():start
755.929 0.000 0.000 poll block of FlatFish::Actions::Navigation::SinusoidalMovement:0x7f5aef553420<id:6243>():end
755.929 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):start
755.930 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosX:0x7f5aec0e0ff8<id:6367>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.5613446366334031, orocos_name: sinusoid_signal_world_pos_x):end
755.930 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):start
755.931 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosY:0x7f5aee693b38<id:6368>(amplitude: 2, conf: ["default"], frequency: 0.2, offset: -2.2394328715524163, orocos_name: sinusoid_signal_world_pos_y):end
755.931 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):start
755.932 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosZ:0x7f5aef3c55b8<id:6369>(amplitude: 0, conf: ["default"], frequency: 0, offset: -3.066761269564217, orocos_name: sinusoid_signal_world_pos_z):end
755.932 0.000 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):start
755.932 0.001 0.001 poll block for Dive::Compositions::SinusoidSignalGenerators::WorldPosYaw:0x7f5aeeb0aa40<id:6373>(amplitude: 0, conf: ["default"], frequency: 0, offset: 0.006001968664297033, orocos_name: sinusoid_signal_world_pos_yaw):end
755.932 0.000 external_events
755.933 0.001 scheduler
755.933 0.000 poll_state_events:start
755.933 0.000 0.000 poll_state_events:end
755.933 0.000 propagation_handlers
755.933 0.000 event_propagation_phase:start
755.935 0.002 scheduler
755.935 0.000 poll_state_events:start
755.935 0.000 0.000 poll_state_events:end
755.935 0.000 syskit:connection_management_update:start
755.936 0.001 0.001 syskit:connection_management_update:end
755.936 0.000 syskit:apply_requirement_modifications:start
755.937 0.000 0.000 syskit:apply_requirement_modifications:end
755.937 0.000 0.003 event_propagation_phase:end
755.937 0.000 error_handling_phase:start
755.937 0.000 structure_check
755.937 0.000 exception_propagation
755.938 0.001 0.001 error_handling_phase:end
755.943 0.005 garbage_collect
755.943 0.000 0.036 process_events:end
756.000 0.057 sleep
756.000 0.000 at_cycle_end:start
756.002 0.001 0.001 at_cycle_end:end
756.002 0.000 0.095 cycle:end
The durations do not take into account time spent in other threads. So, if the execution spends 2.5s in another thread between the cycle:start and cycle:end event, the duration will include these 2.5s in the main thread as well. That's what I believe happened (from the timepoint_* events in the first log).
One great way to visualize the timepoint log is to convert it to CTF and then read it with trace compass (http://tracecompass.org/)
The conversion is done with roby-log timepoints -ctf /path/to/log
. This creates two things:
Load the directory in trace compass by right-clicking on the Traces in the project explorer and then Right Click -> Open Trace.
If you look at the Call Stack view (at the bottom), you'll see that the names are dumb (0x1, ...). This is what the name file is for. The second button in the call stack view's toolbar will allow you to "select a mapping file" (select the .names file). The names will be resolved, and you'll be able to see how the different processes overlay each other.
I use a composition to generate input commands for the auv_control. It happens that the auv_control was expecting to receive
cmd_in
(provide byDive::Compositions::SinusoidSignalGenerators::WorldPos
) with at least 1s.It happens that sometimes, the poll block of the compositions are called with a ~2s interval (16:28:51, 16:28:53, 16:28:55). Just increasing the timeout would fix the problem, but I'd like to understand what Syskit is doing in the meantime. Is there a way to guarantee the periodicity of a composition's poll?
Here is the data provided by
roby-log decode live-events.log