{"action":"created","issue":{"url":"https://api.github.com/repos/ros/ros_comm/issues/1362","repository_url":"https://api.github.com/repos/ros/ros_comm","labels_url":"https://api.github.com/repos/ros/ros_comm/issues/1362/labels{/name}","comments_url":"https://api.github.com/repos/ros/ros_comm/issues/1362/comments","events_url":"https://api.github.com/repos/ros/ros_comm/issues/1362/events","html_url":"https://github.com/ros/ros_comm/issues/1362","id":312664871,"number":1362,"title":"Message Size-dependent Queueing/Latency","user":{"login":"shomin","id":156187,"avatar_url":"https://avatars0.githubusercontent.com/u/156187?v=4","gravatar_id":"","url":"https://api.github.com/users/shomin","html_url":"https://github.com/shomin","followers_url":"https://api.github.com/users/shomin/followers","following_url":"https://api.github.com/users/shomin/following{/other_user}","gists_url":"https://api.github.com/users/shomin/gists{/gist_id}","starred_url":"https://api.github.com/users/shomin/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/shomin/subscriptions","organizations_url":"https://api.github.com/users/shomin/orgs","repos_url":"https://api.github.com/users/shomin/repos","events_url":"https://api.github.com/users/shomin/events{/privacy}","received_events_url":"https://api.github.com/users/shomin/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2018-04-09T19:55:50Z","updated_at":"2018-04-10T13:30:35Z","closed_at":null,"author_association":"NONE","body":"Originally posted this on ROS answers, but this appears to be a ros_comm bug\r\nhttps://answers.ros.org/question/287292/message-size-dependent-queueinglatency/\r\n\r\nI've noticed some delays up to 1/(publish_frequency) for medium sized messages.  I've reproduced the behavior just using rostopic below:\r\n\r\n    rostopic pub -r 50 /test std_msgs/String \"data: '`printf \"%0.s-\" {1..100}`'\"\r\n    rostopic hz -w 50 /test\r\n\r\n    average rate: 49.983\r\n    \tmin: 0.018s max: 0.022s std dev: 0.00043s window: 50\r\n\r\nNote the printf command just makes the data 100 hyphens.  Pretty normal, what you might expect. Now how about 1000 bytes of hyphens:\r\n\r\n    rostopic pub -r 50 /test std_msgs/String \"data: '`printf \"%0.s-\" {1..1000}`'\"\r\n\r\n    average rate: 50.033\r\n    \tmin: 0.019s max: 0.020s std dev: 0.00018s window: 50\r\n    average rate: 49.994\r\n    \tmin: 0.019s max: 0.021s std dev: 0.00019s window: 50\r\n    average rate: 49.990\r\n    \tmin: 0.019s max: 0.021s std dev: 0.00021s window: 50\r\n    average rate: 49.973\r\n    \tmin: 0.019s max: 0.021s std dev: 0.00021s window: 50\r\n    average rate: 49.027\r\n    \tmin: 0.000s max: 0.040s std dev: 0.01368s window: 50\r\n    average rate: 51.041\r\n    \tmin: 0.000s max: 0.041s std dev: 0.01996s window: 50\r\n    average rate: 51.035\r\n    \tmin: 0.000s max: 0.044s std dev: 0.01963s window: 50\r\n\r\nNotice that after about 3 seconds, we see a min of 0 seconds and a max of .04 seconds. Introspecting, after this starts to happen, it continues happens very consistency (every other message is queued). \r\n\r\nNow for the extra weirdness, this doesn't seem to happen with big messages.  100,000 bytes of hyphens:\r\n\r\n    rostopic pub -r 50 /test std_msgs/String \"data: '`printf \"%0.s-\" {1..100000}`'\"\r\n    \r\n    average rate: 50.037\r\n    \tmin: 0.019s max: 0.020s std dev: 0.00020s window: 50\r\n    average rate: 49.994\r\n    \tmin: 0.019s max: 0.021s std dev: 0.00027s window: 50\r\n    average rate: 49.979\r\n    \tmin: 0.019s max: 0.021s std dev: 0.00020s window: 50\r\n    average rate: 50.020\r\n    \tmin: 0.018s max: 0.022s std dev: 0.00042s window: 50\r\n    average rate: 49.995\r\n    \tmin: 0.019s max: 0.021s std dev: 0.00020s window: 50\r\n    average rate: 50.007\r\n    \tmin: 0.019s max: 0.021s std dev: 0.00017s window: 50\r\n\r\nSo, no problem for large messages!  At 50 Hz, the size of message that seems to do this is EXACTLY 516 bytes to 65475 bytes of data.  Try this out:\r\n\r\n    rostopic pub -r 50 /test std_msgs/String \"data: '`printf \"%0.s-\" {1..515}`'\"\r\n\r\n^ No problem\r\n\r\n    rostopic pub -r 50 /test std_msgs/String \"data: '`printf \"%0.s-\" {1..516}`'\"\r\n\r\n^ Problem!\r\n\r\n    rostopic pub -r 50 /test std_msgs/String \"data: '`printf \"%0.s-\" {1..65475}`'\"\r\n\r\n^ No problem\r\n\r\n    rostopic pub -r 50 /test std_msgs/String \"data: '`printf \"%0.s-\" {1..65574}`'\"\r\n\r\n^ Problem!\r\n\r\nUnfortunately for my use case, I can't just make all my messages bigger (or smaller).  Introspecting in the specific use case, it seems like queueing in that there will be a miss and then 2 messages the next expected cycle.  However, after it starts, this continues to happen with regularity, unless the messages are bigger or smaller.  Any idea why this is happening?\r\n\r\nI've reproduced in roscpp and rospy, with and without tcdnodelay, zero queues, and sychonous publishing (queu_size=None).  It always exhibits this same behavior.  I've also tried this in the indigo-ros-core docker container as well as the lunar-ros-core docker container.  Lastly, I've also adjusted process priority, which also has no effect. Obviously, this is all on one machine as well, no network issues here."},"comment":{"url":"https://api.github.com/repos/ros/ros_comm/issues/comments/380098585","html_url":"https://github.com/ros/ros_comm/issues/1362#issuecomment-380098585","issue_url":"https://api.github.com/repos/ros/ros_comm/issues/1362","id":380098585,"user":{"login":"scott-eddy","id":5719830,"avatar_url":"https://avatars1.githubusercontent.com/u/5719830?v=4","gravatar_id":"","url":"https://api.github.com/users/scott-eddy","html_url":"https://github.com/scott-eddy","followers_url":"https://api.github.com/users/scott-eddy/followers","following_url":"https://api.github.com/users/scott-eddy/following{/other_user}","gists_url":"https://api.github.com/users/scott-eddy/gists{/gist_id}","starred_url":"https://api.github.com/users/scott-eddy/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/scott-eddy/subscriptions","organizations_url":"https://api.github.com/users/scott-eddy/orgs","repos_url":"https://api.github.com/users/scott-eddy/repos","events_url":"https://api.github.com/users/scott-eddy/events{/privacy}","received_events_url":"https://api.github.com/users/scott-eddy/received_events","type":"User","site_admin":false},"created_at":"2018-04-10T13:30:35Z","updated_at":"2018-04-10T13:30:35Z","author_association":"NONE","body":"Note that is is an issue with [Nagle's algorithm](https://en.wikipedia.org/wiki/Nagle%27s_algorithm) on the Linux TCP stack which is used by default between ROS publisher's and subscribers.  If you create a minimal Publisher/Subscriber node specifying [ros::TransportHints::tcpNoDelay()](http://docs.ros.org/kinetic/api/roscpp/html/classros_1_1TransportHints.html#a03191a9987162fca0ae2c81fa79fcde9) you will see that the queueing stops.  \r\n\r\nI've never tried turning off the algorithm globally on a system [but it would appear possible](https://stackoverflow.com/questions/17842406/how-would-one-disable-nagles-algorithm-in-linux)"}}
{"actor":{"display_login":"scott-eddy"}}