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)
rospy.loginfo(hello_str)
rate.sleep()
if __name__ == '__main__':
try:
talker()
except rospy.ROSInterruptException:
pass
Thanks in advance, Val
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.
If this is running on the same machine then seeing the code would indeed be helpful.
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.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.
The wiki page you link shows you how to publish
string
s, not timestamps. Can we assume you arestr(ts)
on the sender side? Any particular reason you're not just using the msg.header.stamp field?Could you please just add the sender side of your code as well?
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.)
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.