gradle-profiler icon indicating copy to clipboard operation
gradle-profiler copied to clipboard

Build time peak on every 4th iteration

Open wrozwad opened this issue 3 years ago • 5 comments

I observe strange behavior because on every 4th clean build iteration I receive 10-30% build time peak. It occurs only on long time builds for at least 3 mins. image

I run this benchmark via:

gradle-profiler --benchmark --scenario-file build-time_clean-change.scen

with this scenario:

clean_build_change {
    title = "Clean Build with changes Xmx12g"
    tasks = [":app:buildDebug"]
    gradle-args = ["--parallel"]
    cleanup-tasks = ["clean"]
    jvm-args = ["-Xmx12g"]
	
    warm-ups = 4
    iterations = 10
	
    apply-abi-change-to = "app/src/main/java/com/awesome/app/MainActivity.kt"
    apply-android-resource-change-to = "app/src/main/res/values/strings.xml"
}

Tested on hardware: i7-8550U, 256 GB SSD (Toshiba 2280), 16 GB DDR4

I tried to use different -Xmx parameter but without any significant changes. Did you have any other suggestions?

wrozwad avatar Aug 10 '21 20:08 wrozwad

I've seen this happen from time to time as well

Screenshot 2022-02-01 at 09 19 42

jonnycaley avatar Feb 04 '22 16:02 jonnycaley

My first guess would be that gc kicks in, so there is a gc pause. And then JVM increases the heap size and it's better on the next runs. I would suggest you also set -Xms (initial heap size), since -Xmx is just the maximum heap that process can use and JVM starts with much less at the beginning (I don't know from my head what is the default value for the -Xms).

You can also try to use --measure-gc for gradle-profiler so you can see some gc benchmarks.

asodja avatar Feb 04 '22 19:02 asodja

Thanks for the advice @asodja

I added the --measure-gc flag and frequently get a significantly higher build time around the 7th iteration 🤔 It doesn't look like it has anything to do with the gc from the statistics Screenshot 2022-02-15 at 08 23 36

jonnycaley avatar Feb 15 '22 08:02 jonnycaley

Can you share the complete HTML perhaps? Data from the 8th iteration is not visible on your screenshot.

lptr avatar Feb 15 '22 13:02 lptr

Hey, yeh in hindsight I should have done that in the first place as my comment wasn't very helpful, my bad 🤦

I managed to figure out it was due to the remote build caches being enabled, and for whatever reason these increase builds were taking longer than usual to upload to the remote cache.

Normal build Longer build
Screenshot 2022-02-15 at 14 03 27 copy Screenshot 2022-02-15 at 14 03 31 copy

I cannot say this is the reason for the original author of this issue but what I will suggest trying is the same steps I took to work it out:

  1. Enable gradle scans for the benchmarks by adding gradle-args = ["--scan"] to each scenario
  2. Add this to root project build.gradle to accept the terms and conditions automatically
  3. Run the benchmarks and once they are complete find out which one has a spike (in my case above it was measurement 8)
  4. Go to the generated profile.log file search for Publishing build scan... until you find the one associated with the anomaly build
  5. Use the link to open the build scan and try to work it out from the build timeline. I also found opening another scan of a build that took an expected amount of time to compare the differences and help narrow it down

jonnycaley avatar Feb 15 '22 14:02 jonnycaley