ROS Resources: Documentation | Support | Discussion Forum | Index | Service Status | Q&A answers.ros.org

# Receiving before sending???

I am a ROS noobie, so bare with me.

I've just implemented the "talker.py" and "listener.py" example in the very helpful ROS tutorial pages.

Out of curiosity, I modified my listener.py such that it calls rospy.get_time() as the first step of the callback() function. Then it calculates the difference between this timestamp and the one sent by the talker (now - received time) as a rudimentary way to estimate the time-lag of sending/receiving a message. I then log both this instantaneous difference, the average of the last 100 such measurements and their standard deviation.

Here is a snippet of the resulting output:

[INFO] [WallTime: 1455490866.482270] /listener_10101_1455490785467Time diff: 0.00205, avg(100): 0.00116 +/- 0.00029
[INFO] [WallTime: 1455490866.581423] /listener_10101_1455490785467Time diff: 0.00113, avg(100): 0.00116 +/- 0.00029
[INFO] [WallTime: 1455490866.681358] /listener_10101_1455490785467Time diff: 0.00111, avg(100): 0.00116 +/- 0.00029
[INFO] [WallTime: 1455490866.781439] /listener_10101_1455490785467Time diff: 0.00117, avg(100): 0.00116 +/- 0.00029
[INFO] [WallTime: 1455490866.881240] /listener_10101_1455490785467Time diff: 0.00104, avg(100): 0.00116 +/- 0.00029
[INFO] [WallTime: 1455490866.981350] /listener_10101_1455490785467Time diff: 0.00102, avg(100): 0.00116 +/- 0.00029


I've found that over time the values are occasionally < 0 (see the transition in the second line below), indicating the the time stamp on receipt of the message is BEFORE the time stamp sent by the talker. That is the message is received before it was sent!!! (What???)

[INFO] [WallTime: 1455490892.081103] /listener_10101_1455490785467Time diff: 0.00089, avg(100): 0.00105 +/- 0.00015
[INFO] [WallTime: 1455490892.181117] /listener_10101_1455490785467Time diff: 0.00091, avg(100): 0.00105 +/- 0.00015
[INFO] [WallTime: 1455490898.958321] /listener_10101_1455490785467Time diff: -0.00189, avg(100): 0.00102 +/- 0.00033
[INFO] [WallTime: 1455490898.959107] /listener_10101_1455490785467Time diff: -0.00100, avg(100): 0.00100 +/- 0.00039
[INFO] [WallTime: 1455490892.376509] /listener_10101_1455490785467Time diff: -0.00369, avg(100): 0.00096 +/- 0.00061
[INFO] [WallTime: 1455490892.477625] /listener_10101_1455490785467Time diff: -0.00259, avg(100): 0.00092 +/- 0.00070


I would be thrilled if anyone could help me understand either what conceptual error I am making here or how this is possible?

EDIT: Here is the important part of the code (the callback() function). (sorry for the mess in the comments below)

import numpy as np

valuelist = []

def callback(data, vals = valuelist):
now = rospy.get_time()
sentval = data.data.split()
dt = now - float(sentval[2])
if vals.__len__() < 100:
vals.insert(0,dt)
else:
vals.pop()
vals.insert(0,dt)

valsnp = np.array(vals)
rospy.loginfo(rospy.get_caller_id() + 'Time diff: %0.5f, avg(%3d): %0.5f +/- %0.5f ' % (dt, valsnp.size, valsnp.mean(),valsnp.std()) )


EDIT2: The talker code (talker.py)

import rospy
from std_msgs.msg import String

def talker():
pub = rospy.Publisher('chatter', String, queue_size=10)
rospy.init_node('talker', anonymous=True)
rate = rospy.Rate(10) # 10hz
while not rospy.is_shutdown():
hello_str = "hello world %s" % rospy.get_time()
pub.publish(hello_str)
rate.sleep()

if __name__ == '__main__':
try:
talker()
except rospy.ROSInterruptException:
pass


edit retag close merge delete

2

Are the talker and listener running on the same computer? Sometimes you'll see time travel if the clock on the sender is ahead of the clock on the receiver.

( 2016-02-14 20:04:16 -0600 )edit

I'm happy to post the code if that's helpful.

If this is running on the same machine then seeing the code would indeed be helpful.

( 2016-02-15 04:00:53 -0600 )edit

How is your talker formatting and sending timestamps? It looks like you're doing something complicated with timestamps instead of simply using the stamp field in the message header.

( 2016-02-15 16:00:52 -0600 )edit

It's exactly (indeed the same file) as in the tutorial here: http://wiki.ros.org/ROS/Tutorials/Wri...

Maybe I should add, although I don't think it should matter, is that this is all running on a virtual machine.

( 2016-02-16 18:14:56 -0600 )edit

The wiki page you link shows you how to publish strings, not timestamps. Can we assume you are str(ts) on the sender side? Any particular reason you're not just using the msg.header.stamp field?

( 2016-02-17 02:04:15 -0600 )edit

( 2016-02-17 02:04:41 -0600 )edit

I've added the talker code. I'm not using the msg.header.stamp field simply because the tutorial didn't. (The tutorial hasn't discussed the header msg yet.)

( 2016-02-17 06:08:11 -0600 )edit

Thank you. I suspect there is some rounding going on, which sometimes makes the received ts being floored, sometimes ceiled, resulting in minute 'jumps' in the deltas.

( 2016-02-17 06:10:26 -0600 )edit

Sort by ยป oldest newest most voted

You are right and you beat me to it. This call

rospy.get_time()


only produces time to two decimal places and it seems to be rounding that value. So when the fractional second is say 0.006, this gets reported as 0.01. So the logger can timestamp before 0.01 actually occurs.

Thanks for your help with this!!!

more

Just for the record: rospy.get_time() just returns a float value. The nr decimals is not limited to 2, that really depends on the formatting string used to print it. Calling that function in a Python session in a terminal gets me this fi: 1455714769.854213.

( 2016-02-17 07:14:45 -0600 )edit

You can probably do what you want, by using something like %.8f instead of %s where you assign your string to hello_str.

( 2016-02-17 07:16:13 -0600 )edit

Ah. thanks!

( 2016-02-17 07:38:15 -0600 )edit

I _strongly_ recommending using the ROS time type (or the stamp field in the header, if your message has a header) for transferring times between nodes, instead of trying to convert times to strings and back. Any conversion of a time to a string will lose precision and semantics.

( 2016-02-17 11:47:08 -0600 )edit

I'm obviously not recommending to start publishing / handling / using timestamps in messages in this way. I was merely trying to explain what was happening, and that there is a way to get Python to stringify a float with more decimals than the 2 observed by @vschmidt.

( 2016-02-17 13:04:40 -0600 )edit