Laser scan (ray sensor) updates erratic and slower than desired

Issue #20 closed
John Hsu created an issue

can be anywhere from 10 to 50% slower than expected (see [[http://answers.ros.org/question/43960/publishing-rate-of-gazebo-sensor-plugins-broken-on-fuerte/ | this thread]]). This is probably because SensorManger::Update() calls image sensor updates and ray sensor updates serially. Image rendering is dictated by GPU transport rates, so it's a good idea to split the two up into separate threads.

Comments (22)

  1. Stefan Kohlbrecher

    Are there news on this issue? This IMHO definitely is no minor issue and apparently affects simulation quality for every user simulating LIDARs. I causes a slower than intended update rate that is hard to notice if not explicitly looked for and that will break or silently degrade performance of systems relying on the requested update rate. This issue is also the single reason why we are still stuck with electric, as sensor simulation in fuerte can be considered broken unless this is fixed.

  2. Thomas Koletschka

    It's not as bad as Fuerte anymore but I still only get 32.5Hz instead of 40 on the drc robot.

  3. Nate Koenig

    I believe that you are looking at the wrong information.

    rostopic reports a Hz rate according to the wall clock time that a message is received. Gazebo on the other hand generates sensor data based on simulation time, which can be much slower than real time.

    The best way to measure hz rate for a laser or camera message is to look at the time stamp associated with the message. The can be done with:

    gztopic view <laser_or_camera_topic>

    Note that the above command will only work with Gazebo 1.4+.

    As a test, I create a world with 4 cameras, 1 PR2, and an additional hokuyo. The total topics include 14 cameras streams, 3 laser streams, 7 contact streams, and more. I subscribe to them all, and they all produce data at the specified Hz rate - according to simulation time.

    We are working on making Gazebo run faster. However, right now we have to simulate a physical world, simulate sensor data, and (optionally) run ROS on a single PC.

  4. Stefan Kohlbrecher

    No, "rostopic hz" apparently does not use wall time. If I simulate atlas without stereo_image_proc I get about 0.5x realtime and:

    kohlbrecher@opstation:~$ rostopic hz scan
    subscribed to [/scan]
    average rate: 33.113
        min: 0.025s max: 0.050s std dev: 0.00991s window: 16
    average rate: 34.411
        min: 0.024s max: 0.050s std dev: 0.00879s window: 34
    average rate: 33.380
        min: 0.024s max: 0.051s std dev: 0.00970s window: 49
    

    Switching on stereo_image_proc I get about 0.27x realtime and

    kohlbrecher@opstation:~$ rostopic hz scan
    subscribed to [/scan]
    average rate: 28.037
        min: 0.025s max: 0.055s std dev: 0.01209s window: 7
    average rate: 27.197
        min: 0.025s max: 0.055s std dev: 0.01042s window: 14
    average rate: 29.494
        min: 0.024s max: 0.055s std dev: 0.00949s window: 22
    average rate: 27.455
    

    So let's agree that rostopic uses "some time" ;) for estimating the frequency, it might not be sim time, it most certainly also is not wall time.

    To get a valid sim time measurement I switched to rosbag, recording data and then putting out the frequency of scan messages. Without subscribing to point cloud data I get 40Hz, which is good:

    kohlbrecher@opstation:~/tmp$ rosbag info --freq no_pc.bag 
    path:        no_pc.bag
    version:     2.0
    duration:    11.3s
    start:       Jan 01 1970 01:07:55.08 (475.08)
    end:         Jan 01 1970 01:08:06.34 (486.34)
    size:        2.1 MB
    messages:    377
    compression: none [3/3 chunks]
    types:       sensor_msgs/LaserScan [90c7ef2dc6895d81024acba2ac42f369]
    topics:      scan   377 msgs @ 40.0 Hz : sensor_msgs/LaserScan
    

    Subscribing to point cloud data before recording, I get 32Hz:

    kohlbrecher@opstation:~/tmp$ rosbag info --freq with_pc.bag 
    path:        with_pc.bag
    version:     2.0
    duration:    10.4s
    start:       Jan 01 1970 01:08:15.70 (495.70)
    end:         Jan 01 1970 01:08:26.15 (506.15)
    size:        1.7 MB
    messages:    305
    compression: none [3/3 chunks]
    types:       sensor_msgs/LaserScan [90c7ef2dc6895d81024acba2ac42f369]
    topics:      scan   305 msgs @ 32.3 Hz : sensor_msgs/LaserScan
    

    Will do a fuerte test later.

  5. Stefan Kohlbrecher

    Fuerte (same scenario as described in OP here: http://answers.gazebosim.org/question/890/laser-scanner-update-rate-on-fuerte-completely/ )

    Again, update rate for LIDAR plugin s set to 40 Hz.

    Without image or pointcloud subscription:

    kohlbrecher@opstation:~/tmp$ rosbag info --freq hlugv_laser_only.bag 
    path:        hlugv_laser_only.bag
    version:     2.0
    duration:    37.5s
    start:       Jan 01 1970 01:02:32.52 (152.52)
    end:         Jan 01 1970 01:03:10.00 (190.00)
    size:        9.2 MB
    messages:    1100
    compression: none [13/13 chunks]
    types:       sensor_msgs/LaserScan [90c7ef2dc6895d81024acba2ac42f369]
    topics:      scan   1100 msgs @ 31.2 Hz : sensor_msgs/LaserScan
    

    Subscribing to camera images:

    kohlbrecher@opstation:~/tmp$ rosbag info --freq hlugv_image.bag 
    path:        hlugv_image.bag
    version:     2.0
    duration:    57.4s
    start:       Jan 01 1970 01:03:48.39 (228.39)
    end:         Jan 01 1970 01:04:45.76 (285.76)
    size:        8.6 MB
    messages:    1030
    compression: none [12/12 chunks]
    types:       sensor_msgs/LaserScan [90c7ef2dc6895d81024acba2ac42f369]
    topics:      scan   1030 msgs @ 20.4 Hz : sensor_msgs/LaserScan
    

    Subscribing to both camera images and point clouds:

    kohlbrecher@opstation:~/tmp$ rosbag info --freq hlugv_image_pc.bag 
    path:        hlugv_image_pc.bag
    version:     2.0
    duration:    1:32s (92s)
    start:       Jan 01 1970 01:05:36.87 (336.87)
    end:         Jan 01 1970 01:07:09.17 (429.17)
    size:        9.8 MB
    messages:    1176
    compression: none [14/14 chunks]
    types:       sensor_msgs/LaserScan [90c7ef2dc6895d81024acba2ac42f369]
    topics:      scan   1176 msgs @ 18.5 Hz : sensor_msgs/LaserScan
    

    I think we can agree that this looks broken, and to me this definitely is not a minor issue, because our USAR robots worked flawless in simulation in electric and stopped doing that in fuerte because of this. My question is if this will be fixed on fuerte, or if we should skip to groovy. I know you guys have a lot of things to do and everything you do really is much appreciated. But we have to decide on which ROS/Gazebo version to use for some projects, so a comment on the treatment of this issue in fuerte would be great.

  6. Nate Koenig

    My results from running Atlas:

    head_hokuyo_sensor: ~40Hz ( fluctates from ~37 to 41 hz)

    left_camera_sensor: ~14Hz (it can fluctuate from 13-17)

    I will try more to reproduce your results. right_camera_sensor: ~14Hz (it can fluctuate from 13-17)

  7. Stefan Kohlbrecher

    Ok, to get more reproducibility: I'm on a Ubuntu 12.04 AMD64 machine, Core I5 (i5-2430M CPU @ 2.40GHz, Nvidia GeForce GT 540M). ROS Fuerte/Gazebo/drcsim installed from (their respective) .debs.

    How I tested:

    Started Atlas:

    roslaunch atlas_utils atlas.launch
    

    New terminal, start a subscriber for scans (so recording via bagfile doesn't incur recording start overhead/delay when no scans have been subscribed before):

    rostopic hz scan
    

    Record a bagfile of 1000 scans:

    rosbag record --l 1000 scan
    

    Optionally in new terminal, to increase load and also start up image publishers:

    rostopic hz /multisense_sl/points2
    

    Then, again record bag file:

    rosbag record --l 1000 scan
    

    On my machine I then get the following using the 'info --freq' bagfile option:

    Only scan subscribed:

    kohlbrecher@opstation:~/tmp$ rosbag info --freq atlas_scan_only.bag 
    path:        atlas_scan_only.bag
    version:     2.0
    duration:    28.6s
    start:       Jan 01 1970 01:05:49.36 (349.36)
    end:         Jan 01 1970 01:06:17.00 (378.00)
    size:        5.6 MB
    messages:    1000
    compression: none [8/8 chunks]
    types:       sensor_msgs/LaserScan [90c7ef2dc6895d81024acba2ac42f369]
    topics:      scan   1000 msgs @ 38.5 Hz : sensor_msgs/LaserScan
    

    Also subscribing to pointcloud data:

    kohlbrecher@opstation:~/tmp$ rosbag info --freq atlas_scan_pc2_subscribed.bag 
    path:        atlas_scan_pc2_subscribed.bag
    version:     2.0
    duration:    35.4s
    start:       Jan 01 1970 01:07:34.03 (454.03)
    end:         Jan 01 1970 01:08:09.41 (489.41)
    size:        5.6 MB
    messages:    1000
    compression: none [8/8 chunks]
    types:       sensor_msgs/LaserScan [90c7ef2dc6895d81024acba2ac42f369]
    topics:      scan   1000 msgs @ 30.3 Hz : sensor_msgs/LaserScan
    

    I also recorded versions of both tests with both /scan and /clock. Interestingly, the frequency numbers exactly match those of the same test without clock data, suggesting that jitter doesn't play an important role.

    kohlbrecher@opstation:~/tmp$ rosbag info --freq atlas_scan_clock_only.bag 
    path:        atlas_scan_clock_only.bag
    version:     2.0
    duration:    28.8s
    start:       Jan 01 1970 01:06:37.09 (397.09)
    end:         Jan 01 1970 01:07:05.92 (425.92)
    size:        5.7 MB
    messages:    2000
    compression: none [8/8 chunks]
    types:       rosgraph_msgs/Clock   [a9c97c1d230cfc112e270351a944ee47]
                 sensor_msgs/LaserScan [90c7ef2dc6895d81024acba2ac42f369]
    topics:      clock   1000 msgs @ 1.0 kHz : rosgraph_msgs/Clock  
                 scan    1000 msgs @ 38.5 Hz : sensor_msgs/LaserScan
    
    kohlbrecher@opstation:~/tmp$ rosbag info --freq atlas_scan_clock_pc2_subscribed.bag 
    path:        atlas_scan_clock_pc2_subscribed.bag
    version:     2.0
    duration:    35.1s
    start:       Jan 01 1970 01:08:17.34 (497.34)
    end:         Jan 01 1970 01:08:52.48 (532.48)
    size:        5.7 MB
    messages:    2000
    compression: none [8/8 chunks]
    types:       rosgraph_msgs/Clock   [a9c97c1d230cfc112e270351a944ee47]
                 sensor_msgs/LaserScan [90c7ef2dc6895d81024acba2ac42f369]
    topics:      clock   1000 msgs @ 1.0 kHz : rosgraph_msgs/Clock  
                 scan    1000 msgs @ 30.3 Hz : sensor_msgs/LaserScan
    

    /edit: Ok, recording only 1000 clock messages is probably making only limited sense ;) Still serves to show that the frequency is reproducible.

  8. Nate Koenig

    Update:

    1) Timing information from rostopic has nothing to do with sensor generation from Gazebo. rostopic report the time at which a message is received by rostopic. This is not the time when the message was produced, and it's not the time when a sensor generated data. Therefore, data from rostopic should not be used as measurement tool for simulation sensor performance.

    2) The correct way to measure sensor performance is to use gztopic view <topic_name>. This will report the time at which sensor data has actually been generated.

    3) A little research by John and Brian found that switching ROS to use UDP produces better performance when delivering messages. This change has been incorporated in to DRC 2.0.

    4) It was referenced that the version of Gazebo released in ROS Electric had correct update rates. This is not true. The Gazebo ROS plugin was sending out data at the correct Hz rate, but the data was copied from the last update of the sensor. So nodes would receive duplicate data. No complaints were voiced about this.

    The above reasons are why this issue was marked as minor.

    pull request #277 has incorporated threaded sensors. I have now been able to run Atlas at 1.40x real-time with all sensors producing correct Hz rate. In fact I was getting the correct Hz rate prior to this pull-request, but now Gazebo runs a bit faster.

  9. Johannes Meyer

    Regarding 1)

    rostopic uses the time published on the /clock topic by the gazebo_ros_api plugin in the gazebo ROS package. So the rates displayed in rostopic hz should always correspond to the intended publishing rates, no matter at which update rate Gazebo is running.

    When throttling Gazebo (version 1.3) to 0.1x real-time, rostopic hz and gztopic view still displays the correct rate of 40.0 Hz for the laser (using simulated time), while gztopic hz falls back to 4 Hz. This is what I would expect. Running in real-time, rostopic hz decreases to approximately 37 Hz on my machine, which might be caused by message loss in the ROS publisher/subscriber pipeline on high CPU loads.

    Let's see if the threaded sensor implementation brings some improvements here. In general, I would expect that the update rate decreases if the computing resources are exhausted, but the publishing rates measured in simulated time should not degrade.

  10. Nate Koenig

    rostopic hz will correspond to publishing rates of the ROS publisher. This is not tied to Gazebo. As such, rostopic hz cannot be used as a measurement tool.

  11. Thomas Koletschka

    rostopic hz gives the framerate that the robot will receive though ... as such it is a better measurement tool than gazebo tools that measure the frequency within gazebo ... unless you allow us to write everything as gazebo plugin to make use of gazebo's internal framerates.

  12. Nate Koenig

    There are two issues here. The first is the rate at which Gazebo generates data, the second is the rate at which that data is sent out over ROS. I was under the impression that this thread was about the first, and not the second.

    Here is the document that will list the rates at which ROS topics operate: http://gazebosim.org/wiki/DRC/UserGuide#ROS_APIs

    Concerns about those TBD rates should be posted on the DRC Sim issue tracker.

  13. Log in to comment