Time spent in integration is only partially captured in logging

Summary

When opening a build shell on an element in a non-trivial project, I find that significant time is spent in-between these two log lines:

[00:00:05][4a0ba65b][ main:target.bst                    ] SUCCESS Staging dependencies
.. a few seconds spent in the middle here ..
[--:--:--][4a0ba65b][ main:target.bst                    ] START   Integrating sandbox

This seems to be because Sandbox.batch won't start the timed_activity until the batched commands are actually run. This means that time spent creating the batch is not captured.

From profiling, I see the time spent is mostly parsing public.yaml files from the artifacts to be integrated.

Steps to reproduce

Note: I was not able to repro this using @jennis' handy [debian-stretch-bst](git clone https://gitlab.com/jennis/debian-stretch-bst.git), as it doesn't do any integration.

I'm happy to spend more effort making a public repro case if it would help.

What is the current bug behavior?

Time spent preparing to do integration is not captured.

What is the expected correct behavior?

Time spent preparing to do integration should be captured.

Possible fixes

We could wrap integration and others in a timed_activity again like so:

diff --git a/buildstream/buildelement.py b/buildstream/buildelement.py
index 6ef060f1..ba2439b7 100644
--- a/buildstream/buildelement.py
+++ b/buildstream/buildelement.py
@@ -223,9 +223,10 @@ class BuildElement(Element):

         # Run any integration commands provided by the dependencies
         # once they are all staged and ready
-        with sandbox.batch(SandboxFlags.NONE, label="Integrating sandbox"):
-            for dep in self.dependencies(Scope.BUILD):
-                dep.integrate(sandbox)
+        with self.timed_activity("Integrating sandbox", silent_nested=True):
+            with sandbox.batch(SandboxFlags.NONE):
+                for dep in self.dependencies(Scope.BUILD):
+                    dep.integrate(sandbox)

         # Stage sources in the build root
         self.stage_sources(sandbox, self.get_variable('build-root'))

We could also look at starting the timer earlier in the Sandbox.batch context manager.

Other relevant information

• BuildStream version affected: /milestone %BuildStream_v1.x

---