Network latency affects performance of rospy logger function

[furushchev]

Hi,

I tested the performance of ros on network with huge latency (up to 2000msec for round trip) and found that network latency affects execution time of logging functions on rospy.
(For example, In network 2000msec latency, rospy.loginfo takes more than 2000msec)
I remapped /rosout to other topic name, which is not subscribed by any node, but still the same issue happens.
I can guess rospy.loginfo invokes any blocking communication with rosmaster internally but I still could not track it.
On the other hand, in roscpp logging functions return immediately even in network with latency.

Does anyone know something about this issue?
Thank you very much in advance!

[paulbovbel]

I'll bet I know what this is - from #1575, rospy logging will currently hit rosmaster for the /rosout_disable_topics_generation on every logging invocation. This can be quite.. unpleasant.

According to #1597 (review), it would not be acceptable to only check this parameter at init time.

One way to resolve this would be to pull in the rospy cached param API PR from #1515, and then query the param in cached mode as in here locusrobotics@5b39fbf.

[furushchev]

@paulbovbel Thank you for very helpful comment! I'll try the patch and see it solves the issue. Anyway, all the best for the new year! 👍

[furushchev]

@paulbovbel Hi, I tested on the environment with huge latency (where it takes 2 seconds for round trip).
As far as I see the code, there are two calling rosmaster in one logging invocation:

1. rospy.get_param("/rosout_disable_topics_generation")
2. get_topic_manager().get_topics()

The hypotheses are:
As for the call 1, I expect that we can save calling every time by applying #1515.
As for the call 2, after applying the patch AND setting param /rosout_disable_topics_generation to true, the call is skipped.

And I confirmed it works as expected.

With application of #1515, I changed as follows:

diff --git a/clients/rospy/src/rospy/impl/rosout.py b/clients/rospy/src/rospy/impl/rosout.py
index a1ce4d84c..ba7d135dd 100644
--- a/clients/rospy/src/rospy/impl/rosout.py
+++ b/clients/rospy/src/rospy/impl/rosout.py
@@ -89,10 +89,7 @@ def _rosout(level, msg, fname, line, func):
                     # check parameter server/cache for omit_topics flag
                     # the same parameter is checked in rosout_appender.cpp for the same purpose
                     # parameter accesses are cached automatically in python
-                    if rospy.has_param("/rosout_disable_topics_generation"):
-                        disable_topics_ = rospy.get_param("/rosout_disable_topics_generation")
-                    else:
-                        disable_topics_ = False
+                    disable_topics_ = rospy.get_param_cached("/rosout_disable_topics_generation", False)
 
                     if not disable_topics_:
                         topics = get_topic_manager().get_topics()

Without latency

• Using normal rospy

$ ipython
In [1]: import rospy
In [2]: rospy
Out[2]: <module 'rospy' from '/opt/ros/melodic/lib/python2.7/dist-packages/rospy/__init__.pyc'>
In [3]: rospy.init_node('bbb')
In [4]: %time rospy.loginfo('not patched')
[INFO] [1578368864.669303] [/bbb:rosout]: not patched
CPU times: user 3.09 ms, sys: 0 ns, total: 3.09 ms
Wall time: 4.38 ms

• Using patched rospy

$ ipython
In [1]: import rospy
In [2]: rospy
Out[2]: <module 'rospy' from '/home/furushchev/testing/devel/lib/python2.7/dist-packages/rospy/__init__.pyc'>
In [3]: rospy.init_node('aaa')
In [4]: %time rospy.loginfo('patched')
[INFO] [1578368850.560460] [/aaa:rosout]: patched
CPU times: user 2.17 ms, sys: 228 µs, total: 2.4 ms
Wall time: 4.14 ms

With latency

• Using normal rospy

In [6]: %time rospy.loginfo('not patched')
[INFO] [1578371149.784252] [/bbb:rosout]: not patched
CPU times: user 14.5 ms, sys: 1.96 ms, total: 16.5 ms
Wall time: 4.01 s

• Using patched rospy

In [8]: %time rospy.loginfo('patched')
[INFO] [1578371140.534392] [/aaa:rosout]: patched
CPU times: user 6.83 ms, sys: 3.81 ms, total: 10.6 ms
Wall time: 2 s

# rosparam set /rosout_disable_topics_generation true

In [9]: %time rospy.loginfo('patched')
[INFO] [1578371218.355506] [/aaa:rosout]: patched
CPU times: user 1.77 ms, sys: 534 µs, total: 2.3 ms
Wall time: 1.71 ms

[dirk-thomas]

Resolved by #1881.