autoninja adds 0.2s overhead to builds |
|
Issue descriptionI 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.
,
Dec 10
s$ time python -c 'import uuid' real 0m0.039s user 0m0.021s sys 0m0.011s
,
Dec 10
So much for that theory. On Windows I get 0.12 s as the median result for: > tools\win\timeit python -c "import uuid"
,
Dec 11
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?
,
Dec 11
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 |
|
Comment 1 by brucedaw...@chromium.org
, Dec 10