Build cache print out missing 'from cache' even though they are fetched from cache

wisechengyi · 2017-07-07 22:01:41 UTC

Example output

:lib:core:util:java:common:compileKotlin
:tools:checkstyle-rules:processResources NO-SOURCE
:lib:core:util:java:common:compileJava FROM-CACHE
:tools:checkstyle-rules:compileKotlin
:lib:core:util:java:common:copyMainKotlinClasses
:lib:core:util:java:common:processResources NO-SOURCE
:lib:core:util:java:common:classes UP-TO-DATE
:lib:core:util:java:common:jar
:tools:checkstyle-rules:compileJava FROM-CACHE
:tools:checkstyle-rules:copyMainKotlinClasses
:tools:checkstyle-rules:classes UP-TO-DATE
:tools:checkstyle-rules:jar
:app:example:checkstyle
:lib:legacy:checkstyle
:lib:legacy-test:checkstyle
:tools:android-junit-report:checkstyle
:tools:checkstyle-rules:checkstyle
:lib:core:annotation-processors:checkstyle
:lib:core:performance-metrics:checkstyle
:lib:third-party:fabric:checkstyle
:tools:checkstyle-rules:checkstyle FROM-CACHE
:lib:third-party:phone-number:checkstyle
:lib:core:annotation-processors:checkstyle FROM-CACHE
:lib:third-party:robolectric:checkstyle FROM-CACHE
:lib:example:repositories:checkstyle
:lib:third-party:fabric:checkstyle FROM-CACHE
:tools:lint:detectors:checkstyle
:lib:third-party:phone-number:checkstyle FROM-CACHE
:tools:lint:java:checkstyle NO-SOURCE
:lib:core:app:common:checkstyle
:tools:android-junit-report:checkstyle FROM-CACHE
:lib:core:app:common-java:checkstyle FROM-CACHE
:lib:core:app:compiler:checkstyle
:lib:core:performance-metrics:checkstyle FROM-CACHE
:lib:core:async:common:checkstyle
:lib:core:app:compiler:checkstyle FROM-CACHE
:lib:core:async:http:checkstyle
:tools:lint:detectors:checkstyle FROM-CACHE
:lib:core:config:featureswitches:checkstyle
:lib:core:async:http:checkstyle FROM-CACHE
:lib:example:repositories:checkstyle FROM-CACHE
:lib:core:database:common:checkstyle
:lib:core:database:compiler:checkstyle
:lib:core:async:common:checkstyle FROM-CACHE
:app:example:checkstyle FROM-CACHE
:lib:core:database:lru:checkstyle
:lib:core:database:util:checkstyle
:lib:core:config:featureswitches:checkstyle FROM-CACHE
:lib:core:media:common:checkstyle
:lib:core:app:common:checkstyle FROM-CACHE
:lib:core:database:lru:checkstyle FROM-CACHE
:lib:core:media:opencl-metrics:checkstyle
:lib:core:media:superresolution:checkstyle
:lib:core:database:util:checkstyle FROM-CACHE
:lib:core:media:ui:checkstyle
:lib:core:database:compiler:checkstyle FROM-CACHE
:lib:core:media:opencl-metrics:checkstyle FROM-CACHE
:lib:core:model:collection:checkstyle
:lib:core:model:json:checkstyle
:lib:core:database:common:checkstyle FROM-CACHE
:lib:core:model:json-compiler:checkstyle
:lib:core:media:superresolution:checkstyle FROM-CACHE
:lib:core:network:common:checkstyle
:lib:core:model:collection:checkstyle FROM-CACHE
:lib:core:model:json-compiler:checkstyle FROM-CACHE
:lib:core:network:narc:checkstyle
:lib:core:repositories:common:checkstyle
:lib:core:model:json:checkstyle FROM-CACHE
:lib:core:ui:adapters:checkstyle
:lib:core:media:ui:checkstyle FROM-CACHE
:lib:core:ui:autocomplete:checkstyle
:lib:core:network:narc:checkstyle FROM-CACHE
:lib:core:ui:components:checkstyle
:lib:core:ui:autocomplete:checkstyle FROM-CACHE
:lib:core:ui:navigation:checkstyle
:lib:core:repositories:common:checkstyle FROM-CACHE
:lib:example:analytics:annotations:checkstyle
:lib:core:media:common:checkstyle FROM-CACHE
:lib:core:ui:adapters:checkstyle FROM-CACHE
:lib:example:analytics:common:checkstyle
:lib:example:analytics:features:checkstyle
:lib:example:analytics:annotations:checkstyle FROM-CACHE
:lib:example:api:common:checkstyle
:lib:core:ui:navigation:checkstyle FROM-CACHE
:lib:example:api:legacy:checkstyle
:lib:example:api:common:checkstyle FROM-CACHE
:lib:example:app:common:checkstyle
:lib:legacy-test:checkstyle FROM-CACHE
:lib:example:config:featureswitches:checkstyle
:lib:example:analytics:common:checkstyle FROM-CACHE
:lib:example:database:legacy:checkstyle
:lib:core:network:common:checkstyle FROM-CACHE
:lib:example:database:schema:checkstyle
:lib:example:analytics:features:checkstyle FROM-CACHE
:lib:example:database:store:checkstyle
:lib:example:config:featureswitches:checkstyle FROM-CACHE
:lib:example:features:connect:checkstyle
:lib:example:app:common:checkstyle FROM-CACHE
:lib:example:features:contacts:checkstyle
:lib:example:features:connect:checkstyle FROM-CACHE
:lib:example:database:store:checkstyle FROM-CACHE
:lib:example:features:debug-assets:checkstyle
:lib:example:features:legacy:checkstyle
:lib:example:features:debug-assets:checkstyle NO-SOURCE
:lib:example:features:onboarding:checkstyle
:lib:example:features:contacts:checkstyle FROM-CACHE
:lib:example:features:search:checkstyle FROM-CACHE
:lib:example:media:common:checkstyle
:lib:example:database:schema:checkstyle FROM-CACHE
:lib:example:media:ui:checkstyle
:lib:core:ui:components:checkstyle FROM-CACHE
:lib:example:model:json:checkstyle
:lib:example:media:common:checkstyle FROM-CACHE
:lib:example:model:objects:checkstyle
:lib:example:features:onboarding:checkstyle FROM-CACHE
:lib:example:media:ui:checkstyle FROM-CACHE
:lib:example:network:common:checkstyle
:lib:example:network:oauth:checkstyle
:lib:legacy:checkstyle FROM-CACHE
:lib:example:subsystems:cards:checkstyle
:lib:example:network:oauth:checkstyle FROM-CACHE
:lib:example:subsystems:dm:checkstyle
:lib:example:database:legacy:checkstyle FROM-CACHE
:lib:example:subsystems:geo:checkstyle
:lib:example:network:common:checkstyle FROM-CACHE
:lib:example:subsystems:legacy-base-classes:checkstyle
:lib:example:subsystems:geo:checkstyle FROM-CACHE
:lib:example:subsystems:navigation:checkstyle
:lib:example:subsystems:cards:checkstyle FROM-CACHE
:lib:example:subsystems:tweet-view:checkstyle
:lib:example:subsystems:dm:checkstyle FROM-CACHE
:lib:example:ui:components:checkstyle
:lib:example:subsystems:legacy-base-classes:checkstyle FROM-CACHE
:lib:example:ui:dock:checkstyle
:lib:example:subsystems:navigation:checkstyle FROM-CACHE
:lib:example:ui:renderable:checkstyle
:lib:example:subsystems:tweet-view:checkstyle FROM-CACHE
:lib:core:media:av:player:checkstyle
:lib:example:ui:renderable:checkstyle FROM-CACHE
:lib:core:test:app:common:checkstyle
:lib:example:api:legacy:checkstyle FROM-CACHE
:lib:core:test:database:fixtures:checkstyle
:lib:core:test:app:common:checkstyle FROM-CACHE
:lib:core:test:util:java:checkstyle
:lib:core:test:database:fixtures:checkstyle FROM-CACHE
:lib:core:util:android:common:checkstyle
:lib:example:ui:dock:checkstyle FROM-CACHE
:lib:core:util:android:geo:checkstyle
:lib:example:ui:components:checkstyle FROM-CACHE
:lib:core:util:android:io:checkstyle
:lib:core:test:util:java:checkstyle FROM-CACHE
:lib:core:util:android:play-services:checkstyle FROM-CACHE
:lib:core:util:android:geo:checkstyle FROM-CACHE
:lib:core:util:compiler:auto-service:checkstyle
:lib:core:util:compiler:common:checkstyle
:lib:core:util:android:io:checkstyle FROM-CACHE
:lib:core:util:java:app:checkstyle
:lib:core:util:compiler:auto-service:checkstyle FROM-CACHE
:lib:core:util:java:common:checkstyle
:lib:core:util:android:common:checkstyle FROM-CACHE
:lib:core:util:java:io:checkstyle
:lib:core:util:compiler:common:checkstyle FROM-CACHE
:lib:core:util:java:serialization:checkstyle FROM-CACHE
:lib:example:api:model:json:checkstyle
:lib:core:util:java:app:checkstyle FROM-CACHE
:lib:example:api:model:objects:checkstyle
:lib:core:util:java:io:checkstyle FROM-CACHE
:lib:example:features:moments:core:checkstyle
:lib:example:api:model:objects:checkstyle FROM-CACHE
:lib:example:api:model:json:checkstyle FROM-CACHE
:lib:core:util:java:common:checkstyle FROM-CACHE
:lib:example:features:moments:maker:checkstyle
:lib:example:test:model:objects:checkstyle
:lib:example:ui:navigation:core:checkstyle FROM-CACHE
:lib:example:ui:navigation:drawer:checkstyle
:lib:core:media:av:player:checkstyle FROM-CACHE
:lib:core:media:av:model:objects:checkstyle
:lib:example:features:moments:maker:checkstyle FROM-CACHE
:lib:core:test:util:android:common:checkstyle
:lib:example:ui:navigation:drawer:checkstyle FROM-CACHE
:lib:example:features:moments:core:checkstyle FROM-CACHE
:lib:core:media:av:model:objects:checkstyle FROM-CACHE
:lib:core:test:util:android:common:checkstyle FROM-CACHE
:lib:example:model:json:checkstyle FROM-CACHE
:lib:example:test:model:objects:checkstyle FROM-CACHE
:lib:example:model:objects:checkstyle FROM-CACHE
:lib:example:features:legacy:checkstyle FROM-CACHE

BUILD SUCCESSFUL in 8s
97 actionable tasks: 6 executed, 91 from cache

For example :lib:core:test:util:java:checkstyle, it is actually fetched from cache, but does not have the correct status with it, which makes things a bit confusing. I had to go to the build scan in order to make sure that was the case.

$ ./gradlew -v

------------------------------------------------------------
Gradle 4.0
------------------------------------------------------------

Build time:   2017-06-14 15:11:08 UTC
Revision:     316546a5fcb4e2dfe1d6aa0b73a4e09e8cecb5a5

Groovy:       2.4.11
Ant:          Apache Ant(TM) version 1.9.6 compiled on June 29 2015
JVM:          1.8.0_131 (Oracle Corporation 25.131-b11)
OS:           Mac OS X 10.12.5 x86_64

sterling · 2017-07-07 22:25:53 UTC

This is a “feature” when using plain console output and parallel execution.

:lib:core:test:util:java:checkstyle is listed twice, once when the task starts and once when it finishes. It only says FROM-CACHE the second time.

wisechengyi · 2017-07-07 22:28:22 UTC

Interesting. Do you think the ‘feature’ can be removed? It is quite confusing especially when the output is long. Printing each task once is good enough.

sterling · 2017-07-08 00:00:56 UTC

It may, but we’re spending more time on rich console output, which doesn’t have this problem.

It’s a trade-off with how to show concurrent tasks and what’s currently happening when we are not connected to a console and can’t use ANSI codes to show something fancier. We need to be able to show “task :foo has started”, otherwise you’ll have no indication of what’s going on with long running tasks.

jjustinic · 2017-07-08 04:51:11 UTC

Your explanation of the design and priorities make sense, but I think the last sentence just convinced me there is an implementation bug based on the output provided by the OP. There are four outcomes represented and the design seems to dictate at least one of them will be duplicated, but it feels like it’s the wrong one.

The first two are easy:

NO-SOURCE - absolutely nothing to do, log it as such and move on; no duplication
UP-TO-DATE - nothing to do because all the inputs and outputs are correct, log it and move on; no duplication.

For the next two, when work needs to be done (or retrieved), it seems like the tasks that actually executed would be the ones logged twice, once on start and once on finish. However the executed tasks are logged once (when they complete it seems), and the tasks from cache are logged twice, once on start and once when complete with the FROM-CACHE status.

Based on your explanation, it seems like the intended logging logic is there for both cases, but in checking for the cache hit vs. execution is negated (or not) incorrectly.

sterling · 2017-07-08 14:30:45 UTC

That’s only because NO-SOURCE and UP-TO-DATE are usually very quick to finish before another task starts/finishes. There’s nothing that prevents all tasks from being duplicated if just the right combination of tasks start/finish at the right time.

FROM-CACHE usually takes longer (because it does everything that the NO-SOURCE and UP-TO-DATE outcomes have done plus downloading/unpacking something from the cache), but there’s nothing special about it.

All tasks are logged twice (start and finish). If the task completes before any other task starts/finishes or any other output is logged, we de-duplicate the lines and only show one line with the outcome.

You can see this in action with a task with an outcome of NO-SOURCE with this (gradle --console=plain compileJava):

apply plugin: 'java'

compileJava {
   source {
     println "interruption"
     file("src/main/another")
   }
}