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