Cleaning a project (using mvn clean or Project -> Clean) and building it take a very long time (a few minutes). This applies to projects compiled to jar. This happens in 20160620-165733 and in previous versions.

As @gohla points out it's probably related to dependency tracking for files emitted by the Stratego compiler. There is an indication that heavy I/O contributes to this as enabling/disabling full disk encryption on OS X increases/decreases the build times significantly.

In terms of building for the project i'm working on (DynSem), the entire strj time spent during the build is 1.2 minutes, measured by instrumenting org/metaborg/spoofax/meta/core/pluto/build/Strj. However after strj is finished the build takes another 3-4 minutes before moving on to the next phase.

Submitted by Vlad Vergu on 22 June 2016 at 08:43

On 22 June 2016 at 10:06 Vlad Vergu commented:

At a closer look it appears that mvn clean also sometimes a very long a time, in the order of minutes. Isn't it odd for cleaning to take so long?


On 22 June 2016 at 16:07 Gabriël Konat commented:

I think this is caused by cleaning Pluto's dynamic dependency analysis, which is based on Java's Preferences storage, which seems to have a slow implementation on OSX. Pluto tracks a lot of dependencies for DynSem, because of all the generated Java files from strj.

How large is your ~/Library/Preferences/com.apple.java.util.prefs.plist file? That's where the data is stored.


On 22 June 2016 at 16:24 Vlad Vergu commented:

~/Library/Preferences/com.apple.java.util.prefs.plist is 866K.


On 22 June 2016 at 16:27 Gabriël Konat commented:

Can you provide a stack trace (run jps to find the PID and jstack to get the stack trace) during a clean operation, so we can see what the clean operation is doing?


On 23 June 2016 at 09:57 Vlad Vergu commented:

I think your hunch is right about dependency tracking. This is stack for the relevant thread:

"main" #1 prio=5 os_prio=31 tid=0x00007fb6ec00a800 nid=0x1703 runnable [0x0000700001118000] java.lang.Thread.State: RUNNABLE at java.util.prefs.MacOSXPreferencesFile.removeKeyFromNode(Native Method) at java.util.prefs.MacOSXPreferencesFile.removeKeyFromNode(MacOSXPreferencesFile.java:409) - locked <0x00000007b1fbd158> (a java.lang.Class for java.util.prefs.MacOSXPreferencesFile) at java.util.prefs.MacOSXPreferences.removeSpi(MacOSXPreferences.java:160) at java.util.prefs.AbstractPreferences.remove(AbstractPreferences.java:316) - locked <0x00000007b1fc3ca8> (a java.lang.Object) at java.util.prefs.AbstractPreferences.clear(AbstractPreferences.java:339) - locked <0x00000007b1fc3ca8> (a java.lang.Object) at build.pluto.xattr.XattrPreferencesStrategy.clear(XattrPreferencesStrategy.java:69) at build.pluto.xattr.Xattr.clear(Xattr.java:110) at build.pluto.builder.BuildManager.resetDynamicAnalysis(BuildManager.java:393) at build.pluto.builder.BuildManagers.resetDynamicAnalysis(BuildManagers.java:113) at org.metaborg.spoofax.meta.core.build.LanguageSpecBuilder.plutoClean(LanguageSpecBuilder.java:296) at org.metaborg.spoofax.meta.core.build.LanguageSpecBuilder.clean(LanguageSpecBuilder.java:267) at org.metaborg.spoofax.maven.plugin.mojo.CleanMojo.execute(CleanMojo.java:44) at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:207) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145) at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116) at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80) at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51) at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128) at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:307) at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:193) at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:106) at org.apache.maven.cli.MavenCli.execute(MavenCli.java:863) at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288) at org.apache.maven.cli.MavenCli.main(MavenCli.java:199) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289) at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229) at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415) at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)

I've updated the issue to include build times, because i think the same problem occurs in that case. Here's the stack trace for the relevant thread for building:

"main" #1 prio=5 os_prio=31 tid=0x00007ff20100a800 nid=0x1703 runnable [0x0000700001117000] java.lang.Thread.State: RUNNABLE at java.util.prefs.MacOSXPreferencesFile.getKeyFromNode(Native Method) at java.util.prefs.MacOSXPreferencesFile.getKeyFromNode(MacOSXPreferencesFile.java:416) - locked <0x0000000784ed6158> (a java.lang.Class for java.util.prefs.MacOSXPreferencesFile) at java.util.prefs.MacOSXPreferences.getSpi(MacOSXPreferences.java:152) at java.util.prefs.AbstractPreferences.get(AbstractPreferences.java:287) - locked <0x0000000783f58a98> (a java.lang.Object) at build.pluto.xattr.XattrPreferencesStrategy.getXattr(XattrPreferencesStrategy.java:50) at build.pluto.xattr.Xattr.addGenBy(Xattr.java:24) at build.pluto.builder.DynamicAnalysis.checkGeneratedFilesOverlap(DynamicAnalysis.java:81) at build.pluto.builder.DynamicAnalysis.check(DynamicAnalysis.java:54) at build.pluto.builder.BuildManager.executeBuilder(BuildManager.java:128) at build.pluto.builder.BuildManager.require(BuildManager.java:328) at build.pluto.builder.Builder.requireBuild(Builder.java:215) at build.pluto.builder.Builder.requireBuild(Builder.java:234) at org.metaborg.spoofax.meta.core.pluto.build.main.GenerateSourcesBuilder.build(GenerateSourcesBuilder.java:308) at org.metaborg.spoofax.meta.core.pluto.build.main.GenerateSourcesBuilder.build(GenerateSourcesBuilder.java:1) at build.pluto.builder.Builder.triggerBuild(Builder.java:134) at build.pluto.builder.BuildManager.executeBuilder(BuildManager.java:95) at build.pluto.builder.BuildManager.require(BuildManager.java:328) at build.pluto.builder.BuildManager.requireInitially(BuildManager.java:255) at build.pluto.builder.BuildManagers.build(BuildManagers.java:72) at org.metaborg.spoofax.meta.core.build.LanguageSpecBuilder.plutoBuild(LanguageSpecBuilder.java:292) at org.metaborg.spoofax.meta.core.build.LanguageSpecBuilder.compile(LanguageSpecBuilder.java:133) at org.metaborg.spoofax.maven.plugin.mojo.CompileMojo.execute(CompileMojo.java:29) at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:207) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145) at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116) at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80) at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51) at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128) at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:307) at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:193) at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:106) at org.apache.maven.cli.MavenCli.execute(MavenCli.java:863) at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288) at org.apache.maven.cli.MavenCli.main(MavenCli.java:199) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289) at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229) at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415) at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
Maybe the Java Preferences storage is simply not designed to handle heavy traffic/large stores.


On 17 August 2016 at 14:43 Gabriël Konat tagged pluto

On 13 September 2016 at 11:07 Vlad Vergu commented:

Bump. This problem is still present in Spoofax based on https://github.com/metaborg/spoofax-releng/commit/9b846405aa6276f8f87b7ad8d8eb16b3195a59ca.


On 13 September 2016 at 13:28 Gabriël Konat commented:

Sebastian has replaced the Java preference storage with a faster database system, but there's still some bugs in the code so we can't use it yet. Hopefully we can fix those soon.


On 14 September 2016 at 17:06 Gabriël Konat commented:

This should be solved in the latest build, since Pluto is not longer using the Java preference store, but the Xodus database instead. Dynsem in Eclipse builds in about ~1 minute after a Stratego change. Can you confirm this?


On 15 September 2016 at 08:37 Vlad Vergu commented:

WOW! Over here a full build of DynSem is done in just under 2 minutes, and a build after only Stratego changes in just under 1 minute. This is great! I love it! Thanks for the fix.


On 15 September 2016 at 10:48 Gabriël Konat closed this issue.

Log in to post comments