[ros2topic] pub frequency lower then expect

[yechun1]

publish msg period as 1 minutes, but actually the result is lower then expect.

$ ros2 topic pub /image sensor_msgs/Image -r 10 -p 10
actually period: 1.004s.

$ ros2 topic pub /image sensor_msgs/Image -r 100 -p 100
actually period: 1.040s.

$ ros2 topic pub /image sensor_msgs/Image -r 1000 -p 1000
actually period: 1.387s.

reference debug code:

diff --git a/ros2topic/ros2topic/verb/pub.py b/ros2topic/ros2topic/verb/pub.py
index e07bdeb..431877d 100644
--- a/ros2topic/ros2topic/verb/pub.py
+++ b/ros2topic/ros2topic/verb/pub.py
@@ -101,9 +101,13 @@ def publisher(

     print('publisher: beginning loop')
     count = 0
+    prev = time.time()
     while rclpy.ok():
         count += 1
         if print_nth and count % print_nth == 0:
+            interval = time.time() - prev
+            print('interval:%s' %interval)
+            prev = time.time()

[dirk-thomas]

In the current code in the loop it sleeps for the duration specified by the rate argument:

ros2cli/ros2topic/ros2topic/verb/pub.py

Line 112 in 4dbd63b

time.sleep(period)

So any time spend in the actual publish call will add to the time of one cycle and therefore reduce the actual rate. I would suggest to change the main loop to use a time so that the publish time doesn't affect the rate (as long as publishing doesn't take longer than the rate). Please consider to provide a pull request for this.

The secondary issue is that the publish call does take that long for large messages in Python but I think that is already covered by other tickets (e.g. ros2/common_interfaces#55).

[yechun1]

PR #141 use timer to fix rate loss of time.sleep()

[dirk-thomas]

The first problem of the loop accumulating delays in each cycle is been addressed by #141 and ros2/rcl#291.

The slow performance of the publish() invocation is still pending.

[yechun1]

I have investigated publish issue, here is the status updates:

1. When only pub topic with sub. the rate is normal for example 1000hz.
2. When pub topic with sub(patch Enable ros2tpoic hz command #133), sometimes the rate is keep normal.(1000hz),
   sometimes, the publish rate will continually decrease. for example 1000hz -> 800hz -> 600hz ... (cpu > 100%)

the reproducing probability is about 50%. see the cpu occupy increased, not sure if there is memory leak on low level functions called by publish. I try to use valgrind, the log has memory issue of rmw and rcl but trace only to .so, not code line. I don't find the way to build ros2 with -g for valgrind analytics.

[yechun1]

I have sync-up the latest ros2.repo code (include rcl updates), have not reproduced the publish rate decrease issue.

On test:
the publish(msg) cost about 0.06s on every 1s print, using timer could keep the expected pub rate (with merged patches: #141 and ros2/rcl#291) .
$ ros2 topic pub /image sensor_msgs/Image -r 1000 -p 1000
actually period: 0.999994s.

the issue should be fixed.