Add caching for the exec function in rbm

In a mail to tbb-dev, dcf mentioned that while building tor-browser, a lot of time is spent in rbm: https://lists.torproject.org/pipermail/tbb-dev/2020-February/001045.html

I think an easy way to improve this is by caching the result from the exec() template function. We use it for example with the line version: '[% c("abbrev") %]' which runs something like exec("git log -1 --format=%h"), which then runs a git checkout before running the git log command. The version value is used in filenames, and build_id, which are then used in a lot of places, but with no caching we end up doing a lot of calls the same git checkout and git log commands. The switch to pion which added a lot of go projects each with their git repository probably made this issue more visible.

added TorBrowserTeam202002R actualpoints::.5 component::applications/rbm owner::boklm priority::medium resolution::fixed severity::normal status::closed tbb-9.5a6 tbb-rbm type::task labels

Looking at https://people.torproject.org/~dcf/graphs/nytprof-rbm-20200212-94fce31e/root-tor-browser-build-rbm-lib-RBM-pm-8-line.html#715 it seems input_file_need_dl is another function where we could add caching, to avoid computing sha256sum of input files multiple times.

Trac:
Cc: dcf to dcf, mcs

In branch bug_33283_v2, I added two patches.

The first one adds caching for the exec template function: https://gitweb.torproject.org/user/boklm/rbm.git/commit/?h=bug_33283_v2&id=ce6b9136fc9e006536b34844946d67aa92cc0c21

The second one avoids computing sha256sum of files multiple times: https://gitweb.torproject.org/user/boklm/rbm.git/commit/?h=bug_33283_v2&id=e4f12abe9ed81050994b5345c21b988005259396

When running the command rbm/rbm showconf tor-browser filename --target torbrowser-linux-x86_64 --target alpha on my machine, without those patches it takes 3m25. With the first patch, it now takes 2m49, and 1m59 with both patches.

Trac:
Status: new to needs_review
Keywords: N/A deleted, TorBrowserTeam202002R added

Replying to boklm:

When running the command rbm/rbm showconf tor-browser filename --target torbrowser-linux-x86_64 --target alpha on my machine, without those patches it takes 3m25. With the first patch, it now takes 2m49, and 1m59 with both patches.

For me the times are 5m28s with no patches, and 3m50s with both patches. This is with having run make fetch beforehand.

# git log --oneline | head -n 1
c27a4f7 Pick up tor-browser -build2
# time rbm/rbm showconf tor-browser filename --target torbrowser-linux-x86_64 --target alpha
tor-browser-9.5a5-linux-x86_64-0e25a4

real    5m28.603s
user    4m53.818s
sys     0m38.330s
# cd rbm
# git remote add boklm https://git.torproject.org/user/boklm/rbm.git
# git fetch boklm
# git checkout bug_33283_v2
# cd ..
# time rbm/rbm showconf tor-browser filename --target torbrowser-linux-x86_64 --target alpha
tor-browser-9.5a5-linux-x86_64-0e25a4

real    3m50.601s
user    3m38.372s
sys     0m13.379s

Replying to boklm:

In branch bug_33283_v2, I added two patches.

I did another profiler run using these two patches. https://people.torproject.org/~dcf/graphs/nytprof-rbm-20200212-e4f12abe/ It looks like the number of calls to RBM::config_p are down a little, from 89 million to 87.5 million. Still about half of the calls come from RBM::get_target.

I tried to match the conditions of the first profiler run as closely as possible. I started after running a full make testbuild at b46fd762e0866fe01707e469eb997040f37c16a2. Then I removed only the snowflake output: mv out/snowflake out.snowflake.bak. Then I ran

# time perl -d:NYTProf rbm/rbm build snowflake --target testbuild --target torbrowser-linux-x86_64
Created /root/tor-browser-build/tmp/rbm-kPAVL/snowflake-5eff0f3ba406.tar.gz
Using file /root/tor-browser-build/out/container-image/container-image_wheezy-amd64-f2bcf2cde274.tar.gz
Using file /root/tor-browser-build/out/go/go-1.12.13-6f6dc9.tar.gz
Using file /root/tor-browser-build/out/uniuri/uniuri-8902c56451e9-linux-x86_64-952cce.tar.gz
Using file /root/tor-browser-build/out/goptlib/goptlib-v1.1.0-linux-x86_64-b9f8dc.tar.gz
Using file /root/tor-browser-build/out/pion-webrtc/pion-webrtc-77c6e3b827e4-linux-x86_64-b7f872.tar.gz
Using file /root/tor-browser-build/out/quic-go/quic-go-907071221cf9-linux-x86_64-7136df.tar.gz
Build log: /root/tor-browser-build/logs/snowflake-linux-x86_64.log

real    46m42.061s
user    43m9.134s
sys     3m43.336s

I'll re-do the experiment without the two bug_33283_v2 patches, to verify that it's a fair comparison.

UPDATE: here is the verification. As in my email, without the two patches, there are about 89 million calls to RBM::config_p (89245624). It took about 10 minutes longer.

# time perl -d:NYTProf rbm/rbm build snowflake --target testbuild --target torbrowser-linux-x86_64
Created /root/tor-browser-build/tmp/rbm-twDRE/snowflake-5eff0f3ba406.tar.gz
Using file /root/tor-browser-build/out/container-image/container-image_wheezy-amd64-f2bcf2cde274.tar.gz
Using file /root/tor-browser-build/out/go/go-1.12.13-6f6dc9.tar.gz
Using file /root/tor-browser-build/out/uniuri/uniuri-8902c56451e9-linux-x86_64-952cce.tar.gz
Using file /root/tor-browser-build/out/goptlib/goptlib-v1.1.0-linux-x86_64-b9f8dc.tar.gz
Using file /root/tor-browser-build/out/pion-webrtc/pion-webrtc-77c6e3b827e4-linux-x86_64-b7f872.tar.gz
Using file /root/tor-browser-build/out/quic-go/quic-go-907071221cf9-linux-x86_64-7136df.tar.gz
Build log: /root/tor-browser-build/logs/snowflake-linux-x86_64.log

real    55m8.928s
user    46m42.348s
sys     8m29.499s

Okay, the patches look good. I merged the branch with master and I picked it up on tor-browser-build with commit ffc6f844dbbf1985f5d10bd8dab2b15d9c8c2e75.

Trac:
Resolution: N/A to fixed
Status: needs_review to closed

Trac:
Keywords: N/A deleted, tbb-9.5a6 added

Trac:
Actualpoints: N/A to .5

closed

added 4h of time spent

mentioned in issue #33336 (moved)

moved to tpo/applications/rbm#33283 (closed)

mentioned in issue tpo/anti-censorship/pluggable-transports/snowflake#33336 (closed)