ninja on mac really slow?

[Jeremy Apthorp]

I'm seeing no-op builds take 45 seconds:

$ time ninja -C out/Debug chrome

ninja: Entering directory `out/Debug'

ninja: no work to do.

ninja -C out/Debug chrome  1.24s user 0.98s system 4% cpu 45.403 total

and one-file change builds taking nearly 2 minutes:

$ time ninja -C out/Debug chrome

ninja: Entering directory `out/Debug'

[12/12] STAMP Chromium.app

ninja -C out/Debug chrome  25.94s user 7.40s system 29% cpu 1:54.80 total

this is building a non-component build, so I expect the link to take a while. But why is the no-op build so slow? It used to be only a few seconds. It feels like the files are never in cache.

I've only noticed this on Mountain Lion.

[Nico Weber]

Is your source directory excluded from virus scanners? Does Activity
Monitor show anything else hitting the disk? You can pass `-d stats`
to ninja to get some more detail where the time goes.

Empty builds should be ~0.88s on a system with an SSD and ~1.35s on a
system with a HDD in my experience. (I tried SSD just now and HDD four
days ago.)

Nico

> --
> --
> Chromium Developers mailing list: chromi...@chromium.org
> View archives, change email options, or unsubscribe:
> http://groups.google.com/a/chromium.org/group/chromium-dev
>
>
>

[Bernhard Bauer]

I'm seeing even worse times, on a regular HDD:

$ time ninja -d stats -C out/Debug -k 1000 chrome

ninja: Entering directory `out/Debug'

ninja: no work to do.

metric           count avg (us) total (ms)

.ninja parse     736   3823.0   2813.8

canonicalize str 138716 0.2     34.5

canonicalize path 1297265 0.2     230.5

lookup node       1297265 0.3     340.3

.ninja_log load   1     107519.0 107.5

node stat         42042 403.2   16952.4

depfile load     10488 8159.6   85578.0

path->node hash load 0.54 (52968 entries / 98317 buckets)

real 1m45.441s

user 0m1.653s

sys 0m2.629s

$ time ninja -d stats -C out/Debug -k 1000 chrome

ninja: Entering directory `out/Debug'

ninja: no work to do.

metric           count avg (us) total (ms)

.ninja parse     736   780.8   574.7

canonicalize str 138716 0.2     33.2

canonicalize path 1297265 0.1     176.7

lookup node       1297265 0.2     211.8

.ninja_log load   1     53183.0 53.2

node stat         42042 53.0     2227.6

depfile load     10488 80.2     841.1

path->node hash load 0.54 (52968 entries / 98317 buckets)

real 0m3.565s

user 0m1.126s

sys 0m0.550s

I suspect it's a disk caching issue; not sure why my cache seems to be evicted so often (I have several GB of RAM free) :-/

Bernhard.

[Nico Weber]

I can't reproduce this. I did a static debug build on my HDD mac pro,
and I'm getting empty build times of 1.4s and incremental build times
after changing an arbitrary file (net/base/keygen_handler.cc) of 48s.

Your best bet is probably to file an issue at http://crbug.com/new and
see if you can find hints what might cause this over time. (E.g. is
there anything in Console.app about "quarantine" or other
virus-scanner-related stuff?)

Nico

ps: Doing release component builds with dcheck_always_on=1
mac_strip_release=1 gives you binaries with symbols, dchecks, and
incremental build times that are more than 10x better.

[Rachel Blum]

I wanted to know, so I ran a few experiments, and it seems OSX disk cache is biting us. Running 'purge' guarantees a 100% repro case on my machine. Depfile loads will take around 90s, reproducibly. (Since we have 12K .d files, I wonder if https://github.com/martine/ninja/pull/258 will address that, but haven't tried yet)

Using less memory (i.e. no Chromium), and the depfiles are less likely to be evicted. This becomes worse over time - long running Chromium sessions seem to be correlated with more "inactive memory". (No, I have no proof of that, except cursing at my machine)

Since my machine has only 16GB, it might be more likely to exhibit said behavior.

 - rachel

[Nico Weber]

On Mon, Feb 11, 2013 at 5:48 PM, Rachel Blum <gr...@chromium.org> wrote:
> I wanted to know, so I ran a few experiments, and it seems OSX disk cache is
> biting us. Running 'purge' guarantees a 100% repro case on my machine.
> Depfile loads will take around 90s, reproducibly. (Since we have 12K .d
> files, I wonder if https://github.com/martine/ninja/pull/258 will address
> that, but haven't tried yet)

Uncached empty builds are closer to 40s for me. Anything in
Console.app? Is your disk really full?

[Jeremy Apthorp]

I'm also getting open2: fork failed: Resource temporarily unavailable at ../bindings/scripts/preprocessor.pm line 80 sometimes on a full build.

I don't have any virus scanners running. My disk is relatively empty. I have 12GB of RAM, about half active. Not seeing anything interesting in Console.

[Nico Weber]

On Mon, Feb 11, 2013 at 6:14 PM, Jeremy Apthorp <jer...@google.com> wrote:
> I'm also getting open2: fork failed: Resource temporarily unavailable at
> ../bindings/scripts/preprocessor.pm line 80 sometimes on a full build.

I get this one on my 10.6 box sometimes too, probably due to the low
process limit on 10.6. Building again makes things go again. I've
never seen this on 10.7 or 10.8.

[Jeremy Apthorp]

This is on 10.8. Building again fixes it.

[Rachel Blum]

Nothing in console.app. I would expect it depends a little bit on the target, and the build setup. In my case, I was building unit_tests - building Chrome drops it down to 1m11s. (Release, component_build).  HDD usage is 33%. 

Given that my Mac is 2 years old, I'm willing to chalk up the rest of the difference to a slower HDD.

 - rachel

[Nico Weber]

On Mon, Feb 11, 2013 at 6:27 PM, Rachel Blum <gr...@chromium.org> wrote:
> Nothing in console.app. I would expect it depends a little bit on the
> target, and the build setup. In my case, I was building unit_tests -
> building Chrome drops it down to 1m11s. (Release, component_build). HDD
> usage is 33%.
>
> Given that my Mac is 2 years old, I'm willing to chalk up the rest of the
> difference to a slower HDD.

My Mac is 2.5 years old too. I'm not sure newer Mac Pros exist :-P

[Rachel Blum]

As for console.app, I'm seeing 

2/11/13 6:25:29.100 PM mdworker[91685]: Unable to talk to lsboxd

2/11/13 6:25:30.000 PM kernel[0]: Sandbox: sandboxd(91701) deny mach-lookup com.apple.coresymbolicationd

2/11/13 6:25:37.940 PM sandboxd[91701]: ([91685]) mdworker(91685) deny mach-lookup com.apple.ls.boxd

 - rachel

On Mon, Feb 11, 2013 at 6:09 PM, Nico Weber <tha...@chromium.org> wrote: