cake
cake copied to clipboard
cake-build
Cake Build Tool's Startup is Slow - 25s (64% overhead)
What You Are Seeing?
When I clone the example repo, and time the build command, there is A LOT of overhead time on the build even after repeated builds so it has had a chance to download everything and cache anything. That is, a lot of the time is spent loading cake and compiling the build script. See below for exact numbers.
What is Expected?
There should be less than a couple seconds of overhead from the build tool. 25s might be acceptable for a build on a build server, but it is unacceptable for a workflow where you repeatedly run the build locally each time you need feedback on compilation errors. You can't be waiting half a minute for every build to even start.
What version of Cake are you using?
v0.28.0
Are you running on a 32 or 64 bit system?
64 Bit
What environment are you running on? Windows? Linux? Mac?
Windows 7 Pro
Are you running on a CI Server? If so, which one?
No
How Did You Get This To Happen? (Steps to Reproduce)
- Clone the example repo
- Run a build
./build.ps1, ignore the timing of this build, it is downloading things for the first time etc. - Run a second build using the powershell command to time it
Measure-Command { ./build.ps1 -Verbosity Verbose -Verbose | Out-Host }
The end of the build output is:
Task Duration
--------------------------------------------------
Clean 00:00:00.0557395
Restore-NuGet-Packages 00:00:02.5100364
Build 00:00:07.7906003
Run-Unit-Tests 00:00:03.5055638
Default 00:00:00.0071490
--------------------------------------------------
Total: 00:00:13.8690890
Days : 0
Hours : 0
Minutes : 0
Seconds : 38
Milliseconds : 407
Ticks : 384074655
TotalDays : 0.000444530850694444
TotalHours : 0.0106687404166667
TotalMinutes : 0.640124425
TotalSeconds : 38.4074655
TotalMilliseconds : 38407.4655
You can see that Cake reported 13.8s total time. But powershell reported 38.4s total time. A difference of almost 25s. Almost all of which comes during the startup of cake. Repeated runs show similar results.
Your development machine may be faster reducing the pain, but it still shouldn't be 64% of the total time.
I feel this pain. This has been pushing me recently toward the idea of precompiling binaries and distributing them via NuGet feed, turning the Cake script into a glorified settings file.
I cloned repo tried the same on my Machine, first run
time ./build.sh
Task Duration
--------------------------------------------------
Clean 00:00:00.0055274
Restore-NuGet-Packages 00:00:02.5795448
Build 00:00:02.1711037
Run-Unit-Tests 00:00:01.2189825
Default 00:00:00.0001979
--------------------------------------------------
Total: 00:00:05.9753563
./build.sh 9.44s user 1.59s system 83% cpu 13.266 total
Next run
Task Duration
--------------------------------------------------
Clean 00:00:00.0054196
Restore-NuGet-Packages 00:00:02.3709420
Build 00:00:00.7348149
Run-Unit-Tests 00:00:01.1956039
Default 00:00:00.0002194
--------------------------------------------------
Total: 00:00:04.3069998
./build.sh 6.96s user 0.71s system 98% cpu 7.773 total
WIthout bootstrapper
Task Duration
--------------------------------------------------
Clean 00:00:00.0093852
Restore-NuGet-Packages 00:00:02.3830687
Build 00:00:00.7219495
Run-Unit-Tests 00:00:01.1815667
--------------------------------------------------
Total: 00:00:04.2963833
cake build.cake 6.20s user 0.62s system 98% cpu 6.928 total
My results on a clean clone of the repository on a 4G mobile connection (I'm currently at a Café).
> time ./build.sh
[OMITTED]
Task Duration
--------------------------------------------------
Clean 00:00:00.0038619
Restore-NuGet-Packages 00:00:03.4260819
Build 00:00:01.4021285
Run-Unit-Tests 00:00:00.8172034
Default 00:00:00.0001519
--------------------------------------------------
Total: 00:00:05.6494276
./build.sh 8,46s user 0,98s system 60% cpu 15,629 total
Tried on a Windows Machine i7 2.8GHz no SSD, previous was on a Mac Pro 2016
1st run
Measure-Command { .\build.ps1 }
Days : 0
Hours : 0
Minutes : 0
Seconds : 11
Milliseconds : 358
Ticks : 113589104
TotalDays : 0.00013146887037037
TotalHours : 0.00315525288888889
TotalMinutes : 0.189315173333333
TotalSeconds : 11.3589104
TotalMilliseconds : 11358.9104
2nd run
Measure-Command { .\build.ps1 }
Days : 0
Hours : 0
Minutes : 0
Seconds : 9
Milliseconds : 505
Ticks : 95059788
TotalDays : 0.000110022902777778
TotalHours : 0.00264054966666667
TotalMinutes : 0.15843298
TotalSeconds : 9.5059788
TotalMilliseconds : 9505.9788
Without bootstrapper
Days : 0
Hours : 0
Minutes : 0
Seconds : 6
Milliseconds : 929
Ticks : 69299148
TotalDays : 8.02073472222222E-05
TotalHours : 0.00192497633333333
TotalMinutes : 0.11549858
TotalSeconds : 6.9299148
TotalMilliseconds : 6929.9148
Looking at the times where both a total from Cake and from timing the command were provided, even on the much faster machines than mine, it took 2s to 3.5s of overhead and this was 30%-40% of the total time. Also, while an up to date run build time of 7s is much better than what I'm getting on my machine. It is still a very long time if what you want to do is build frequently as you write code to get feedback and that is a starting number for a very simple build.
My concrete suggestions would be:
- Make the total time reported by cake include as much of the cake startup time as possible. i.e. start the timer first thing in the cake code. (This removes the feeling that you are crazy because the build seems to take longer than reported).
- Consider adding a step to the cake build task output for this initial start time
- Investigate whether it would be possible to cache the compilation of the build file similar to how python will cache in .pyc files.
- Profile Cake to make sure there isn't something that is needlessly wasting time
- Evaluate whether async code would allow things to be done in parrelel thereby reducing the wallclock time
If you want continuous real time builds it would probably make sense to have cake process running and have things in a loop, iterations triggered by i.e. user input, file watcher event etc.
Your suggestions sounds like good avenues to pursue, if you to we'll happily review your findings in a PR.
Near future the Cake team has other features prioritized, we might do some refactoring around roslyn script handling, but for now I'll mark this as up for grabs.
I got a new laptop:
- i7-8750H (6 cores)
- 16 GB RAM
- Everything on an NVMe SSD drive
- Plugged in so no throttling due to battery power
First run:
Task Duration
--------------------------------------------------
Clean 00:00:00.0074903
Restore-NuGet-Packages 00:00:03.1880764
Build 00:00:02.0895781
Run-Unit-Tests 00:00:00.8834263
Default 00:00:00.0027005
--------------------------------------------------
Total: 00:00:06.1712716
Days : 0
Hours : 0
Minutes : 0
Seconds : 22
Milliseconds : 813
Ticks : 228138695
TotalDays : 0.000264049415509259
TotalHours : 0.00633718597222222
TotalMinutes : 0.380231158333333
TotalSeconds : 22.8138695
TotalMilliseconds : 22813.8695
second run:
Task Duration
--------------------------------------------------
Clean 00:00:00.0134219
Restore-NuGet-Packages 00:00:01.6837056
Build 00:00:00.4692074
Run-Unit-Tests 00:00:00.7049643
Default 00:00:00.0016347
--------------------------------------------------
Total: 00:00:02.8729339
Days : 0
Hours : 0
Minutes : 0
Seconds : 6
Milliseconds : 712
Ticks : 67123516
TotalDays : 7.76892546296296E-05
TotalHours : 0.00186454211111111
TotalMinutes : 0.111872526666667
TotalSeconds : 6.7123516
TotalMilliseconds : 6712.3516
Additional runs show similar times.
While this is much faster overall, almost 4 seconds of overhead time seems totally ridiculous on a brand new, gaming laptop. Cake is 58% of the runtime for the second run. Perhaps the actual slow down is network?
@WalkerCodeRanger These are the same run from my Windows Laptop with about the same specs.
4 seconds "overhead" seems reasonable to me if you take into account what is done (processing files, checking nuget packages, compiling scripts, executing said script)
Task Duration
--------------------------------------------------
Clean 00:00:00.0056246
Restore-NuGet-Packages 00:00:01.0763986
Build 00:00:01.1507315
Run-Unit-Tests 00:00:00.7000715
Default 00:00:00.0014587
--------------------------------------------------
Total: 00:00:02.9342849
Days : 0
Hours : 0
Minutes : 0
Seconds : 8
Milliseconds : 568
Ticks : 85681928
TotalDays : 9.91688981481481E-05
TotalHours : 0.00238005355555556
TotalMinutes : 0.142803213333333
TotalSeconds : 8.5681928
TotalMilliseconds : 8568.1928
Second run:
Task Duration
--------------------------------------------------
Clean 00:00:00.0060150
Restore-NuGet-Packages 00:00:00.7813876
Build 00:00:00.3725292
Run-Unit-Tests 00:00:00.6247090
Default 00:00:00.0018488
--------------------------------------------------
Total: 00:00:01.7864896
Days : 0
Hours : 0
Minutes : 0
Seconds : 5
Milliseconds : 68
Ticks : 50683407
TotalDays : 5.86613506944444E-05
TotalHours : 0.00140787241666667
TotalMinutes : 0.084472345
TotalSeconds : 5.0683407
TotalMilliseconds : 5068.3407
@WalkerCodeRanger said... almost 4 seconds of overhead time seems totally ridiculous on a brand new,
Out of interest... what would you deem as acceptable?
This is what I got on a 2 year old Intel nuc i7 with SSD
First run:
Task Duration
--------------------------------------------------
Clean 00:00:00.0160194
Restore-NuGet-Packages 00:00:03.1897614
Build 00:00:02.8009840
Run-Unit-Tests 00:00:01.3675296
--------------------------------------------------
Total: 00:00:07.3757996
Days : 0
Hours : 0
Minutes : 0
Seconds : 17
Milliseconds : 922
Ticks : 179221536
TotalDays : 0.000207432333333333
TotalHours : 0.004978376
TotalMinutes : 0.29870256
TotalSeconds : 17.9221536
TotalMilliseconds : 17922.1536
Second run:
Task Duration
--------------------------------------------------
Clean 00:00:00.0168614
Restore-NuGet-Packages 00:00:01.7663950
Build 00:00:00.7507376
Run-Unit-Tests 00:00:01.0086823
--------------------------------------------------
Total: 00:00:03.5446485
Days : 0
Hours : 0
Minutes : 0
Seconds : 9
Milliseconds : 124
Ticks : 91245783
TotalDays : 0.000105608545138889
TotalHours : 0.00253460508333333
TotalMinutes : 0.152076305
TotalSeconds : 9.1245783
TotalMilliseconds : 9124.5783
Sure could be network related. Could be Antimalware/virus kicking in too, in those cases hard to optimize Cake for that.
I have nothing against better performance (and we'll happily look at taking contributions in this area), but IMHO think it's currently good enough for is to put focus elsewhere. Don't think it's totally unacceptable.
Reran it on another machine HP Envy i7, 8gbs ram and SSD First run:
Task Duration
--------------------------------------------------
Clean 00:00:00.0157910
Restore-NuGet-Packages 00:00:01.8415308
Build 00:00:01.8083681
Run-Unit-Tests 00:00:01.1041097
--------------------------------------------------
Total: 00:00:04.7712985
Days : 0
Hours : 0
Minutes : 0
Seconds : 13
Milliseconds : 344
Ticks : 133448886
TotalDays : 0.000154454729166667
TotalHours : 0.0037069135
TotalMinutes : 0.22241481
TotalSeconds : 13.3448886
TotalMilliseconds : 13344.8886
Second run
Task Duration
--------------------------------------------------
Clean 00:00:00.0173817
Restore-NuGet-Packages 00:00:01.5461378
Build 00:00:00.6896346
Run-Unit-Tests 00:00:00.9825372
--------------------------------------------------
Total: 00:00:03.2372046
Days : 0
Hours : 0
Minutes : 0
Seconds : 8
Milliseconds : 752
Ticks : 87528970
TotalDays : 0.000101306678240741
TotalHours : 0.00243136027777778
TotalMinutes : 0.145881616666667
TotalSeconds : 8.752897
TotalMilliseconds : 8752.897
Out-Host and console output could also have an effect on perf.
Doing a dotnet new console --no-restore
And then Measure-Command { dotnet run | Out-Host } on same machine
Days : 0
Hours : 0
Minutes : 0
Seconds : 2
Milliseconds : 382
Ticks : 23820180
TotalDays : 2.75696527777778E-05
TotalHours : 0.000661671666666667
TotalMinutes : 0.0397003
TotalSeconds : 2.382018
TotalMilliseconds : 2382.018
That's a zero dependency console application just containing
Console.WriteLine("Hello World!");
I'm currently using Cake in a large project with many subproject where the overhead (of 4 to 5 seconds) gets multiplied by the number of projects. Even if nothing has changed in any of the projects (thus no rebuild necessary and the build passes within milliseconds), This results in a built time of a few minutes when nothing has changed.
I'm seeing in the region of an overhead of ~2s compared per invocation after the first with cake 3.1.0, which is quite a lot on a modern machine
