dramatic performance boost for consecutive rospack calls [backport to indigo] #49

rhaschke · 2015-11-25T23:31:26Z

Consecutive calls to the rospack library, e.g. ros::package::getPath(), from within the same process recrawled the ROS_PACKAGE_PATH all the time, because the appropriate rospack instances were created again and again.
This PR (going in line with a similar PR on roslib) improves things in two respects:

a static rospack::Rospack instance is used in ROSPack::run(), thus re-using the same instance for all consecutive calls
in Rosstackage::crawl() the cache is loaded only once at the beginning, when search_paths_ is still empty

The following simple test program (doing 3000 calls to getPath()) performs 160 times faster:

time ./foo
real    0m0.264s
user    0m0.251s
sys     0m0.012s

time ./foo
real    0m49.456s
user    0m42.500s
sys     0m6.840s

#include <ros/package.h>
int main(int argc, char *argv[]) {
    for (int i=0; i<3000; ++i) {
        ros::package::getPath("roscpp");
    }
}

rhaschke · 2015-11-25T23:38:36Z

This goes along with roslib PR #97.

dirk-thomas · 2015-11-25T23:50:32Z

src/rospack.cpp

@@ -331,16 +331,13 @@ Rosstackage::crawl(std::vector<std::string> search_path,
 {
  if(!force)
  {
-    if(readCache())
+    // read the cache only once (when search_paths_ is still empty)
+    if(search_paths_.empty() && readCache())


Why do you want to prevent using the existing cache here? This will result in worse performance when this function is called multiple times.

Indeed, if the current search_path has changed, we should read the corresponding cache. I adapted the code, such that there are the following code paths in Rosstackage::crawl() now:

crawling is enforced -> just (re)crawl

current search_path matches previous one and rospack already crawled: nothing todo [new]

current search_path diverges from previous one: read corresponding cache

on success: nothing else todo

on failure (no cache or too old): re-crawl

on re-crawling, set the search_paths_ appropriately

rhaschke · 2015-11-27T09:13:12Z

@dirk-thomas Did you already have seen my answers to your remarks?

dirk-thomas · 2015-11-30T18:13:26Z

src/rospack.cpp

+      return false;
+  }
+  return true;
+}


How is this function different from the comparison operator of a vector (http://en.cppreference.com/w/cpp/container/vector/operator_cmp)?

Valid point. I didn't checked for availability of vector::operator==. Simply moved the existing verbose code into its own function. Now, the function is replaced by std::vector::operator==.

gerkey · 2015-12-09T20:01:34Z

I've started working on this in two branches:

https://github.com/ros/ros/tree/reuse_cache
https://github.com/ros/rospack/tree/reuse_cache

I applied @rhaschke's changes and added a test to rospack to test the effect of in-process changes to ROS_PACKAGE_PATH: https://github.com/ros/rospack/blob/reuse_cache/test/test/utest.cpp#L129

Sadly, that test passes on the first run, but fails on the second run and all subsequent runs. I'm still looking into it.

rhaschke · 2015-12-09T20:21:45Z

Hm. I tested that only manually. I will have a look into your branch too.

rhaschke · 2015-12-09T21:41:10Z

@gerkey Created pull request #52 to fix the unit test.

rhaschke · 2015-12-09T21:43:21Z

I had some issues to compile the unit test. Using my catkin tools environment, the binary rospack-utest wasn't created by default. I had to manually make rospack-utest. Is that normal behavior?

gerkey · 2015-12-09T21:50:01Z

Thanks for fixes in #52.

But I still have failures elsewhere after the initial run, apparently related to whether the cache is available:

gerkey@rossum:~/code/rospack-caching/build/rospack/test$ rm -rf ~/.ros/rospack_cache_*
gerkey@rossum:~/code/rospack-caching/build/rospack/test$ ../../../devel/lib/rospack/rospack-utest 
[==========] Running 4 tests from 1 test case.
[----------] Global test environment set-up.
[----------] 4 tests from rospack
[ RUN      ] rospack.reentrant
[       OK ] rospack.reentrant (4 ms)
[ RUN      ] rospack.multiple_rospack_objects
[       OK ] rospack.multiple_rospack_objects (6 ms)
[ RUN      ] rospack.deduplicate_tokens
[       OK ] rospack.deduplicate_tokens (0 ms)
[ RUN      ] rospack.env_change
[       OK ] rospack.env_change (2 ms)
[----------] 4 tests from rospack (12 ms total)

[----------] Global test environment tear-down
[==========] 4 tests from 1 test case ran. (12 ms total)
[  PASSED  ] 4 tests.
gerkey@rossum:~/code/rospack-caching/build/rospack/test$ ../../../devel/lib/rospack/rospack-utest 
[==========] Running 4 tests from 1 test case.
[----------] Global test environment set-up.
[----------] 4 tests from rospack
[ RUN      ] rospack.reentrant
[       OK ] rospack.reentrant (4 ms)
[ RUN      ] rospack.multiple_rospack_objects
[       OK ] rospack.multiple_rospack_objects (5 ms)
[ RUN      ] rospack.deduplicate_tokens
[       OK ] rospack.deduplicate_tokens (0 ms)
[ RUN      ] rospack.env_change
/home/gerkey/code/rospack-caching/src/rospack/test/test/utest.cpp:188: Failure
Value of: test_pkgs.size()
  Actual: 3
Expected: output_list.size()
Which is: 4
/home/gerkey/code/rospack-caching/src/rospack/test/test/utest.cpp:204: Failure
Value of: found
  Actual: false
Expected: true
/home/gerkey/code/rospack-caching/src/rospack/test/test/utest.cpp:214: Failure
Value of: std::string()
  Actual: ""
Expected: output
Which is: "precedence1\nprecedence2\nprecedence3\nroslang"
[  FAILED  ] rospack.env_change (2 ms)
[----------] 4 tests from rospack (11 ms total)

[----------] Global test environment tear-down
[==========] 4 tests from 1 test case ran. (11 ms total)
[  PASSED  ] 3 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] rospack.env_change

 1 FAILED TEST

gerkey · 2015-12-09T21:53:01Z

To build and run the test (assuming you have a workspace ws with ros and rospack):

cd ws
catkin_make tests
# The test is sensitive to CWD
cd build/rospack/test
../../../devel/lib/rospack/rospack-utest

You can also run all the tests via catkin_make run_tests, but you have do some scrolling to see the output of this particular test.

gerkey · 2015-12-09T22:05:14Z

Here's more detail, with some instrumentation added to the test:

[ RUN      ] rospack.env_change
/home/gerkey/code/rospack-caching/src/rospack/test/test/utest.cpp:188: Failure
Value of: test_pkgs.size()
  Actual: 3
Expected: output_list.size()
Which is: 4
output_list: 
  precedence1
  precedence2
  precedence3
  roslang
test_pkgs: 
  precedence1
  precedence2
  precedence3

Looks like the result from the first run, with one setting for ROS_PACKAGE_PATH, is persisting into the second run, where that var has been changed.

@rhaschke, can you look into this and get back when it's working?

rhaschke · 2015-12-09T22:06:21Z

Yes, of course. I will do it.

rhaschke · 2015-12-09T23:06:53Z

readCache() simply add more stackages without clearing the list of stackages_ beforehand...
Fixed in #53.

gerkey · 2015-12-10T02:05:30Z

Thanks for the fixes in #53. I'll open a new PR now.

rhaschke · 2015-12-10T08:17:32Z

The cache itself was valid. However, reading the cache simply added new
stackages withouth wiping out existing stuff before.
This worked for the first run, before the internal list was empty
anyway. Additionally, the cache invalidates after 60s thus enforcing a
recrawl, which also wiped out internal storage beforehand.

readCache if search paths have changed

readCache should clear stackages_ before adding more added new method clearStackages(), used in three locations

rhaschke · 2015-12-10T18:33:40Z

I rebased onto the same indigo-devel commit from where #54 started. Subsequently I rebased all additional commits in #54 onto this original PR to keep proper history (see comments here).
#54 and #49 are identical again (except for a permission change that was lost in #54 for some reason).
Hence, I suggest to close #54 and continue here again.

rhaschke · 2016-01-29T13:49:06Z

@dirk-thomas, @gerkey
friendly ping on this PR (and its counter-part ros/ros#97)

gerkey · 2016-02-01T22:16:44Z

We discussed this today and agree that it should be merged into jade, then depending on whether there are any problems, we'll consider backporting to indigo.

dirk-thomas · 2016-03-01T00:42:32Z

@ros-pull-request-builder test this please

dirk-thomas · 2016-03-01T01:49:31Z

This patch has been merged into the newly created jade-devel branch: 2dbf9d8

If there are no regressions it will be considered for being backported into indigo-devel.

dirk-thomas · 2016-03-01T01:49:50Z

I have updated the issue title that only the backport is pending.

dirk-thomas · 2016-06-27T17:31:59Z

Since this has been released into Kinetic as well as Jade for a while without any regressions I cherry-picked the change to the indigo-devel branch as well: 2ce1584

It will be part of the next patch release for Indigo.

rhaschke mentioned this pull request Nov 25, 2015

allow caching of rospack results [backport to indigo] ros/ros#97

Closed

rhaschke mentioned this pull request Nov 25, 2015

[gazebo_ros] fixes #361 ros-simulation/gazebo_ros_pkgs#362

Merged

dirk-thomas reviewed Nov 25, 2015
View reviewed changes

dirk-thomas reviewed Nov 30, 2015
View reviewed changes

gerkey mentioned this pull request Dec 10, 2015

Reuse previous results for better performance (replaces #49) #54

Closed

rhaschke mentioned this pull request Dec 10, 2015

Reuse previous results for better performance (replaces #97) ros/ros#98

Closed

rhaschke force-pushed the indigo-devel branch from d805a22 to cf34b95 Compare December 10, 2015 18:12

rhaschke and others added 9 commits December 10, 2015 19:20

allow caching of rospack results

3e0ede5

rospack: read cache file only once in a process

2f2384b

moved code to compare search paths to new function sameSearchPaths()

010a1ce

readCache if search paths have changed

replaced sameSearchPaths() by std::vector::operator==()

5544930

adding a test cache reuse

deb721c

add test to check cache behavior when env vars change

57c1da2

code simplification

aef53c3

fixed utest

d88d716

fixed readCache()

73a1c31

readCache should clear stackages_ before adding more added new method clearStackages(), used in three locations

add helpful comments

5f65a89

rhaschke force-pushed the indigo-devel branch from cf34b95 to 5f65a89 Compare December 10, 2015 18:24

dirk-thomas pushed a commit that referenced this pull request Mar 1, 2016

allow caching of rospack results (#49)

2dbf9d8

dirk-thomas changed the title ~~dramatic performance boost for consecutive rospack calls~~ dramatic performance boost for consecutive rospack calls [backport to indigo] Mar 1, 2016

rhaschke mentioned this pull request Mar 30, 2016

Add package path cache to load_resource.cpp getPath() ros-visualization/rviz#966

Closed

merge branch 'origin/indigo-devel' into indigo-devel

96e1858

dirk-thomas pushed a commit that referenced this pull request Jun 27, 2016

allow caching of rospack results (#49)

2ce1584

dirk-thomas closed this Jun 27, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

dramatic performance boost for consecutive rospack calls [backport to indigo] #49

dramatic performance boost for consecutive rospack calls [backport to indigo] #49

rhaschke commented Nov 25, 2015

rhaschke commented Nov 25, 2015

dirk-thomas Nov 25, 2015

rhaschke Nov 26, 2015

rhaschke commented Nov 27, 2015

dirk-thomas Nov 30, 2015

rhaschke Dec 1, 2015

gerkey commented Dec 9, 2015

rhaschke commented Dec 9, 2015

rhaschke commented Dec 9, 2015

rhaschke commented Dec 9, 2015

gerkey commented Dec 9, 2015

gerkey commented Dec 9, 2015

gerkey commented Dec 9, 2015

rhaschke commented Dec 9, 2015

rhaschke commented Dec 9, 2015

gerkey commented Dec 10, 2015

rhaschke commented Dec 10, 2015

rhaschke commented Dec 10, 2015

rhaschke commented Jan 29, 2016

gerkey commented Feb 1, 2016

dirk-thomas commented Mar 1, 2016

dirk-thomas commented Mar 1, 2016

dirk-thomas commented Mar 1, 2016

dirk-thomas commented Jun 27, 2016

dramatic performance boost for consecutive rospack calls [backport to indigo] #49

dramatic performance boost for consecutive rospack calls [backport to indigo] #49

Conversation

rhaschke commented Nov 25, 2015

rhaschke commented Nov 25, 2015

dirk-thomas Nov 25, 2015

Choose a reason for hiding this comment

rhaschke Nov 26, 2015

Choose a reason for hiding this comment

rhaschke commented Nov 27, 2015

dirk-thomas Nov 30, 2015

Choose a reason for hiding this comment

rhaschke Dec 1, 2015

Choose a reason for hiding this comment

gerkey commented Dec 9, 2015

rhaschke commented Dec 9, 2015

rhaschke commented Dec 9, 2015

rhaschke commented Dec 9, 2015

gerkey commented Dec 9, 2015

gerkey commented Dec 9, 2015

gerkey commented Dec 9, 2015

rhaschke commented Dec 9, 2015

rhaschke commented Dec 9, 2015

gerkey commented Dec 10, 2015

rhaschke commented Dec 10, 2015

rhaschke commented Dec 10, 2015

rhaschke commented Jan 29, 2016

gerkey commented Feb 1, 2016

dirk-thomas commented Mar 1, 2016

dirk-thomas commented Mar 1, 2016

dirk-thomas commented Mar 1, 2016

dirk-thomas commented Jun 27, 2016