gradle / gradle-profiler

A tool for gathering profiling and benchmarking information for Gradle builds
Apache License 2.0
1.4k stars 155 forks source link

Build time peak on every 4th iteration #348

Open wrozwad opened 3 years ago

wrozwad commented 3 years ago

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?

jonnycaley commented 2 years ago

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

Screenshot 2022-02-01 at 09 19 42
asodja commented 2 years ago

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.

jonnycaley commented 2 years ago

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
lptr commented 2 years ago

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

jonnycaley commented 2 years ago

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