[tbb-dev] Very very slow tor-browser-build build; catastrophic recursion in rbm?

[David Fifield]

I did a build of tor-browser-build build and it took even longer than I
remember it taking -- from Friday until Tuesday, roughly. This is on a
VPS with six 2 GHz CPUs and 16 GB RAM. Some projects I know take a long
time to build, like rust and firefox, but it seemed like most of the
time was being spent in the "rbm" process, not in building the projects.

I don't know much about profiling Perl, but I tried a tool called
NYTProf that produces HTML output:
https://people.torproject.org/~dcf/graphs/nytprof-rbm-20200212-94fce31e/

The above NYTProf output is not from a full build. It's from modifying
projects/snowflake/config only and then building snowflake for only one
target; still it took almost an hour.
	perl -d:NYTProf rbm/rbm build snowflake --target testbuild --target torbrowser-linux-x86_64
	nytprofhtml

To my untrained eye it looks like there is some kind of exponential
recursion happening around the RBM::config_p function. See here, where
in building one project the function was called 89 million times:
https://people.torproject.org/~dcf/graphs/nytprof-rbm-20200212-94fce31e/#subs_table
Clicking through to the per-line view, we see that 45 million of those
calls were from RBM::get_target, and most of the rest were from
RBM::config:
https://people.torproject.org/~dcf/graphs/nytprof-rbm-20200212-94fce31e/root-tor-browser-build-rbm-lib-RBM-pm-8-line.html#89

You know how, if you write a Fibonacci number function and don't memoize
the recursive calls, it ends up re-computing the same subtrees over and
over and doing exponential work?
	def fib(n):
	    if n == 0 or n == 1:
		return 1
	    return fib(n - 1) + fib(n - 2)
It feels like something like that is happening here. There's a pattern
where RBM::process_template calls a chain of functions that reaches
RBM::config_p, which eventually calls RBM::process_template again. It's
not an infinite loop, but it seems to be doing the same work many times.
I looked at it for a bit but my Perl isn't strong enough to understand
specifically what's happening.

Notice how there are three loops of RBM::process_template before doing
an RBM::config_p that calls back into further RBM::process_template.

RBM::process_template
Template::process
Template::Service::process
Template::Context::process
Template::Document::process
Template::Document::__ANON__[input text:10]
Template::Stash::XS::get
RBM::__ANON__[rbm/lib/RBM.pm:640]
RBM::project_config
RBM::process_template
Template::process
Template::Service::process
Template::Context::process
Template::Document::process
Template::Document::__ANON__[input text:9]
Template::Stash::XS::get
RBM::__ANON__[rbm/lib/RBM.pm:640]
RBM::project_config
RBM::process_template
Template::process
Template::Service::process
Template::Context::process
Template::Document::process
Template::Document::__ANON__[input text:18]
Template::Stash::XS::get
RBM::__ANON__[rbm/lib/RBM.pm:640]
RBM::project_config
RBM::config
RBM::config_p
RBM::DefaultConfig::__ANON__[rbm/lib/RBM/DefaultConfig.pm:606]
RBM::input_files
RBM::project_step_config
RBM::project_config
RBM::process_template
Template::process
... et cetera ...

Some more evidence is that while I was waiting for rbm to do something,
I was watching the modification times of the git_clones:
	ls -ltrhd git_clones/*/.git | tail -n 15
It was constantly touching all different projects, but re-touching the
same ones over and over.