Details

Description

Let's say you have 2 scripts : script1 and script2 and they both use class BeanX and they are all loaded via the same GroovyScriptEngine instance. If I modify BeanX, the script that is the first to get loaded and references BeanX will reflect changes made to BeanX, while the other or second script to reference BeanX will fail to reflect changes made to BeanX.

I'm assuming this is not the proper behavior, although I don't see any test to test for this scenario. If one is using groovy via Groovlets or something like Gaelyk where the assumption is that I can write
scripts and hot have to constantly restart to have my changes reflected then I would assume the GSE should reload classes and dependent classes regardless of the order in which they are referenced.

Activity

I've ran into a similar issue. For me, the problem presented itself as a class cast exception after a runtime update of some scripts.

The attached patches are:

a patch to the GroovyScriptEngineReloadTest, for testing for this (non-deterministic) phenomenon. Both the case reported by David and 'my' problem are included as test cases.

a patch to the GroovyScriptEngine that solves this problem. The solution works, but is pretty crude.

Both patches are relative to the 1.8.4 sources.

I hope this can be included in the next release. We're using the script engine inside a process engine we've written to replace BPEL in our organisation, using Groovy as a process definition language. Works great, but because of this issue we have to restart the entire engine every time we change a process.

Frans van Buul
added a comment - 04/Dec/11 11:42 - edited I've ran into a similar issue. For me, the problem presented itself as a class cast exception after a runtime update of some scripts.
The attached patches are:
a patch to the GroovyScriptEngineReloadTest, for testing for this (non-deterministic) phenomenon. Both the case reported by David and 'my' problem are included as test cases.
a patch to the GroovyScriptEngine that solves this problem. The solution works, but is pretty crude.
Both patches are relative to the 1.8.4 sources.
I hope this can be included in the next release. We're using the script engine inside a process engine we've written to replace BPEL in our organisation, using Groovy as a process definition language. Works great, but because of this issue we have to restart the entire engine every time we change a process.

I've looked into that, but that doesn't solve the problem. The unit tests I provided set the config.minimumRecompilationInterval value to 0 ms, and sleep for 20ms between modifying the scripts and using them through the scripting engine. This should be non-problematic, but it is.

Frans van Buul
added a comment - 05/Dec/11 01:01 Hi Jochen,
I've looked into that, but that doesn't solve the problem. The unit tests I provided set the config.minimumRecompilationInterval value to 0 ms, and sleep for 20ms between modifying the scripts and using them through the scripting engine. This should be non-problematic, but it is.
Regards,
Frans

only the thing is, your patch more or less sets the time code for every entry to about 1s in the past. Unless minimumRecompilationInterval is set higher it will not have any effect anymore. minimumRecompilationInterval has a certain impact on performance of the engine, that is why it was introduced. Also there is the problem with getting an exact time on windows. currentTimeMillis has a resolution of about 1ms on Linux systems, but on for example XP it 15ms or more. I remember on older windows versions it was even higher. That's also why we set the minimumRecompilationInterval to 100 by default, to avoid such strange timing problems. If you wait only 20ms (or even less), then it can happen that current time will still be the same as before, thus no recompilation will happen.

makes me wonder if the problem is not here to be found. With reloading intervals below 1s this code may set times in the future, since we use lastMod to create a new ScriptCacheEntry. The code was added as a reaction to GROOVY-4492, the lastMod as time for the new entry is used due to GROOVY-2811 and GROOVY-4286, but I cannot see why. But I feel the fix should be in this part instead actually

Jochen Theodorou
added a comment - 05/Dec/11 06:41 only the thing is, your patch more or less sets the time code for every entry to about 1s in the past. Unless minimumRecompilationInterval is set higher it will not have any effect anymore. minimumRecompilationInterval has a certain impact on performance of the engine, that is why it was introduced. Also there is the problem with getting an exact time on windows. currentTimeMillis has a resolution of about 1ms on Linux systems, but on for example XP it 15ms or more. I remember on older windows versions it was even higher. That's also why we set the minimumRecompilationInterval to 100 by default, to avoid such strange timing problems. If you wait only 20ms (or even less), then it can happen that current time will still be the same as before, thus no recompilation will happen.
Looking at isSourceNewer
protected boolean isSourceNewer(ScriptCacheEntry entry) throws ResourceException {
if (entry == null ) return true ;
long now = System .currentTimeMillis();
for ( String scriptName : entry.dependencies) {
ScriptCacheEntry depEntry = scriptCache.get(scriptName);
long nextPossibleRecompilationTime = depEntry.lastModified + config.getMinimumRecompilationInterval();
if (nextPossibleRecompilationTime > now) continue ;
URLConnection conn = rc.getResourceConnection(scriptName);
// getLastModified() truncates up to 999 ms from the true modification time, let's fix that
long lastMod = ((conn.getLastModified() / 1000) + 1) * 1000 - 1;
// getResourceConnection() opening the inputstream, let's ensure all streams are closed
forceClose(conn);
if (depEntry.lastModified < lastMod) {
ScriptCacheEntry newEntry = new ScriptCacheEntry(depEntry.scriptClass, lastMod, depEntry.dependencies);
scriptCache.put(scriptName, newEntry);
return true ;
}
}
return false ;
}
especially the
URLConnection conn = rc.getResourceConnection(scriptName);
// getLastModified() truncates up to 999 ms from the true modification time, let's fix that long lastMod = ((conn.getLastModified() / 1000) + 1) * 1000 - 1;
makes me wonder if the problem is not here to be found. With reloading intervals below 1s this code may set times in the future, since we use lastMod to create a new ScriptCacheEntry. The code was added as a reaction to GROOVY-4492 , the lastMod as time for the new entry is used due to GROOVY-2811 and GROOVY-4286 , but I cannot see why. But I feel the fix should be in this part instead actually

There is definitely a problem. The problem is with ScriptCacheEntry.dependencies, not the timing.
The dependency graph is not correct for a second script that loads dependencies that have already been loaded.

It's demonstrated in both test. isSourceNewer is failing because ScriptCacheEntry.dependencies does not contain all of the correct entries for the second script.

It's easily evident if the tests are run in a debug session w/breakpoints set in isSourceNewer inspecting entry.dependencies.

Derek Smith
added a comment - 05/Dec/11 08:30 There is definitely a problem. The problem is with ScriptCacheEntry.dependencies, not the timing.
The dependency graph is not correct for a second script that loads dependencies that have already been loaded.
It's demonstrated in both test. isSourceNewer is failing because ScriptCacheEntry.dependencies does not contain all of the correct entries for the second script.
It's easily evident if the tests are run in a debug session w/breakpoints set in isSourceNewer inspecting entry.dependencies.

David is correct. My original solution only hides the problem. I've run a new test similar to my original ones (attached) with a minimum recompilation interval of 2000 ms and sleeps of 5000 ms between modifying the source and using it. This is slow enough to eliminate all timing issues. In this case, the problem shows up deterministically, 100% of the time.

Any ideas on how this should be properly solved? I do have some time available to work on this, but some pointers would be useful.

Frans van Buul
added a comment - 05/Dec/11 10:02 David is correct. My original solution only hides the problem. I've run a new test similar to my original ones (attached) with a minimum recompilation interval of 2000 ms and sleeps of 5000 ms between modifying the source and using it. This is slow enough to eliminate all timing issues. In this case, the problem shows up deterministically, 100% of the time.
Any ideas on how this should be properly solved? I do have some time available to work on this, but some pointers would be useful.

I've inserted some logging into the scripting engine and my test case, results are shown below. The entire dependency between Extractor and MyBean is not managed, and looking at the code, I see nothing that should manage it. Disabling the timestamp check in 'isSourceNewer' solves the problem at the expense of disabling the entire mechanism.

Frans, having a test that fails deterministically each time is worth a lot! Since we now know that the dependencies are set wrong, we can concentrate on that part better and stop thinking about timing problems (the code in isSourceNewer still looks wrong to me, but we can maybe fix that one later on)

That means there might be a bug in org.codehaus.groovy.tools.gse.DependencyTracker then - or its usage... so I guess a first step would be to check if the tracker gets the dependency between MyBean and Extractor right and if they both appear then correctly in the transitive hull.

Should that work, then the next step would be to check the way the dependencies are stored, and if that is right. This part is also not so easy code and may have the bug we search for.

Jochen Theodorou
added a comment - 05/Dec/11 12:49 Frans, having a test that fails deterministically each time is worth a lot! Since we now know that the dependencies are set wrong, we can concentrate on that part better and stop thinking about timing problems (the code in isSourceNewer still looks wrong to me, but we can maybe fix that one later on)
That means there might be a bug in org.codehaus.groovy.tools.gse.DependencyTracker then - or its usage... so I guess a first step would be to check if the tracker gets the dependency between MyBean and Extractor right and if they both appear then correctly in the transitive hull.
Should that work, then the next step would be to check the way the dependencies are stored, and if that is right. This part is also not so easy code and may have the bug we search for.

Jochen, I put logging into the DependencyTracker and that seems to be working correctly. I also checked how they are stored in the scriptcache, and how the transitive hull is calculated. Seems to be working correctly as well. I think the problem is that this information is not being used.

I changed GroovyScriptEngine#isSourceNewer in such a way that when an entry is updated, existing entries that depend on the updated entry are removed from the cache. This forces recompilation when they are accessed. The relevant fragment is shown below. With this modification, the unit test passes. Is this an acceptable solution?

Frans van Buul
added a comment - 06/Dec/11 10:30 - edited Jochen, I put logging into the DependencyTracker and that seems to be working correctly. I also checked how they are stored in the scriptcache, and how the transitive hull is calculated. Seems to be working correctly as well. I think the problem is that this information is not being used.
I changed GroovyScriptEngine#isSourceNewer in such a way that when an entry is updated, existing entries that depend on the updated entry are removed from the cache. This forces recompilation when they are accessed. The relevant fragment is shown below. With this modification, the unit test passes. Is this an acceptable solution?
if (depEntry.lastModified < lastMod) {
ScriptCacheEntry newEntry = new ScriptCacheEntry(depEntry.scriptClass, lastMod, depEntry.dependencies);
scriptCache.put(scriptName, newEntry);
/* Removing entries from cache that depended on the entry we just updated; these should be recompiled. */
for (Map.Entry< String , ScriptCacheEntry> currentEntry : scriptCache.entrySet()) {
if (!currentEntry.getKey().equals(scriptName) &&
currentEntry.getValue().dependencies.contains(scriptName)) {
scriptCache.remove(currentEntry.getKey());
}
}
return true ;
}

Some more results: the change I proposed in my previous comment certainly fixes one problem, but not all. In the more complex case, the registration/calculation of the dependencies seems broken as well. I'll look into that next.

Frans van Buul
added a comment - 07/Dec/11 06:09 Some more results: the change I proposed in my previous comment certainly fixes one problem, but not all. In the more complex case, the registration/calculation of the dependencies seems broken as well. I'll look into that next.

I've created a new patch to fix this issue. It contains a new unit test, a small change to DependencyTracker, and several changes to GroovyScriptEngine.

To summarise, I found and (I think) corrected the following issues:

1. After a class is updated because a newer version of the script is found, all classes that directly or indirectly depend on it are no longer valid. This means they must be removed from the scriptcache (as per my previous comment), but also from the classloader cache (new in this patch).

2. If we have dependencies (A->C) and (B->C), and we first compile A (compilation unit (A,C)), compiling B later on would fail to detect the dependency on C. The reason was that in this case, class C is not identified as a primary node in the semantic analysis and is thus ignored in the dependency tracker. I've modified the tracker and the scripting engine to ignore the 'primary node' status in case we're dealing with a previously seen scripted class.

Frans van Buul
added a comment - 10/Dec/11 06:53 - edited I've created a new patch to fix this issue. It contains a new unit test, a small change to DependencyTracker, and several changes to GroovyScriptEngine.
To summarise, I found and (I think) corrected the following issues:
1. After a class is updated because a newer version of the script is found, all classes that directly or indirectly depend on it are no longer valid. This means they must be removed from the scriptcache (as per my previous comment), but also from the classloader cache (new in this patch).
2. If we have dependencies (A->C) and (B->C), and we first compile A (compilation unit (A,C)), compiling B later on would fail to detect the dependency on C. The reason was that in this case, class C is not identified as a primary node in the semantic analysis and is thus ignored in the dependency tracker. I've modified the tracker and the scripting engine to ignore the 'primary node' status in case we're dealing with a previously seen scripted class.

Derek Smith
added a comment - 04/Jan/12 21:37 - edited Finally got around to trying this patch.
It works beautifully thus far. Thanks Frans.
Hopefully the groovy team will include this is a release soon.

Thanks for trying it out. I've discussed this patch on the Groovy dev list. Jochen Theodorou had some very valid criticisms on this patch, it runs fine in the unit tests but it's not completely reliable in all circumstances.

Once I find some time (hopefully next week) I'll try to create a new patch that addresses these problems.

Frans van Buul
added a comment - 05/Jan/12 00:10 Hi David,
Thanks for trying it out. I've discussed this patch on the Groovy dev list. Jochen Theodorou had some very valid criticisms on this patch, it runs fine in the unit tests but it's not completely reliable in all circumstances.
Once I find some time (hopefully next week) I'll try to create a new patch that addresses these problems.
Regards,
Frans

Scott Murphy
added a comment - 25/Jan/12 12:25 Any update on this? We believe this bug may be causing a nasty side effect of recompiling scripts on each use resulting
in frequent PermGen errors for server side applications.
http://groups.google.com/group/gaelyk/browse_thread/thread/58ff42f7d679b23b

Stevo Slavic
added a comment - 10/Apr/12 01:31 - edited Shouldn't DependencyTracker#visitCastExpression(org.codehaus.groovy.ast.expr.CastExpression) be called for that cast to MyBean in Extractor.groovy (see GroovyScriptEngineReloadingSlowTest.groovy ), so that MyBean.groovy , along with Extractor.groovy , gets registered as dependency of Extractor ?
When I debuged, visitCastExpression didn't get called, and Extractor , like in Frans' log output , had only Extractor.groovy as dependency.

I am looking now into this again freshly... RealodTest#testReloadWith2ScriptsDependentOnSameBean looks good and produces the problem, so I will use that... In a first call we request script1, that will create a dependency for script1 on itself and Bean, as it should. In the next run we request script2, that also depends on Bean, but as found out earlier in here, it is not added as dependency, because it is no primary node.

Frans patch tried to change that here and ignore the primary node state. Doing so will correctly ensure the dependency, but it will not recompile Bean the first time. That means if we would make a test in which first script2 is loaded and we then change Bean to then load script1, we would still not get a recompiled Bean. Testing this with a modified version of ReloadTest I can confirm this.

Solving this problem would most probably also solve the other problems

Jochen Theodorou
added a comment - 17/Aug/12 09:02 I am looking now into this again freshly... RealodTest#testReloadWith2ScriptsDependentOnSameBean looks good and produces the problem, so I will use that... In a first call we request script1, that will create a dependency for script1 on itself and Bean, as it should. In the next run we request script2, that also depends on Bean, but as found out earlier in here, it is not added as dependency, because it is no primary node.
Frans patch tried to change that here and ignore the primary node state. Doing so will correctly ensure the dependency, but it will not recompile Bean the first time. That means if we would make a test in which first script2 is loaded and we then change Bean to then load script1, we would still not get a recompiled Bean. Testing this with a modified version of ReloadTest I can confirm this.
Solving this problem would most probably also solve the other problems

After further thinking I tend to say that ResolveVisitor is here not doing the right thing for us. ResolveVisitor resolves Bean to a precompiled class, as it already exists. It is done with that and now happily assumes all is fine. But in our case we want Bean maybe to be enlisted in the compilation queue, with our own check for if the source is newer or not. ResolveVisitor is clearly lacking some abstraction in that section, making a nice solution difficult.

Jochen Theodorou
added a comment - 17/Aug/12 09:45 After further thinking I tend to say that ResolveVisitor is here not doing the right thing for us. ResolveVisitor resolves Bean to a precompiled class, as it already exists. It is done with that and now happily assumes all is fine. But in our case we want Bean maybe to be enlisted in the compilation queue, with our own check for if the source is newer or not. ResolveVisitor is clearly lacking some abstraction in that section, making a nice solution difficult.

The issue should be fixed now. It required me to hook into ResolveVisitor in a way, that was not planned before, but well, there is a clean way now and the reload test from before works now. It would be nice to here of you people here if this new versions resolves the issues you had

Jochen Theodorou
added a comment - 22/Aug/12 08:34 The issue should be fixed now. It required me to hook into ResolveVisitor in a way, that was not planned before, but well, there is a clean way now and the reload test from before works now. It would be nice to here of you people here if this new versions resolves the issues you had

Jochen Theodorou
added a comment - 24/Aug/12 05:33 if you say you test with 1.8.8 SNAPSHOT, you mean you compiled it from our repository? And you say the here attached ReloadTest.groovy does not work for you?

Jochen Theodorou
added a comment - 24/Aug/12 08:57 I just tested to be sure. I got the SNAPSHOT from http://snapshots.repository.codehaus.org/org/codehaus/groovy/groovy-all/1.8.8-SNAPSHOT/ and executed ReloadTest.groovy. Actually ReloadTest.groovy has a bug, the line:
path = new File(dir + "ReloadTest" );
should be (on my system at least)
path = new File(dir, "ReloadTest" );
. After changing the two times this appaears the test executes and works for me

Groovy 1.8.8 does not solve the problem for me. The tests (both the Groovy one and Java one) still fail randomly, both when launched from IntelliJ IDEA and when run manually from the command line. The Java test fails much more often, though - you may have to run the Groovy test several times in a row before getting a failure.

I observed a couple of facts, that I report here in hope that they will help someone who knows the GSE internals better than me to find a solution.

1. When the test fails, the 2nd dependent script has its dependencies incorrectly computed: it only depends on itself, not on the shared Bean.

2. I modified the generated scripts to print their classloader, as well as the one that loaded the Bean class. When the test passes, each script gets its own classloader, which is always also the classloader of the Bean class. In other words, each script class gets its own version of the Bean class. When the test fails, the 2nd script has a different classloader than the first, but it sees the Bean class as loaded from the 1st classloader (which I suppose should be the expected behaviour). Somehow that causes the script not be reloaded. To make it clearer, this is a printout of two sample runs:

Note: this is from the test method testReloadWith2ScriptsDependentOnSameBeanOrderSwitched(), but similar stuff happen with testReloadWith2ScriptsDependentOnSameBean(). "Instantiating bean class" is printed from a static initializer in Bean.

Alessio Stalla
added a comment - 14/Sep/12 07:47 Groovy 1.8.8 does not solve the problem for me. The tests (both the Groovy one and Java one) still fail randomly, both when launched from IntelliJ IDEA and when run manually from the command line. The Java test fails much more often, though - you may have to run the Groovy test several times in a row before getting a failure.
I observed a couple of facts, that I report here in hope that they will help someone who knows the GSE internals better than me to find a solution.
1. When the test fails, the 2nd dependent script has its dependencies incorrectly computed: it only depends on itself, not on the shared Bean.
2. I modified the generated scripts to print their classloader, as well as the one that loaded the Bean class. When the test passes, each script gets its own classloader, which is always also the classloader of the Bean class. In other words, each script class gets its own version of the Bean class. When the test fails, the 2nd script has a different classloader than the first, but it sees the Bean class as loaded from the 1st classloader (which I suppose should be the expected behaviour). Somehow that causes the script not be reloaded. To make it clearer, this is a printout of two sample runs:
test PASS
class script2
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@186fa9fc
Instantiating bean class: groovy.lang.GroovyClassLoader$InnerLoader@186fa9fc
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@186fa9fc
class script1
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@2918958e
Instantiating bean class: groovy.lang.GroovyClassLoader$InnerLoader@2918958e
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@2918958e
class script1
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@87e9ce2
Instantiating bean class: groovy.lang.GroovyClassLoader$InnerLoader@87e9ce2
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@87e9ce2
class script2
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@5567d7fb
Instantiating bean class: groovy.lang.GroovyClassLoader$InnerLoader@5567d7fb
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@5567d7fb
test FAIL
class script2
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@36b60b93
Instantiating bean class: groovy.lang.GroovyClassLoader$InnerLoader@36b60b93
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@36b60b93
class script1
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@741827d1
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@36b60b93
class script1
script classloader: groovy.lang.GroovyClassLoader$InnerLoader@741827d1
bean classloader: groovy.lang.GroovyClassLoader$InnerLoader@36b60b93
//FAIL
Note: this is from the test method testReloadWith2ScriptsDependentOnSameBeanOrderSwitched(), but similar stuff happen with testReloadWith2ScriptsDependentOnSameBean(). "Instantiating bean class" is printed from a static initializer in Bean.

Alessio, what OS are you using? Because the only part that I can imagine still failing here is that an update of the file is not seen, because of timing issues of the OS. That would also explain why it fails only sometimes. Before it should have failed always.

Jochen Theodorou
added a comment - 14/Sep/12 08:02 Alessio, what OS are you using? Because the only part that I can imagine still failing here is that an update of the file is not seen, because of timing issues of the OS. That would also explain why it fails only sometimes. Before it should have failed always.

I'm using OSX, but I also tested it on Linux, with the same outcome. I don't think it's related to timing and the OS, because I can arbitrarily increase the wait time between writing the bean and reloading the dependent scripts, and I still get failures. The test above was using a 500ms wait, but I went up to 4500ms to no avail. Also, the two different classloader behaviours are already apparent before any reload happens: the shared Bean is modified just before the line "class script1" is printed for the second time in my example.

Alessio Stalla
added a comment - 14/Sep/12 08:53 I'm using OSX, but I also tested it on Linux, with the same outcome. I don't think it's related to timing and the OS, because I can arbitrarily increase the wait time between writing the bean and reloading the dependent scripts, and I still get failures. The test above was using a 500ms wait, but I went up to 4500ms to no avail. Also, the two different classloader behaviours are already apparent before any reload happens: the shared Bean is modified just before the line "class script1" is printed for the second time in my example.

I made the following... I downloaded Groovy 2.0.2 and let it execute raw.github.com/groovy/groovy-core/master/src/test/groovy/util/GroovyScriptEngineReloadingTest.groovy 10 times in a row. And indeed the test is failing about once in ten times.... maybe every 6th time.

But I don't understand why. If it is no timing issue, then I would have put my finger on a concurrency issue, but with 4500ms wait time, that is unlikely as well. The symptoms are clear of course. I mean the classloader being the same and all. The question is more what the cause is.

Jochen Theodorou
added a comment - 17/Sep/12 10:01 I made the following... I downloaded Groovy 2.0.2 and let it execute raw.github.com/groovy/groovy-core/master/src/test/groovy/util/GroovyScriptEngineReloadingTest.groovy 10 times in a row. And indeed the test is failing about once in ten times.... maybe every 6th time.
But I don't understand why. If it is no timing issue, then I would have put my finger on a concurrency issue, but with 4500ms wait time, that is unlikely as well. The symptoms are clear of course. I mean the classloader being the same and all. The question is more what the cause is.
Why does it work one time and another time it does not?

One thing that I thought that could cause nondeterminism is the garbage collector. I saw that a few caches are held in thread-local weak references; maybe if they're garbage collected too early some important information could be lost. I passed the -verbose:gc flag to the JVM, but it only prints something at the beginning; OTOH, I don't know whether it only prints full GC or it is more detailed.

As for concurrency, I'm convinced that there's only one thread; I put print statements in a few places to be sure.

Alessio Stalla
added a comment - 17/Sep/12 10:46 One thing that I thought that could cause nondeterminism is the garbage collector. I saw that a few caches are held in thread-local weak references; maybe if they're garbage collected too early some important information could be lost. I passed the -verbose:gc flag to the JVM, but it only prints something at the beginning; OTOH, I don't know whether it only prints full GC or it is more detailed.
As for concurrency, I'm convinced that there's only one thread; I put print statements in a few places to be sure.

I took my analysis further and I can now say that timing is, indeed, part of the issue - but only because it's exposing a deeper problem.

There are two timestamps being compared to decide whether to recompile a file: one is the file modification time, rounded up to the next second; the other is the script compilation time, not rounded. The first is computed at line 595 in GroovyScriptEngine - long lastMod = ((conn.getLastModified() / 1000) + 1) * 1000 - 1;. The second is at line 240, long now = System.currentTimeMillis();. When a file is compiled (the shared Bean in our case), the rounded up time may end up being earlier or later than the compilation time, in a nondetermistic way, because of the rounding. This alone should not be a big problem - at worst, it would sometimes cause unnecessary recompilations. But...

...the logic that records dependencies between files is flawed; a dependency between file A and file B is only recorded when B is compiled in the same compilation unit as A. If B is not recompiled, the dependency is not recorded. This is caused by the fact that the DependencyTracker is invoked by a PrimaryClassNodeOperation (GSE, lines 165 - 175). I don't know the specifications of the various compiler phases, but certainly I can see that, by manually altering the source file last modification date, I can cause the dependency to be deterministically recorded or not, i.e. dt.visitClass(classNode); (line 173) being executed or not, depending on whether the modification date is forcibly set in the future or in the past. You can obtain the same effect also by causing a big enough sleep (say, 2000ms) between writing Bean.groovy and writing the scripts.

So, those unnecessary recompilations caused by the timing problem are actually necessary for the dependency to be recorded. That's why in our app it consistently fails - the shared classes are compiled much later than their last modification.

Alessio Stalla
added a comment - 19/Sep/12 10:33 I took my analysis further and I can now say that timing is, indeed, part of the issue - but only because it's exposing a deeper problem.
There are two timestamps being compared to decide whether to recompile a file: one is the file modification time, rounded up to the next second; the other is the script compilation time, not rounded. The first is computed at line 595 in GroovyScriptEngine - long lastMod = ((conn.getLastModified() / 1000) + 1) * 1000 - 1; . The second is at line 240, long now = System.currentTimeMillis(); . When a file is compiled (the shared Bean in our case), the rounded up time may end up being earlier or later than the compilation time, in a nondetermistic way, because of the rounding. This alone should not be a big problem - at worst, it would sometimes cause unnecessary recompilations. But...
...the logic that records dependencies between files is flawed; a dependency between file A and file B is only recorded when B is compiled in the same compilation unit as A. If B is not recompiled, the dependency is not recorded. This is caused by the fact that the DependencyTracker is invoked by a PrimaryClassNodeOperation (GSE, lines 165 - 175). I don't know the specifications of the various compiler phases, but certainly I can see that, by manually altering the source file last modification date, I can cause the dependency to be deterministically recorded or not, i.e. dt.visitClass(classNode); (line 173) being executed or not, depending on whether the modification date is forcibly set in the future or in the past. You can obtain the same effect also by causing a big enough sleep (say, 2000ms) between writing Bean.groovy and writing the scripts.
So, those unnecessary recompilations caused by the timing problem are actually necessary for the dependency to be recorded. That's why in our app it consistently fails - the shared classes are compiled much later than their last modification.
Does it make sense to you?

I am currently preparing a fix for the first issue you mention. It seems this new version is excluding the timing issue finally. I am going to push that soon and it would be good of you if you could test it as well. I will comment here as soon as it is available, since it is getting late here.

The second part of your comment is something that should not be true anymore. Since the latest version there is a new element called ClassNodeResolver involved. This is used to resolve class names and eventually enqueue new sources. For every script cache entry of GSE that has been requested, a new source unit will be added, if the source is newer. If not, then no recompilation will happen. It is true that the dependencies are not fully right then, yes... but actually I think the dependency tracking is now surplus, since the ClassNodeResolver will do that job implicitly and much better. Actually I am wondering if I should not remove the tracker even.

Jochen Theodorou
added a comment - 19/Sep/12 13:37 I am currently preparing a fix for the first issue you mention. It seems this new version is excluding the timing issue finally. I am going to push that soon and it would be good of you if you could test it as well. I will comment here as soon as it is available, since it is getting late here.
The second part of your comment is something that should not be true anymore. Since the latest version there is a new element called ClassNodeResolver involved. This is used to resolve class names and eventually enqueue new sources. For every script cache entry of GSE that has been requested, a new source unit will be added, if the source is newer. If not, then no recompilation will happen. It is true that the dependencies are not fully right then, yes... but actually I think the dependency tracking is now surplus, since the ClassNodeResolver will do that job implicitly and much better. Actually I am wondering if I should not remove the tracker even.

As for the other point, I hadn't realized that the ClassNodeResolver was meant to replace the PrimaryClassNodeOperation. Unfortunately, I don't think that you can do without dependency tracking. The ClassNodeResolver is only invoked when a file is compiled; what if a file is not modified (compared to the cached version), but one of its dependencies was modified? Without dependency tracking, the dependency won't be recompiled. In other words, the ClassNodeResolver works top-down, while the decision to recompile or not should be a bottom-up process.

Alessio Stalla
added a comment - 20/Sep/12 04:26 Thanks for addressing the timing issue!
As for the other point, I hadn't realized that the ClassNodeResolver was meant to replace the PrimaryClassNodeOperation. Unfortunately, I don't think that you can do without dependency tracking. The ClassNodeResolver is only invoked when a file is compiled; what if a file is not modified (compared to the cached version), but one of its dependencies was modified? Without dependency tracking, the dependency won't be recompiled. In other words, the ClassNodeResolver works top-down, while the decision to recompile or not should be a bottom-up process.

You are right... as often, almost right after writing that we may not need the tracker it dawned on me, that I said something stupid Of course some of the logic would have to be moved to the ClassNodeResolver and there we don't know the "cause" of the request, this it is impossible to make the connection, thus we need the tracker in the end still.

I just did the commit for GROOVY_1_8_X with my new version. Is it possible for you to check if that helps you?

Jochen Theodorou
added a comment - 20/Sep/12 08:23 You are right... as often, almost right after writing that we may not need the tracker it dawned on me, that I said something stupid Of course some of the logic would have to be moved to the ClassNodeResolver and there we don't know the "cause" of the request, this it is impossible to make the connection, thus we need the tracker in the end still.
I just did the commit for GROOVY_1_8_X with my new version. Is it possible for you to check if that helps you?

full determinism is impossible to achieve. UrlConnection.getLastModified may not know milliseconds, that is why there is this truncation. truncating the modification time means that if your change has been done too fast, it cannot be picked up, since it has the same time as before. So you need 1000 ms minimum delay to ensure the time in last modified is updated properly. But it is actually more, since the OS has a timer with differing resolution. A delay of 1100ms should catch most cases, but that does not guarantee the change will be picked up right away. actually the next possible point of a recompilation is time of last compilation plus 1100 plus minimum recompilation interval.

Jochen Theodorou
added a comment - 20/Sep/12 10:19 full determinism is impossible to achieve. UrlConnection.getLastModified may not know milliseconds, that is why there is this truncation. truncating the modification time means that if your change has been done too fast, it cannot be picked up, since it has the same time as before. So you need 1000 ms minimum delay to ensure the time in last modified is updated properly. But it is actually more, since the OS has a timer with differing resolution. A delay of 1100ms should catch most cases, but that does not guarantee the change will be picked up right away. actually the next possible point of a recompilation is time of last compilation plus 1100 plus minimum recompilation interval.

Ok, let's step back a bit: I don't have a problem with nondeterminism per se - the problem is that GSE doesn't properly reload dependencies, ever, unless a dependency is found to be modified later than it was compiled (due to nondeterminism). That is, nondeterminism is what makes the test pass sometimes, not fail. If you eliminate nondeterminism (for example, by ensuring that there is a long enough sleep between writing Bean.groovy and loading the scripts for the first time), the test always fails.

Alessio Stalla
added a comment - 21/Sep/12 06:57 Ok, let's step back a bit: I don't have a problem with nondeterminism per se - the problem is that GSE doesn't properly reload dependencies, ever , unless a dependency is found to be modified later than it was compiled (due to nondeterminism). That is, nondeterminism is what makes the test pass sometimes, not fail. If you eliminate nondeterminism (for example, by ensuring that there is a long enough sleep between writing Bean.groovy and loading the scripts for the first time), the test always fails.

Alessio, after totally rewriting the tests to not to use the file system anymore, but something custom I found that you are right in more than one way. It was indeed the case that a precompiled dependency is not picked up. This is now basically fixed. I still have a problem to solve though...

In he current setup if I have script1 depending on Bean and script2 depending on it as well, if I recompiled script1 and Bean, because Bean changed, then script2 will not be recompiled, because the entries are all up to date

Jochen Theodorou
added a comment - 25/Sep/12 08:18 Alessio, after totally rewriting the tests to not to use the file system anymore, but something custom I found that you are right in more than one way. It was indeed the case that a precompiled dependency is not picked up. This is now basically fixed. I still have a problem to solve though...
In he current setup if I have script1 depending on Bean and script2 depending on it as well, if I recompiled script1 and Bean, because Bean changed, then script2 will not be recompiled, because the entries are all up to date

the issue was marked as fixed for 2.0.2 and 1.8.8, but it seems due to the tests not always showing the real problem it was only partially fixed. This new version in 2.0.5 and 1.8.9 should finally fix the issue of not picking up dependencies. It is still no 100% satisfying solution to me, but at least it works

Jochen Theodorou
added a comment - 01/Oct/12 02:33 the issue was marked as fixed for 2.0.2 and 1.8.8, but it seems due to the tests not always showing the real problem it was only partially fixed. This new version in 2.0.5 and 1.8.9 should finally fix the issue of not picking up dependencies. It is still no 100% satisfying solution to me, but at least it works