New issue
Advanced search Search tips

Issue 913575 link

Starred by 2 users

Issue metadata

Status: Untriaged
Owner: ----
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug



Sign in to add a comment

autoninja adds 0.2s overhead to builds

Project Member Reported by thakis@chromium.org, Dec 10

Issue description

I was hacking on some (small) project and noticed that an empty build was taking much longer than it should:


Nicos-MacBook-Pro:llvm-mono-2 thakis$ time autoninja -C out/gn   -k 0
/Users/thakis/src/depot_tools/ninja -C out/gn -k 0 -j 160
ninja: Entering directory `out/gn'
ninja: no work to do.

real	0m0.255s
user	0m0.142s
sys	0m0.078s


I got really worried for a while, until I noticed this was due to autoninja:

Nicos-MacBook-Pro:llvm-mono-2 thakis$ time ninja -C out/gn   -k 0
ninja: Entering directory `out/gn'
ninja: no work to do.

real	0m0.062s
user	0m0.037s
sys	0m0.017s



I thought that this is probably because autoninja uses python and python has fairly large startup costs, but it's not just that:

Nicos-MacBook-Pro:llvm-mono-2 thakis$ time python -c 'import sys'

real	0m0.031s
user	0m0.015s
sys	0m0.009s



We try (and currently mostly fail) to keep no-op builds of chrome build targets at < 1s, so this is a pretty large chunk of that budget.


Obviously 0.2s isn't the end of the world, but it's large enough overhead that I noticed it.
 
Cc: yyanagisawa@chromium.org
On Windows the majority of the slowdown is from this line in autoninja.bat:

FOR /f "usebackq tokens=*" %%a in (`python -c "import uuid; print uuid.uuid4()"`) do set AUTONINJA_BUILD_ID=%%a

That adds about 0.15-0.2 s, or half of the total cost, with a lot of that coming from "import uuid", although there's enough noise in my measurements that I should avoid giving too much precision. The equivalent code on OSX is probably causing much of the cost.

s$ time python -c 'import uuid'

real	0m0.039s
user	0m0.021s
sys	0m0.011s

So much for that theory. On Windows I get 0.12 s as the median result for:

> tools\win\timeit python -c "import uuid"
I did not think "python -c 'import uuid; print uuid.uuid4()'" brings 0.2s overhead but let me check.  On my Linux machine, I can see the result like this:

$ time python -c 'import uuid; print uuid.uuid4()'
53c34051-1552-4011-a500-6621bff1ab6f

real	0m0.032s
user	0m0.022s
sys	0m0.010s

I should say getting AUTONINJA_BUILD_ID brings ~0.03s extra time to Linux build.

$ time python ~/depot_tools/autoninja.py ninja -C out/Release
/usr/local/google/home/yyanagisawa/depot_tools/ninja ninja -C out/Release -j 240

real	0m0.024s
user	0m0.020s
sys	0m0.004s

I am a bit surprised that just importing uuid module and execute uuid.uuid4() is a bit slower than autoninja.py.

Then, how is overhead to print random string?

$ time python -c 'import string;import random; print "".join([random.SystemRandom().choice(string.ascii_letters) for _ in range(64)])'
kyyevvvhJikMsFlHzCzkrCJoyKBggSNyNWUXoHesQqVTuvAKMPAOfCRFBJvLzpsQ

real	0m0.023s
user	0m0.014s
sys	0m0.009s

If 0.01s really matters, using this way for AUTONINJA_BUILD_ID can be the choice.

Let me check other autoninja.py performance.

$ time python ~/depot_tools/autoninja.py ninja -C out/Release -t clean
/usr/local/google/home/yyanagisawa/depot_tools/ninja ninja -C out/Release -t clean

real	0m0.023s
user	0m0.011s
sys	0m0.012s

How is the overhead to read out/Release/args.gn?

$ GOMA_DISABLED=true sh -c "time python ~/depot_tools/autoninja.py ninja -C out/Release -t clean"
/usr/local/google/home/yyanagisawa/depot_tools/ninja ninja -C out/Release -t clean

real	0m0.020s
user	0m0.012s
sys	0m0.008s


How it affects to build base_unittests with nothing to build?

$ time autoninja -C out/Release base_unittests
/usr/local/google/home/yyanagisawa/depot_tools/ninja -C out/Release base_unittests -j 240
ninja: Entering directory `out/Release'
ninja: no work to do.

real	0m1.462s
user	0m1.206s
sys	0m0.258s

$ time ninja -C out/Release base_unittests
ninja: Entering directory `out/Release'
ninja: no work to do.

real	0m1.378s
user	0m1.136s
sys	0m0.241s

It seems to ~0.1s overhead.  However, compare to time consumed for other place (1.3s or more), people might not notice.

By the way, fork exec overhead for python and shell.
$ time python -c ''

real	0m0.016s
user	0m0.016s
sys	0m0.000s

$ cat /tmp/foo.sh 
#!/usr/bin/env bash
exit

$ time /tmp/foo.sh

real	0m0.004s
user	0m0.000s
sys	0m0.004s

$ time dirname -- $0
.

real	0m0.002s
user	0m0.002s
sys	0m0.001s

Then, if we can make ninja to do what autoninja do now, we can at least omit 0.04s?
Huh, apparently the majority of the overhead on my system isn't in python but in the shell wrapper?


# Note: For the following to work I had  to add `#!/usr/bin/env python` to the top of autoninja.py
Nicos-MacBook-Pro:llvm-mono-2 thakis$ time ~/src/depot_tools/autoninja.py -C out/gn   -k 0
/Users/thakis/src/depot_tools/ninja -C out/gn -k 0 -j 160

real	0m0.057s
user	0m0.029s
sys	0m0.018s
Nicos-MacBook-Pro:llvm-mono-2 thakis$ time ~/src/depot_tools/autoninja.py -C out/gn   -k 0
/Users/thakis/src/depot_tools/ninja -C out/gn -k 0 -j 160

real	0m0.059s
user	0m0.030s
sys	0m0.019s


Nicos-MacBook-Pro:llvm-mono-2 thakis$ time autoninja -C out/gn   -k 0
/Users/thakis/src/depot_tools/ninja -C out/gn -k 0 -j 160
ninja: Entering directory `out/gn'
ninja: no work to do.

real	0m0.252s
user	0m0.142s
sys	0m0.076s
Nicos-MacBook-Pro:llvm-mono-2 thakis$ time ~/src/depot_tools/autoninja -C out/gn   -k 0
/Users/thakis/src/depot_tools/ninja -C out/gn -k 0 -j 160
ninja: Entering directory `out/gn'
ninja: no work to do.

real	0m0.248s
user	0m0.140s
sys	0m0.076s
Nicos-MacBook-Pro:llvm-mono-2 thakis$ time ~/src/depot_tools/autoninja -C out/gn   -k 0
/Users/thakis/src/depot_tools/ninja -C out/gn -k 0 -j 160
ninja: Entering directory `out/gn'
ninja: no work to do.

real	0m0.254s
user	0m0.143s
sys	0m0.078s

Sign in to add a comment