{"action":"created","issue":{"url":"https://api.github.com/repos/jsk-ros-pkg/jsk_roseus/issues/396","labels_url":"https://api.github.com/repos/jsk-ros-pkg/jsk_roseus/issues/396/labels{/name}","comments_url":"https://api.github.com/repos/jsk-ros-pkg/jsk_roseus/issues/396/comments","events_url":"https://api.github.com/repos/jsk-ros-pkg/jsk_roseus/issues/396/events","html_url":"https://github.com/jsk-ros-pkg/jsk_roseus/issues/396","id":116101179,"number":396,"title":"ros::spin-onceの処理時間が長い","user":{"login":"h-kamada","id":7262021,"avatar_url":"https://avatars.githubusercontent.com/u/7262021?v=3","gravatar_id":"","url":"https://api.github.com/users/h-kamada","html_url":"https://github.com/h-kamada","followers_url":"https://api.github.com/users/h-kamada/followers","following_url":"https://api.github.com/users/h-kamada/following{/other_user}","gists_url":"https://api.github.com/users/h-kamada/gists{/gist_id}","starred_url":"https://api.github.com/users/h-kamada/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/h-kamada/subscriptions","organizations_url":"https://api.github.com/users/h-kamada/orgs","repos_url":"https://api.github.com/users/h-kamada/repos","events_url":"https://api.github.com/users/h-kamada/events{/privacy}","received_events_url":"https://api.github.com/users/h-kamada/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":6,"created_at":"2015-11-10T12:54:40Z","updated_at":"2015-11-11T04:57:13Z","closed_at":null,"body":"#### `ros::spin-once` の処理時間が時間の経過につれて長くなる\r\n* jsk-ros-pkg/jsk_demos#1107 で問題となる\r\n\r\n時間が経過とともに溜め込んでいるデータが増えるため、徐々に`ros::spin-once`にかかる時間が長くなる。\r\n特に高負荷な処理を行っている際には、これが溜まると一度の`ros::spin-once`に2s ~ 4s程度の時間がかかるようになってしまうため、`ros::spin-once`で読み込むデータを制限するなど、何らかの対処が必要。\r\n\r\n##### PR2体内\r\n冷蔵庫デモで立ち上げるlaunch(`detect_cans_in_fridge_201202/launch/startup.launch`)と、\r\njsk-ros-pkg/jsk_demos#1107 で用いる`fridge_demo.launch`を立ち上げた状態で\r\nc1 load average        7.16     　　　8.67    　　　 9.37\r\nc2 load average        23.96 　 　 22.34 　　  21.25\r\n\r\nこの状態でpr2-interfaceのinstanceを作成、一度`ros::spin-once`した後10s後に再び`ros::spin-once`を行い（実際には`(send *ri* :state)`を呼んだ)、2度目の`ros::spin-once`にかかる時間を計測。(8回くらい)\r\n以下に示すようにcontroller actionのデータが支配的。\r\n\r\n何もsubscribeしないpr2-interface\r\n0.000484   0.00066    0.000555    0.001829\r\n0.00043     0.000524  0.000489    0.002214\r\n--> 0.0008983s程度\r\n\r\n通常のpr2-interface\r\n````\r\nSubscriptions:\r\n * /head_traj_controller/follow_joint_trajectory/result [control_msgs/FollowJointTrajectoryActionResult]\r\n * /l_arm_controller/follow_joint_trajectory/feedback [control_msgs/FollowJointTrajectoryActionFeedback]\r\n * /tf_static [unknown type]\r\n * /head_traj_controller/state [pr2_controllers_msgs/JointTrajectoryControllerState]\r\n * /tf [tf2_msgs/TFMessage]\r\n * /r_arm_controller/follow_joint_trajectory/result [control_msgs/FollowJointTrajectoryActionResult]\r\n * /l_gripper_controller/gripper_action/feedback [pr2_controllers_msgs/Pr2GripperCommandActionFeedback]\r\n * /r_gripper_controller/gripper_action/status [actionlib_msgs/GoalStatusArray]\r\n * /joint_states [sensor_msgs/JointState]\r\n * /base_controller/joint_trajectory_action/result [pr2_controllers_msgs/JointTrajectoryActionResult]\r\n * /pressure/r_gripper_motor [pr2_msgs/PressureState]\r\n * /r_arm_controller/state [pr2_controllers_msgs/JointTrajectoryControllerState]\r\n * /l_gripper_controller/gripper_action/status [actionlib_msgs/GoalStatusArray]\r\n * /move_base/feedback [move_base_msgs/MoveBaseActionFeedback]\r\n * /head_traj_controller/follow_joint_trajectory/status [actionlib_msgs/GoalStatusArray]\r\n * /r_arm_controller/follow_joint_trajectory/status [actionlib_msgs/GoalStatusArray]\r\n * /r_gripper_controller/gripper_action/result [pr2_controllers_msgs/Pr2GripperCommandActionResult]\r\n * /l_arm_controller/follow_joint_trajectory/status [actionlib_msgs/GoalStatusArray]\r\n * /move_base/status [actionlib_msgs/GoalStatusArray]\r\n * /r_gripper_controller/gripper_action/feedback [pr2_controllers_msgs/Pr2GripperCommandActionFeedback]\r\n * /move_base/result [move_base_msgs/MoveBaseActionResult]\r\n * /head_traj_controller/follow_joint_trajectory/feedback [control_msgs/FollowJointTrajectoryActionFeedback]\r\n * /torso_controller/state [pr2_controllers_msgs/JointTrajectoryControllerState]\r\n * /l_arm_controller/follow_joint_trajectory/result [control_msgs/FollowJointTrajectoryActionResult]\r\n * /l_arm_controller/state [pr2_controllers_msgs/JointTrajectoryControllerState]\r\n * /base_controller/joint_trajectory_action/feedback [pr2_controllers_msgs/JointTrajectoryActionFeedback]\r\n * /torso_controller/follow_joint_trajectory/result [control_msgs/FollowJointTrajectoryActionResult]\r\n * /base_controller/joint_trajectory_action/status [actionlib_msgs/GoalStatusArray]\r\n * /torso_controller/follow_joint_trajectory/feedback [control_msgs/FollowJointTrajectoryActionFeedback]\r\n * /torso_controller/follow_joint_trajectory/status [actionlib_msgs/GoalStatusArray]\r\n * /r_arm_controller/follow_joint_trajectory/feedback [control_msgs/FollowJointTrajectoryActionFeedback]\r\n * /pressure/l_gripper_motor [pr2_msgs/PressureState]\r\n * /base_odometry/odom [nav_msgs/Odometry]\r\n * /l_gripper_controller/gripper_action/result [pr2_controllers_msgs/Pr2GripperCommandActionResult]\r\n````\r\n計測時間\r\n0.06082　0.061493　0.07795　0.117355　0.078446　0.103501　0.080939　0.121987\r\n--> 0.087811s程度\r\n\r\nrarm, larm, head, torsoのcontroller系のみsubscribeしたpr2-interface\r\n````\r\nSubscriptions:\r\n* /head_traj_controller/follow_joint_trajectory/result [control_msgs/FollowJointTrajectoryActionResult]\r\n * /l_arm_controller/follow_joint_trajectory/feedback [control_msgs/FollowJointTrajectoryActionFeedback]\r\n * /head_traj_controller/state [pr2_controllers_msgs/JointTrajectoryControllerState]\r\n * /r_arm_controller/follow_joint_trajectory/result [control_msgs/FollowJointTrajectoryActionResult]\r\n * /r_arm_controller/state [pr2_controllers_msgs/JointTrajectoryControllerState]\r\n * /head_traj_controller/follow_joint_trajectory/status [actionlib_msgs/GoalStatusArray]\r\n * /r_arm_controller/follow_joint_trajectory/status [actionlib_msgs/GoalStatusArray]\r\n * /l_arm_controller/follow_joint_trajectory/status [actionlib_msgs/GoalStatusArray]\r\n * /head_traj_controller/follow_joint_trajectory/feedback [control_msgs/FollowJointTrajectoryActionFeedback]\r\n * /torso_controller/state [pr2_controllers_msgs/JointTrajectoryControllerState]\r\n * /l_arm_controller/follow_joint_trajectory/result [control_msgs/FollowJointTrajectoryActionResult]\r\n * /l_arm_controller/state [pr2_controllers_msgs/JointTrajectoryControllerState]\r\n * /torso_controller/follow_joint_trajectory/result [control_msgs/FollowJointTrajectoryActionResult]\r\n * /torso_controller/follow_joint_trajectory/feedback [control_msgs/FollowJointTrajectoryActionFeedback]\r\n * /torso_controller/follow_joint_trajectory/status [actionlib_msgs/GoalStatusArray]\r\n * /r_arm_controller/follow_joint_trajectory/feedback [control_msgs/FollowJointTrajectoryActionFeedback]\r\n````\r\n0.115325 0.053393 0.047287 0.04078 0.038668 0.090261 0.045294 0.054744\r\n--> 0.060719s程度\r\n\r\nrgripper, lgripper, movebaseaction, movebasetrajactionのcontrollerのみsubscribeするpr2-interface\r\n````\r\nSubscriptions:\r\n * /l_gripper_controller/gripper_action/feedback [pr2_controllers_msgs/Pr2GripperCommandActionFeedback]\r\n * /r_gripper_controller/gripper_action/status [actionlib_msgs/GoalStatusArray]\r\n * /base_controller/joint_trajectory_action/result [pr2_controllers_msgs/JointTrajectoryActionResult]\r\n * /l_gripper_controller/gripper_action/status [actionlib_msgs/GoalStatusArray]\r\n * /move_base/feedback [move_base_msgs/MoveBaseActionFeedback]\r\n * /r_gripper_controller/gripper_action/result [pr2_controllers_msgs/Pr2GripperCommandActionResult]\r\n * /move_base/status [actionlib_msgs/GoalStatusArray]\r\n * /r_gripper_controller/gripper_action/feedback [pr2_controllers_msgs/Pr2GripperCommandActionFeedback]\r\n * /move_base/result [move_base_msgs/MoveBaseActionResult]\r\n * /base_controller/joint_trajectory_action/feedback [pr2_controllers_msgs/JointTrajectoryActionFeedback]\r\n * /base_controller/joint_trajectory_action/status [actionlib_msgs/GoalStatusArray]\r\n * /l_gripper_controller/gripper_action/result [pr2_controllers_msgs/Pr2GripperCommandActionResult]\r\n````\r\n0.032307    0.020242     0.027439\r\n--> 0.026663s程度\r\n\r\njoint_states  のみのpr2-interface　　　\r\n0.004268      0.005096     0.011949     0.005918\r\n0.011486      0.004679     0.013978     0.005114\r\n--> 0.007811s程度\r\n\r\nrl-gripper-pressureのみのpr2-interface\r\n````\r\nSubscriptions:\r\n * /pressure/r_gripper_motor [pr2_msgs/PressureState]\r\n * /pressure/l_gripper_motor [pr2_msgs/PressureState]\r\n````\r\n0.004494    0.001197      0.00128\r\n--> 0.002324s程度\r\n\r\n/base_odometry/odomのみのpr2-interface\r\n0.001578　　0.001852　　0.002352  -->  0.001927s程度\r\n\r\ntf のみのpr2-interface\r\n0.000964     0.00047      0.000912      0.000416\r\n--> 0.00069s程度\r\n\r\n##### 手元PC(参考程度)\r\n`roseus/test/talker.l`からpub(rate 10)される情報をsubscribeし、同様に処理時間を計測\r\n0.000145　0.00011  3.109300e-05  5.467700e-05\r\n--> 8.519250e-05s程度\r\n\r\n\r\n"},"comment":{"url":"https://api.github.com/repos/jsk-ros-pkg/jsk_roseus/issues/comments/155664271","html_url":"https://github.com/jsk-ros-pkg/jsk_roseus/issues/396#issuecomment-155664271","issue_url":"https://api.github.com/repos/jsk-ros-pkg/jsk_roseus/issues/396","id":155664271,"user":{"login":"k-okada","id":493276,"avatar_url":"https://avatars.githubusercontent.com/u/493276?v=3","gravatar_id":"","url":"https://api.github.com/users/k-okada","html_url":"https://github.com/k-okada","followers_url":"https://api.github.com/users/k-okada/followers","following_url":"https://api.github.com/users/k-okada/following{/other_user}","gists_url":"https://api.github.com/users/k-okada/gists{/gist_id}","starred_url":"https://api.github.com/users/k-okada/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/k-okada/subscriptions","organizations_url":"https://api.github.com/users/k-okada/orgs","repos_url":"https://api.github.com/users/k-okada/repos","events_url":"https://api.github.com/users/k-okada/events{/privacy}","received_events_url":"https://api.github.com/users/k-okada/received_events","type":"User","site_admin":false},"created_at":"2015-11-11T04:57:13Z","updated_at":"2015-11-11T04:57:13Z","body":"どれがどれぐらいきいているだろう？\n100hz 60KB の３つをsubscribeしないと使える程度になったりする？\n\n--\n◉ Kei Okada\n\n\nOn Wed, Nov 11, 2015 at 1:55 PM, h-kamada <notifications@github.com> wrote:\n\n> 全体では次のようになります。\n>\n> /l_gripper_controller/gripper_action/status\n> /r_gripper_controller/gripper_action/status\n> 5hz 500B/s\n>\n> /move_base/status\n> /base_controller/joint_trajectory_action/status\n> 5hz 120B/s\n>\n> /head_traj_controller/follow_joint_trajectory/status\n> /l_arm_controller/follow_joint_trajectory/status\n> /r_arm_controller/follow_joint_trajectory/status\n> /torso_controller/follow_joint_trajectory/status\n> 5hz 1.27KB/s\n>\n> /torso_controller/state\n> 100hz 15KB/s\n>\n> /head_traj_controller/state\n> 100hz 22KB/s\n>\n> /tf\n> 200hz 400KB/s\n>\n> /joint_states\n> 100hz 200KB/s\n>\n> /pressure/r_gripper_motor\n> /pressure/l_gripper_motor\n> 24hz 2.7KB/s\n>\n> /r_arm_controller/state\n> /l_arm_controller/state\n> 100hz 66KB/s\n>\n> /base_odometry/odom\n> 100hz 60KB/s\n>\n> —\n> Reply to this email directly or view it on GitHub\n> <https://github.com/jsk-ros-pkg/jsk_roseus/issues/396#issuecomment-155663404>\n> .\n>\n"}}