Ask Your Question
0

Receiving before sending???

asked 2016-02-14 17:09:08 -0500

vschmidt gravatar image

updated 2016-02-17 05:55:17 -0500

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

edit retag flag offensive close merge delete

Comments

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.

ahendrix gravatar image ahendrix  ( 2016-02-14 20:04:16 -0500 )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.

gvdhoorn gravatar image gvdhoorn  ( 2016-02-15 04:00:53 -0500 )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.

ahendrix gravatar image ahendrix  ( 2016-02-15 16:00:52 -0500 )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.

vschmidt gravatar image vschmidt  ( 2016-02-16 18:14:56 -0500 )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?

gvdhoorn gravatar image gvdhoorn  ( 2016-02-17 02:04:15 -0500 )edit

Could you please just add the sender side of your code as well?

gvdhoorn gravatar image gvdhoorn  ( 2016-02-17 02:04:41 -0500 )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.)

vschmidt gravatar image vschmidt  ( 2016-02-17 06:08:11 -0500 )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.

gvdhoorn gravatar image gvdhoorn  ( 2016-02-17 06:10:26 -0500 )edit

1 Answer

Sort by ยป oldest newest most voted
0

answered 2016-02-17 06:16:19 -0500

vschmidt gravatar image

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!!!

edit flag offensive delete link more

Comments

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.

gvdhoorn gravatar image gvdhoorn  ( 2016-02-17 07:14:45 -0500 )edit

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

gvdhoorn gravatar image gvdhoorn  ( 2016-02-17 07:16:13 -0500 )edit

Ah. thanks!

vschmidt gravatar image vschmidt  ( 2016-02-17 07:38:15 -0500 )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.

ahendrix gravatar image ahendrix  ( 2016-02-17 11:47:08 -0500 )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.

gvdhoorn gravatar image gvdhoorn  ( 2016-02-17 13:04:40 -0500 )edit

Your Answer

Please start posting anonymously - your entry will be published after you log in or create a new account.

Add Answer

Question Tools

2 followers

Stats

Asked: 2016-02-14 17:09:08 -0500

Seen: 149 times

Last updated: Feb 17 '16