Allow sharing caches across actions when sandboxing is in use

[ktf]

Description of the problem / feature request:

Extremely low performance of bazel when building a large project on macOS when compared to running CMake + make.

Bugs: what's the simplest, easiest way to reproduce this bug? Please provide a minimal example if possible.

Build a large bazel project on macOS. I see that a lot of fsevents for files in /private/var/tmp/_bazel_user triggered and fseventsd seems to crawl at 100% - 200% CPU usage after them, slowing down the builds. I do have /private/var/tmp masked out in my spotlight configuration, but it does not seem to be enough.

What operating system are you running Bazel on?

Darwin grisu.dyndns.cern.ch 18.2.0 Darwin Kernel Version 18.2.0: Mon Nov 12 20:24:46 PST 2018; root:xnu-4903.231.4~2/RELEASE_X86_64 x86_64

What's the output of bazel info release?

release 0.22.0

[irengrig]

Hello @ktf, thank you for your feedback. Do you some particular project in mind that we can experiment with?

[ktf]

What I have is:

https://github.com/ktf/AliceO2/tree/bazel-support

where you can for example do bazel build @root//:cling. Given this is a subset of tensorflow (i.e. the part which builds llvm), plus some extra stuff to build parts of clang, I am surprised this is not a common issue. Notice I build on my local laptop (2015 MBP) with no external cache.

[irengrig]

Thank you for the example project! Assigning to Apple team.

[keith]

It might be worth trying to repro with this commit https://github.com/bazelbuild/bazel/commit/087734009801242b83655efb863b2d5a761ae3dc

[jmmv]

Indeed; that commit may help and I'd be very interested to know if it does.

But I have also noticed fseventsd consuming lots of CPU (and, incidentally, this service runs at default priority -- so that commit actually makes Bazel run at a lower priority which is probably good). Haven't had a chance to dig into this. Maybe setting --nowatchfs would prevent the fseventsd activity, though then Bazel will be slower to detect file changes of course... (just thinking aloud). It just feels stupid that we have to waste so much CPU just to watch for file changes...

[ktf]

Thanks. I will try that when I have a bit of time. Notice also that the fsevents seem to be relative to stuff in /var/tmp/_bazel_user/, not in ~/src/myproject. Maybe I simply do not understand the bazel internals, but is that what you'd expect from the file watching process?

[jmmv]

Yes. That's where the build artifacts are -- they are not stored in your source tree -- and Bazel has to watch them for out-of-band changes.

[kastiglione]

Do you know the backstory is for watching the build tree? I was surprised to learn this.

[keith]

@jmmv it looks like --watchfs defaults to false, so unless @ktf is setting that, this may not apply?

[jmmv]

@kastiglione All outputs (except for top-level ones) are inputs to other actions. Bazel needs to know if they have been modified out-of-band to invalidate their corresponding actions. (Yes, you could assume that the build tree is not modified by users, but that's not what real-world usage shows.)

@keith That's a good point. If the reporter is indeed not using --nowatchfs, then fseventsd usage comes from elsewhere.

[ktf]

@keith AFAICR, I did not explicitly enable --watchfs. Any way to check this is the case?

@jmmv, does that happen also for files which are not currently in any given action? The files being watched seem to be the full contents of a tarball of sources I download with http_archive, regardless of them being used in the build or not.

[kastiglione]

@ktf have you run without the sandbox (--spawn_strategy=standalone) to compare the time difference?

[ktf]

So I gave a quick try, with the suggested target and I got:

• bazel build --spawn_strategy=standalone "@root//:cling" 0.24s user 0.36s system 0% cpu 23:11.70 total

• bazel build "@root//:cling" 0.25s user 0.36s system 0% cpu 27:17.31 total

I did a bazel clean --expunge in between the two. What I also see is that in the standalone case 90% of the CPU time for the whole machine is in user, while in the second case I see a lot of longish spikes in system usage and fseventd popping up high in the offenders list. In a shorter test I have an even more dramatic difference:

INFO: Elapsed time: 190,447s, Critical Path: 29,94s
INFO: 226 processes: 226 darwin-sandbox.
INFO: Build completed successfully, 229 total actions
bazel build "@fairmq//..."  0.06s user 0.08s system 0% cpu 3:10.52 total

INFO: Elapsed time: 122,390s, Critical Path: 21,09s
INFO: 226 processes: 226 local.
INFO: Build completed successfully, 229 total actions
bazel build --spawn_strategy=standalone "@fairmq//..."  0.06s user 0.07s system 0% cpu 2:02.46 total

[jmmv]

I'm not sure why you focus on fseventsd though... That's probably a symptom more than a problem.

What exactly are you doing? What build times are you seeing? What are you comparing those against?

[ktf]

Because I see fseventd crawling in "Activity Monitoring", so I suspect it's getting overwhelmed by events and steals CPU cycles which could be used for compilation.

[Globegitter]

@jmmv I am just trying out the flag --experimental_sandbox_async_tree_delete_idle_threads="auto" in bazel 0.26rc4 (would also be nice to see a description on what auto does - how is it different to HOST_CPUS?) you added and it seems to work well for a build that succeeds but now I am getting following NullPointer for failing builds:

(00:29:13) ERROR: Build failed. Not running target
Internal error thrown during build. Printing stack trace: java.lang.NullPointerException
    at com.google.common.base.Preconditions.checkNotNull(Preconditions.java:877)
    at com.google.devtools.build.lib.sandbox.SandboxModule.afterCommand(SandboxModule.java:472)
    at com.google.devtools.build.lib.runtime.BlazeRuntime.afterCommand(BlazeRuntime.java:580)
    at com.google.devtools.build.lib.runtime.BlazeCommandDispatcher.execExclusively(BlazeCommandDispatcher.java:506)
    at com.google.devtools.build.lib.runtime.BlazeCommandDispatcher.exec(BlazeCommandDispatcher.java:206)
    at com.google.devtools.build.lib.server.GrpcServerImpl.executeCommand(GrpcServerImpl.java:749)
    at com.google.devtools.build.lib.server.GrpcServerImpl.access$1600(GrpcServerImpl.java:103)
    at com.google.devtools.build.lib.server.GrpcServerImpl$2.lambda$run$0(GrpcServerImpl.java:818)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.base/java.lang.Thread.run(Unknown Source)
java.lang.NullPointerException
    at com.google.common.base.Preconditions.checkNotNull(Preconditions.java:877)
    at com.google.devtools.build.lib.sandbox.SandboxModule.afterCommand(SandboxModule.java:472)
    at com.google.devtools.build.lib.runtime.BlazeRuntime.afterCommand(BlazeRuntime.java:580)
    at com.google.devtools.build.lib.runtime.BlazeCommandDispatcher.execExclusively(BlazeCommandDispatcher.java:506)
    at com.google.devtools.build.lib.runtime.BlazeCommandDispatcher.exec(BlazeCommandDispatcher.java:206)
    at com.google.devtools.build.lib.server.GrpcServerImpl.executeCommand(GrpcServerImpl.java:749)
    at com.google.devtools.build.lib.server.GrpcServerImpl.access$1600(GrpcServerImpl.java:103)
    at com.google.devtools.build.lib.server.GrpcServerImpl$2.lambda$run$0(GrpcServerImpl.java:818)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.base/java.lang.Thread.run(Unknown Source)
java.lang.NullPointerException
    at com.google.common.base.Preconditions.checkNotNull(Preconditions.java:877)
    at com.google.devtools.build.lib.sandbox.SandboxModule.afterCommand(SandboxModule.java:472)
    at com.google.devtools.build.lib.runtime.BlazeRuntime.afterCommand(BlazeRuntime.java:580)
    at com.google.devtools.build.lib.runtime.BlazeCommandDispatcher.execExclusively(BlazeCommandDispatcher.java:506)
    at com.google.devtools.build.lib.runtime.BlazeCommandDispatcher.exec(BlazeCommandDispatcher.java:206)
    at com.google.devtools.build.lib.server.GrpcServerImpl.executeCommand(GrpcServerImpl.java:749)
    at com.google.devtools.build.lib.server.GrpcServerImpl.access$1600(GrpcServerImpl.java:103)
    at com.google.devtools.build.lib.server.GrpcServerImpl$2.lambda$run$0(GrpcServerImpl.java:818)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.base/java.lang.Thread.run(Unknown Source)

[ob]

@jmmv I have some more data to add to this problem. I compiled my project with/without sandboxing, using master (includes @meisterT 's new profiling of sanbox creation/deletion) and captured the same compilation command towards the end of the build in both cases:

bazel build --genrule_strategy=local --spawn_strategy=local --config Debug --experimental_generate_json_trace_profile --experimental_profile_cpu_usage --profile trace-profile.json //:LinkedIn

Produces:

Wall duration for the action is 809.971 ms, ObjcCompile at the bottom is 757.352 ms.

Then I ran the build again with sandboxing turned on:

bazel build --genrule_strategy=sandboxed --spawn_strategy=sandboxed --config Debug --experimental_generate_json_trace_profile --experimental_profile_cpu_usage --profile trace-profile.json //:LinkedIn

which produces for the same compilation command:

Total action time is 18,721.641 ms, sandbox.createFileSystem is 1,256.937 ms, subprocess.run is 16,576.424 ms, and sandbox.delete is 835.565 ms.

It seems the main problem is in subprocess.run, is there a way to get a more detailed breakdown of what it's doing?

[meisterT]

Are those units correct, i.e. is the action really ~20x slower with sandboxing?

[ob]

Another data point, I replaced sandbox-exec with a fake-sandbox-exec that just exec(2)'s the given arguments (code here ) and got this for that same file:

Total action duration 17,940.675 ms, sandbox.createFileSystem 1,174.103 ms, subprocess.run 16,183.121 ms, and sandbox.delete 531.670 ms.

[ob]

Are those units correct, i.e. is the action really ~20x slower with sandboxing?

Yes, the total build time without sandboxing is about 7 min and with sandboxing is a little over 2 hours.

[meisterT]

Can you try this?

bazel build --experimental_collect_local_sandbox_action_metrics --sandbox_debug //...

Then you should have in the output_base a directories called sandbox/<number> with stats.out files in it. The format is https://github.com/bazelbuild/bazel/blob/master/src/main/protobuf/execution_statistics.proto

[jmmv]

Also... the only thing left to try is to run with --sandbox_debug to keep the sandbox directory around, run with --subcommands to print what is being run, and then manually copy/paste the command invocation without any of the sandbox-exec stuff to run it within the sandbox directory, outside of Bazel's control.

If that's slow... then your theory of slow symlink traversal has some extra points. But I cannot find any hints online that this may be a problem.

Do you use multiple volumes? Is the sandbox maybe being created in a separate one?

[ob]

@meisterT Thanks, I did that and am in the process of writing a text dumper.

@jmmv Interesting, I tried that. I artificially introduced a failure via

#error "fail here"

and ran the bazel command again (sandboxed). Again, it took 18 s. Then I copied the command and ran it manually:

$ time ./buildit.sh
        0.42 real         0.20 user         0.20 sys

So it's something when you run it from Java maybe?

Do you use multiple volumes? Is the sandbox maybe being created in a separate one?

No, it's all in the same SSD volume.

[ob]

So I ran it again using Instruments.app and the weird thing is that when I run it through Bazel, all the time is spent in clang:

Note that clang is taking 14.36 s in this trace. But if I run the exact same command via bash, I get:

with clang taking 387 ms. This is what made me suspect the symbolic links but now I'm not sure... something in the way that Bazel spawns these commands is changing clang's behavior.

[ob]

Ok, found it... when clang is being run through Bazel, it gets passed the flag

'-fmodules-cache-path=bazel-out/ios-x86_64-min11.0-applebin_ios-ios_x86_64-dbg/bin/_objc_module_cache'

and that directory is initially empty. This causes clang to recompile all the system and user's modules. When I run it without the sandbox (or in my bash script), the *.pcm files are already there so clang saves a bunch of time. If I modify my bash script to remove that directory before running:

$ time ./buildit.sh
       14.30 real        11.39 user         2.83 sys

which matches what I'm seeing with Bazel.

[jmmv]

Aha, yeah, that explains it (or at least one problem). I had encountered this earlier because the way the module cache works breaks loudly when sandboxfs is in use but silently "works" in the default case. @allevato

But I'm surprised though: from our previous discussions, it seemed that you'd only see the slowdown in some machines and not others, and only after upgrading to Catalina? Those shouldn't influence how this works.

[allevato]

The Clang and Swift implicit module caches are inherently incompatible with hermetic builds and sandboxed execution. The only way to achieve the same degree of performance as the implicit module cache in a Bazel-like build is to explicitly precompile the modules as part of the build graph and propagate them as known inputs/outputs instead of dumping them into a single common directory. I'm working on that for Swift, but I don't think there's any progress planned for Clang in the extreme short-term.

[ktf]

Is there a way to disable the modulecache completely for C++ projects?

As a side note, do you use DYLD_LIBRARY_PATH anywhere? We noticed that since Mohave the lookup is extremely slow and on my laptop there is ~ 1ms overhead per extra path:

→ time ls
ANALYSIS.md  BUILD  CMakeLists.txt  COOKBOOK.md  README.md  include  scripts  src  test
ls -G  0.00s user 0.00s system 70% cpu 0.006 total

→ time DYLD_LIBRARY_PATH=./a:./b:./c:./d:./e:./f ls
ANALYSIS.md  BUILD  CMakeLists.txt  COOKBOOK.md  README.md  include  scripts  src  test
DYLD_LIBRARY_PATH=./a:./b:./c:./d:./e:./f ls -G  0.00s user 0.01s system 82% cpu 0.012 total

this is particularly bad for the lookup of system libraries.

[ob]

But I'm surprised though: from our previous discussions, it seemed that you'd only see the slowdown in some machines and not others, and only after upgrading to Catalina? Those shouldn't influence how this works.

I think that was a bug in the version of Xcode that I was using / version of Catalina beta. I had one machine where this was extremely slow, 22 hours for a build. But the 15x difference between non-sandboxed and sandboxed builds has always been there.

[jmmv]

@allevato We'd easily poke a hole in the sandbox to share a cache across actions. Sure, mumble mumble sandboxing, but if the performance hit is so significant, and if it hits people by default, maybe we should do it. This wouldn't be that different from using workers actually.

[sgowroji]

Hi there! We're doing a clean up of old issues and will be closing this one. Please reopen if you’d like to discuss anything further. We’ll respond as soon as we have the bandwidth/resources to do so.

[brentleyjones]

This is still relevant.

[Kila2]

I found that when exec bazel builds. macos is listening to the bazel workspace and bazel-out directory. I don't think the bazel-out directory should be included here. ps: the watchfs option is false

[ktf]

Any update on this?

[Kila2]

We found a workaround: use a ramdisk or hdiutil to create a new tmp volume. Then, disable fseventsd for this volume to keep the CPU usage of the fseventsd process lower.