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

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?

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.

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

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?

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.

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

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.

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?

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.