"Opening cache" takes very long time


(Nils Weinander) #1

Any Gradle task hangs for a long time on “Opening cache outputFileStates.bin” (7 seconds last time) and “Opening cache fileHashes.bin” (59 seconds last time), is there a way around this?


(Stefan Malmesjö) #2

I’m working on the same project as Nils, and thought I could paste my logs. For me it takes sometimes over 2 minutes to open outputFileStates.bin. See at 16:37:34.385:

/Stefan

stefan@pauling:~/proj/altrusoft/workspace/entitymachine$ gradle --info --debug copyconf 16:37:29.214 [DEBUG] [org.gradle.logging.internal.DefaultLoggingConfigurer] Finished configuring with level: DEBUG, configurers: [org.gradle.logging.internal.OutputEventRenderer@479f43fa, org.gradle.logging.internal.logback.LogbackLoggingConfigurer@2927f6d2, org.gradle.logging.internal.JavaUtilLoggingConfigurer@7ebd6a19] 16:37:30.909 [DEBUG] [org.gradle.logging.internal.DefaultLoggingConfigurer] Finished configuring with level: DEBUG, configurers: [org.gradle.logging.internal.OutputEventRenderer@479f43fa, org.gradle.logging.internal.logback.LogbackLoggingConfigurer@2927f6d2, org.gradle.logging.internal.JavaUtilLoggingConfigurer@7ebd6a19] 16:37:30.910 [INFO] [org.gradle.BuildLogger] Starting Build 16:37:30.913 [DEBUG] [org.gradle.BuildLogger] Gradle user home: /home/stefan/.gradle 16:37:30.914 [DEBUG] [org.gradle.BuildLogger] Current dir: /home/stefan/proj/altrusoft/workspace/entitymachine 16:37:30.915 [DEBUG] [org.gradle.BuildLogger] Settings file: null 16:37:30.916 [DEBUG] [org.gradle.BuildLogger] Build file: null 16:37:30.947 [DEBUG] [org.gradle.initialization.BuildSourceBuilder] Starting to build the build sources. 16:37:30.950 [DEBUG] [org.gradle.initialization.BuildSourceBuilder] Gradle source dir does not exist. We leave. 16:37:30.952 [DEBUG] [org.gradle.initialization.DefaultGradlePropertiesLoader] Found env project properties: [] 16:37:30.954 [DEBUG] [org.gradle.initialization.DefaultGradlePropertiesLoader] Found system project properties: [] 16:37:31.147 [DEBUG] [org.gradle.api.internal.artifacts.mvnsettings.DefaultLocalMavenRepositoryLocator] No local repository in Settings file defined. Using default path: /home/stefan/.m2/repository 16:37:31.646 [DEBUG] [org.gradle.logging.internal.DefaultLoggingConfigurer] Finished configuring with level: DEBUG, configurers: [org.gradle.logging.internal.OutputEventRenderer@479f43fa, org.gradle.logging.internal.logback.LogbackLoggingConfigurer@2927f6d2, org.gradle.logging.internal.JavaUtilLoggingConfigurer@7ebd6a19] 16:37:31.652 [DEBUG] [org.gradle.logging.internal.DefaultLoggingConfigurer] Finished configuring with level: DEBUG, configurers: [org.gradle.logging.internal.OutputEventRenderer@479f43fa, org.gradle.logging.internal.logback.LogbackLoggingConfigurer@2927f6d2, org.gradle.logging.internal.JavaUtilLoggingConfigurer@7ebd6a19] 16:37:31.654 [DEBUG] [org.gradle.initialization.ScriptEvaluatingSettingsProcessor] Timing: Processing settings took: 0.698 secs 16:37:31.655 [INFO] [org.gradle.BuildLogger] Settings evaluated using empty settings script. 16:37:31.852 [DEBUG] [org.gradle.initialization.ProjectPropertySettingBuildLoader] Looking for project properties from: /home/stefan/proj/altrusoft/workspace/entitymachine/gradle.properties 16:37:31.854 [DEBUG] [org.gradle.initialization.ProjectPropertySettingBuildLoader] project property file does not exists. We continue! 16:37:31.856 [INFO] [org.gradle.BuildLogger] Projects loaded. Root project using build file ‘/home/stefan/proj/altrusoft/workspace/entitymachine/build.gradle’. 16:37:31.858 [INFO] [org.gradle.BuildLogger] Included projects: [root project ‘entitymachine’] 16:37:31.861 [INFO] [org.gradle.configuration.BuildScriptProcessor] Evaluating root project ‘entitymachine’ using build file ‘/home/stefan/proj/altrusoft/workspace/entitymachine/build.gradle’. 16:37:31.919 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on buildscript class cache for build file ‘/home/stefan/proj/altrusoft/workspace/entitymachine/build.gradle’ (/home/stefan/.gradle/caches/1.2/scripts/build_fdmudj3ad78p9baktlj3rc48v/ProjectScript/buildscript). 16:37:31.993 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired. 16:37:32.047 [DEBUG] [org.gradle.logging.internal.DefaultLoggingConfigurer] Finished configuring with level: DEBUG, configurers: [org.gradle.logging.internal.OutputEventRenderer@479f43fa, org.gradle.logging.internal.logback.LogbackLoggingConfigurer@2927f6d2, org.gradle.logging.internal.JavaUtilLoggingConfigurer@7ebd6a19] 16:37:32.050 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on no_buildscript class cache for build file ‘/home/stefan/proj/altrusoft/workspace/entitymachine/build.gradle’ (/home/stefan/.gradle/caches/1.2/scripts/build_fdmudj3ad78p9baktlj3rc48v/ProjectScript/no_buildscript). 16:37:32.051 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired. 16:37:34.019 [DEBUG] [org.gradle.api.internal.artifacts.mvnsettings.DefaultLocalMavenRepositoryLocator] No local repository in Settings file defined. Using default path: /home/stefan/.m2/repository 16:37:34.146 [DEBUG] [org.gradle.api.internal.tasks.execution.ExecuteAtMostOnceTaskExecuter] Starting to execute task ‘:copySettings’ 16:37:34.256 [DEBUG] [org.gradle.api.internal.tasks.execution.SkipUpToDateTaskExecuter] Determining if task ‘:copySettings’ is up-to-date 16:37:34.258 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire exclusive lock on task artifact state cache (/home/stefan/proj/altrusoft/workspace/entitymachine/.gradle/1.2/taskArtifacts). 16:37:34.259 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired. 16:37:34.292 [DEBUG] [org.gradle.cache.internal.btree.BTreePersistentIndexedCache] Opening cache taskArtifacts.bin (/home/stefan/proj/altrusoft/workspace/entitymachine/.gradle/1.2/taskArtifacts/taskArtifacts.bin) 16:37:34.382 [DEBUG] [org.gradle.api.internal.changedetection.DefaultFileCacheListener] Can cache files for directory ‘/home/stefan/proj/altrusoft/workspace/entitymachine/src/main/resources/home’ 16:37:34.383 [DEBUG] [org.gradle.api.internal.changedetection.DefaultFileCacheListener] Can cache files for file ‘/home/stefan/se.altrusoft.entitymachine’ 16:37:34.385 [DEBUG] [org.gradle.cache.internal.btree.BTreePersistentIndexedCache] Opening cache outputFileStates.bin (/home/stefan/proj/altrusoft/workspace/entitymachine/.gradle/1.2/taskArtifacts/outputFileStates.bin) 16:39:56.207 [DEBUG] [org.gradle.cache.internal.btree.BTreePersistentIndexedCache] Opening cache fileHashes.bin (/home/stefan/proj/altrusoft/workspace/entitymachine/.gradle/1.2/taskArtifacts/fileHashes.bin) 16:40:24.134 [DEBUG] [org.gradle.cache.internal.btree.BTreePersistentIndexedCache] Opening cache fileSnapshots.bin (/home/stefan/proj/altrusoft/workspace/entitymachine/.gradle/1.2/taskArtifacts/fileSnapshots.bin) 16:40:24.548 [INFO] [org.gradle.api.internal.changedetection.DefaultTaskArtifactStateRepository] Skipping task ‘:copySettings’ as it is up-to-date. 16:40:24.549 [INFO] [org.gradle.api.internal.tasks.execution.SkipUpToDateTaskExecuter] Skipping task ‘:copySettings’ as it is up-to-date 16:40:24.550 [DEBUG] [org.gradle.api.internal.tasks.execution.ExecuteAtMostOnceTaskExecuter] Finished executing task ‘:copySettings’ 16:40:24.551 [DEBUG] [org.gradle.api.internal.tasks.execution.ExecuteAtMostOnceTaskExecuter] Starting to execute task ‘:copySolrConf’ 16:40:24.579 [DEBUG] [org.gradle.api.internal.tasks.execution.SkipUpToDateTaskExecuter] Determining if task ‘:copySolrConf’ is up-to-date 16:40:24.583 [DEBUG] [org.gradle.api.internal.changedetection.DefaultFileCacheListener] Can cache files for directory ‘/home/stefan/proj/altrusoft/workspace/entitymachine/src/main/resources/solr-home’ 16:40:24.587 [DEBUG] [org.gradle.api.internal.changedetection.DefaultFileCacheListener] Can cache files for file ‘/home/stefan/se.altrusoft.entitymachine/solr-home’ 16:40:24.683 [INFO] [org.gradle.api.internal.changedetection.DefaultTaskArtifactStateRepository] Skipping task ‘:copySolrConf’ as it is up-to-date. 16:40:24.684 [INFO] [org.gradle.api.internal.tasks.execution.SkipUpToDateTaskExecuter] Skipping task ‘:copySolrConf’ as it is up-to-date 16:40:24.685 [DEBUG] [org.gradle.api.internal.tasks.execution.ExecuteAtMostOnceTaskExecuter] Finished executing task ‘:copySolrConf’ 16:40:24.704 [DEBUG] [org.gradle.logging.internal.DefaultLoggingConfigurer] Finished configuring with level: DEBUG, configurers: [org.gradle.logging.internal.OutputEventRenderer@479f43fa, org.gradle.logging.internal.logback.LogbackLoggingConfigurer@2927f6d2, org.gradle.logging.internal.JavaUtilLoggingConfigurer@7ebd6a19] 16:40:24.705 [DEBUG] [org.gradle.configuration.BuildScriptProcessor] Timing: Running the build script took 2 mins 52.843 secs 16:40:24.769 [INFO] [org.gradle.BuildLogger] All projects evaluated. 16:40:24.899 [DEBUG] [org.gradle.execution.taskgraph.DefaultTaskGraphExecuter] Timing: Creating the DAG took 0.004 secs 16:40:24.900 [INFO] [org.gradle.execution.TaskNameResolvingBuildConfigurationAction] Selected primary task ‘copyConfig’ 16:40:24.902 [INFO] [org.gradle.BuildLogger] Tasks to be executed: [task ‘:copyConfig’] 16:40:24.903 [LIFECYCLE] [org.gradle.TaskExecutionLogger] :copyConfig 16:40:24.905 [DEBUG] [org.gradle.api.internal.tasks.execution.ExecuteAtMostOnceTaskExecuter] Starting to execute task ‘:copyConfig’ 16:40:24.906 [INFO] [org.gradle.api.internal.tasks.execution.SkipTaskWithNoActionsExecuter] Skipping task ‘:copyConfig’ as it has no actions. 16:40:24.907 [DEBUG] [org.gradle.api.internal.tasks.execution.ExecuteAtMostOnceTaskExecuter] Finished executing task ‘:copyConfig’ 16:40:24.908 [LIFECYCLE] [org.gradle.TaskExecutionLogger] :copyConfig UP-TO-DATE 16:40:24.910 [DEBUG] [org.gradle.execution.taskgraph.DefaultTaskGraphExecuter] Timing: Executing the DAG took 0.008 secs 16:40:24.912 [LIFECYCLE] [org.gradle.BuildResultLogger]

16:40:24.913 [LIFECYCLE] [org.gradle.BuildResultLogger] BUILD SUCCESSFUL 16:40:24.914 [LIFECYCLE] [org.gradle.BuildResultLogger]

16:40:24.915 [LIFECYCLE] [org.gradle.BuildResultLogger] Total time: 2 mins 57.433 secs 16:40:24.917 [DEBUG] [org.gradle.cache.internal.btree.BTreePersistentIndexedCache] Closing cache taskArtifacts.bin (/home/stefan/proj/altrusoft/workspace/entitymachine/.gradle/1.2/taskArtifacts/taskArtifacts.bin) 16:40:24.918 [DEBUG] [org.gradle.cache.internal.btree.BTreePersistentIndexedCache] Closing cache outputFileStates.bin (/home/stefan/proj/altrusoft/workspace/entitymachine/.gradle/1.2/taskArtifacts/outputFileStates.bin) 16:40:24.919 [DEBUG] [org.gradle.cache.internal.btree.BTreePersistentIndexedCache] Closing cache fileHashes.bin (/home/stefan/proj/altrusoft/workspace/entitymachine/.gradle/1.2/taskArtifacts/fileHashes.bin) 16:40:24.920 [DEBUG] [org.gradle.cache.internal.btree.BTreePersistentIndexedCache] Closing cache fileSnapshots.bin (/home/stefan/proj/altrusoft/workspace/entitymachine/.gradle/1.2/taskArtifacts/fileSnapshots.bin) 16:40:24.921 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on task artifact state cache (/home/stefan/proj/altrusoft/workspace/entitymachine/.gradle/1.2/taskArtifacts). 16:40:24.922 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on no_buildscript class cache for build file ‘/home/stefan/proj/altrusoft/workspace/entitymachine/build.gradle’ (/home/stefan/.gradle/caches/1.2/scripts/build_fdmudj3ad78p9baktlj3rc48v/ProjectScript/no_buildscript). 16:40:24.923 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on buildscript class cache for build file ‘/home/stefan/proj/altrusoft/workspace/entitymachine/build.gradle’ (/home/stefan/.gradle/caches/1.2/scripts/build_fdmudj3ad78p9baktlj3rc48v/ProjectScript/buildscript). 16:40:24.967 [DEBUG] [org.gradle.logging.internal.DefaultLoggingConfigurer] Finished configuring with level: DEBUG, configurers: [org.gradle.logging.internal.OutputEventRenderer@479f43fa, org.gradle.logging.internal.logback.LogbackLoggingConfigurer@2927f6d2, org.gradle.logging.internal.JavaUtilLoggingConfigurer@7ebd6a19]


(Nils Weinander) #3

Sorry to waste someone’s time, we have found the problem :

16:37:34.383 [DEBUG] [org.gradle.api.internal.changedetection.DefaultFileCacheListener] Can cache files for file '/home/stefan/se.altrusoft.entitymachine'

is the culprit. Under that directory was not only the configuration files we have a gradle task to copy, but also a HUGE data storage tree. Have amended the ways and moved configuration to ~/se.altrusoft.entitymachine/conf, which is much cheaper to monitor.