Laser scan (ray sensor) updates erratic and slower than desired about gazebo-classic

[osrf-migration]

Original comment by John Hsu (Bitbucket: hsu, GitHub: hsu).

---

• set assignee_account_id to "557058:f3968cd3-4910-4384-8349-482a6c7889ec"
• changed assignee from "None (Bitbucket: None)" to "hsu (Bitbucket: hsu, GitHub: hsu)"

[osrf-migration]

Original comment by John Hsu (Bitbucket: hsu, GitHub: hsu).

---

• Edited issue description

[osrf-migration]

Original comment by Nate Koenig (Bitbucket: Nathan Koenig).

---

• changed priority from "major" to "minor"

[osrf-migration]

Original comment by Stefan Kohlbrecher (Bitbucket: 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.

[osrf-migration]

Original comment by John Hsu (Bitbucket: hsu, GitHub: hsu).

---

• changed priority from "minor" to "major"

[osrf-migration]

Original comment by John Hsu (Bitbucket: hsu, GitHub: hsu).

---

• changed assignee_account_id from "557058:f3968cd3-4910-4384-8349-482a6c7889ec" to "557058:095b1e12-74ed-4e20-b44f-2f0745b616e0"
• changed assignee from "hsu (Bitbucket: hsu, GitHub: hsu)" to "nkoenig (Bitbucket: nkoenig, GitHub: nkoenig)"

[osrf-migration]

Original comment by Thomas Koletschka (Bitbucket: thomasko).

---

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

[osrf-migration]

Original comment by Stefan Kohlbrecher (Bitbucket: Stefan_Kohlbrecher).

---

Some measured data along with related questions on answers.gazebosim.

[osrf-migration]

Original comment by Nate Koenig (Bitbucket: Nathan 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.

[osrf-migration]

Original comment by Nate Koenig (Bitbucket: Nathan Koenig).

---

• changed priority from "major" to "minor"

[osrf-migration]

Original comment by Stefan Kohlbrecher (Bitbucket: 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:

#!c++

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

#!c++

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:

#!c++

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:

#!c++

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.

[osrf-migration]

Original comment by Stefan Kohlbrecher (Bitbucket: 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:

#!c++

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:

#!c++

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:

#!c++

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.

[osrf-migration]

Original comment by Nate Koenig (Bitbucket: Nathan 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)

[osrf-migration]

Original comment by Stefan Kohlbrecher (Bitbucket: 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.

[osrf-migration]

Original comment by Nate Koenig (Bitbucket: Nathan 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.

[osrf-migration]

Original comment by Johannes Meyer (Bitbucket: johmeyer).

---

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.

[osrf-migration]

Original comment by Nate Koenig (Bitbucket: Nathan 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.

[osrf-migration]

Original comment by Thomas Koletschka (Bitbucket: thomasko).

---

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.

[osrf-migration]

Original comment by Nate Koenig (Bitbucket: Nathan 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.

[osrf-migration]

Original comment by Steve Peters (Bitbucket: Steven Peters, GitHub: scpeters).

---

• changed state from "new" to "resolved"

multi-threaded sensors in pull request #277

[osrf-migration]

Original comment by Nate Koenig (Bitbucket: Nathan Koenig).

---

• set version to "all"

[osrf-migration]

Original comment by Nate Koenig (Bitbucket: Nathan Koenig).

---

• changed state from "resolved" to "closed"