groovy
  1. groovy
  2. GROOVY-4975

GroovyScripeEngine fails to properly reload when dependent class is updated

    Details

    • Type: Bug Bug
    • Status: Closed Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 1.8.1
    • Fix Version/s: 2.0.5, 1.8.9
    • Component/s: GroovyScriptEngine
    • Labels:
    • Environment:
      Win 7 64bit, OSX Lion
    • Testcase included:
      yes
    • Number of attachments :
      6

      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.

      Test attached.

      1. GroovyScriptEngineReloadingSlowTest.groovy
        1 kB
        Frans van Buul
      2. patch4975_main.txt
        0.8 kB
        Frans van Buul
      3. patch4975_test.txt
        5 kB
        Frans van Buul
      4. patch4975_v2.txt
        13 kB
        Frans van Buul
      5. ReloadTest.groovy
        4 kB
        David Smith
      6. ReloadTestJava.java
        6 kB
        David Smith

        Activity

        Hide
        Frans van Buul added a comment - - 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.

        Show
        Frans van Buul added a comment - - 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.
        Hide
        blackdrag blackdrag added a comment -

        in the CompilerConfiguration is a reloading interval as option you can influence... could that be used here?

        Show
        blackdrag blackdrag added a comment - in the CompilerConfiguration is a reloading interval as option you can influence... could that be used here?
        Hide
        Frans van Buul added a comment -

        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

        Show
        Frans van Buul added a comment - 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
        Hide
        blackdrag blackdrag added a comment -

        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

        Show
        blackdrag blackdrag added a comment - 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
        Hide
        David Smith added a comment -

        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.

        Show
        David Smith added a comment - 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.
        Hide
        Frans van Buul added a comment -

        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.

        Show
        Frans van Buul added a comment - 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.
        Hide
        Frans van Buul added a comment -

        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.

        [junit] Writing source code at Mon Dec 05 17:59:42 CET 2011
        [junit]
        [junit]
        [junit] Sleeping for 10 seconds
        [junit]
        [junit]
        [junit] Using source code
        [junit] Instantiating bean
        [junit] Putting into scriptcache (in parseClass): /MyBean.groovy
        [junit] lastmod: Mon Dec 05 17:59:52 CET 2011
        [junit] dependencies: [/MyBean.groovy]
        [junit] Instantiating extractor
        [junit] Putting into scriptcache (in parseClass): /Extractor.groovy
        [junit] lastmod: Mon Dec 05 17:59:52 CET 2011
        [junit] dependencies: [/Extractor.groovy]
        [junit]
        [junit]
        [junit] Sleeping for 10 seconds
        [junit]
        [junit]
        [junit] Modifying MyBean source code at Mon Dec 05 18:00:02 CET 2011
        [junit]
        [junit]
        [junit] Sleeping for 10 seconds
        [junit]
        [junit]
        [junit] Using modified source code
        [junit] Instantiating bean
        [junit] Calling isSourceNewer for entry MyBean
        [junit] Checking dependency /MyBean.groovy
        [junit] Putting into scriptcache (in isSourceNewer): /MyBean.groovy
        [junit] lastmod: Mon Dec 05 18:00:02 CET 2011
        [junit] dependencies: [/MyBean.groovy]
        [junit] Putting into scriptcache (in parseClass): /MyBean.groovy
        [junit] lastmod: Mon Dec 05 18:00:12 CET 2011
        [junit] dependencies: [/MyBean.groovy]
        [junit] Instantiating extractor
        [junit] Calling isSourceNewer for entry Extractor
        [junit] Checking dependency /Extractor.groovy
        [junit] Not putting into scriptcache (in isSourceNewer): /Extractor.groovy
        [junit] lastmod: Mon Dec 05 17:59:42 CET 2011
        [junit] depEntry.lastModified: Mon Dec 05 17:59:52 CET 2011

        Show
        Frans van Buul added a comment - 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. [junit] Writing source code at Mon Dec 05 17:59:42 CET 2011 [junit] [junit] [junit] Sleeping for 10 seconds [junit] [junit] [junit] Using source code [junit] Instantiating bean [junit] Putting into scriptcache (in parseClass): /MyBean.groovy [junit] lastmod: Mon Dec 05 17:59:52 CET 2011 [junit] dependencies: [/MyBean.groovy] [junit] Instantiating extractor [junit] Putting into scriptcache (in parseClass): /Extractor.groovy [junit] lastmod: Mon Dec 05 17:59:52 CET 2011 [junit] dependencies: [/Extractor.groovy] [junit] [junit] [junit] Sleeping for 10 seconds [junit] [junit] [junit] Modifying MyBean source code at Mon Dec 05 18:00:02 CET 2011 [junit] [junit] [junit] Sleeping for 10 seconds [junit] [junit] [junit] Using modified source code [junit] Instantiating bean [junit] Calling isSourceNewer for entry MyBean [junit] Checking dependency /MyBean.groovy [junit] Putting into scriptcache (in isSourceNewer): /MyBean.groovy [junit] lastmod: Mon Dec 05 18:00:02 CET 2011 [junit] dependencies: [/MyBean.groovy] [junit] Putting into scriptcache (in parseClass): /MyBean.groovy [junit] lastmod: Mon Dec 05 18:00:12 CET 2011 [junit] dependencies: [/MyBean.groovy] [junit] Instantiating extractor [junit] Calling isSourceNewer for entry Extractor [junit] Checking dependency /Extractor.groovy [junit] Not putting into scriptcache (in isSourceNewer): /Extractor.groovy [junit] lastmod: Mon Dec 05 17:59:42 CET 2011 [junit] depEntry.lastModified: Mon Dec 05 17:59:52 CET 2011
        Hide
        blackdrag blackdrag added a comment -

        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.

        Show
        blackdrag blackdrag added a comment - 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.
        Hide
        Frans van Buul added a comment - - 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;
        }
        
        Show
        Frans van Buul added a comment - - 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 ; }
        Hide
        Frans van Buul added a comment -

        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.

        Show
        Frans van Buul added a comment - 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.
        Hide
        Frans van Buul added a comment - - 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.

        Show
        Frans van Buul added a comment - - 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.
        Hide
        David Smith added a comment - - 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.

        Show
        David Smith added a comment - - 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.
        Hide
        Frans van Buul added a comment -

        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

        Show
        Frans van Buul added a comment - 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
        Hide
        Scott Murphy added a comment -

        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

        Show
        Scott Murphy added a comment - 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
        Hide
        Guillaume Laforge added a comment -

        Frans, did you have time to integrate Jochen's suggestions in a new patch?

        Show
        Guillaume Laforge added a comment - Frans, did you have time to integrate Jochen's suggestions in a new patch?
        Hide
        blackdrag blackdrag added a comment -

        Frans seems not to have time right now

        Show
        blackdrag blackdrag added a comment - Frans seems not to have time right now
        Hide
        Stevo Slavic added a comment - - 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.

        Show
        Stevo Slavic added a comment - - 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.
        Hide
        blackdrag blackdrag added a comment -

        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

        Show
        blackdrag blackdrag added a comment - 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
        Hide
        blackdrag blackdrag added a comment -

        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.

        Show
        blackdrag blackdrag added a comment - 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.
        Hide
        blackdrag blackdrag added a comment -

        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

        Show
        blackdrag blackdrag added a comment - 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
        Hide
        David Smith added a comment -

        I'm testing w/1.8.8-SNAPSHOT and I'm getting the same result. The test is also still failing for me.

        Show
        David Smith added a comment - I'm testing w/1.8.8-SNAPSHOT and I'm getting the same result. The test is also still failing for me.
        Hide
        blackdrag blackdrag added a comment -

        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?

        Show
        blackdrag blackdrag added a comment - 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?
        Hide
        blackdrag blackdrag added a comment -

        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

        Show
        blackdrag blackdrag added a comment - 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
        Hide
        David Smith added a comment -

        Tried again, the tests did pass for me.

        Show
        David Smith added a comment - Tried again, the tests did pass for me.
        Hide
        blackdrag blackdrag added a comment -

        So you tried ReloadTest and the test just failed by saying the bean had the wrong value? Or was there any exception? Any idea what could be wrong?

        Show
        blackdrag blackdrag added a comment - So you tried ReloadTest and the test just failed by saying the bean had the wrong value? Or was there any exception? Any idea what could be wrong?
        Hide
        David Smith added a comment -

        Everything is good. All tests in ReloadTest passed for me. No exceptions.

        Show
        David Smith added a comment - Everything is good. All tests in ReloadTest passed for me. No exceptions.
        Hide
        blackdrag blackdrag added a comment -

        Ah sorry David... don't know what I was smoking You actually confirmed it being fixed. Thanks for the help

        Show
        blackdrag blackdrag added a comment - Ah sorry David... don't know what I was smoking You actually confirmed it being fixed. Thanks for the help
        Hide
        Alessio Stalla added a comment -

        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.

        Show
        Alessio Stalla added a comment - 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.
        Hide
        blackdrag blackdrag added a comment -

        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.

        Show
        blackdrag blackdrag added a comment - 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.
        Hide
        Alessio Stalla added a comment -

        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.

        Show
        Alessio Stalla added a comment - 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.
        Hide
        blackdrag blackdrag added a comment -

        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?

        Show
        blackdrag blackdrag added a comment - 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?
        Hide
        Alessio Stalla added a comment -

        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.

        Show
        Alessio Stalla added a comment - 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.
        Hide
        Ben Walding added a comment -

        Closing now that spam removed.

        Show
        Ben Walding added a comment - Closing now that spam removed.
        Hide
        Alessio Stalla added a comment -

        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?

        Show
        Alessio Stalla added a comment - 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?
        Hide
        blackdrag blackdrag added a comment -

        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.

        Show
        blackdrag blackdrag added a comment - 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.
        Hide
        blackdrag blackdrag added a comment -

        I filled GROOVY-5713 as follow-up issue

        Show
        blackdrag blackdrag added a comment - I filled GROOVY-5713 as follow-up issue
        Hide
        Alessio Stalla added a comment -

        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.

        Show
        Alessio Stalla added a comment - 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.
        Hide
        blackdrag blackdrag added a comment -

        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?

        Show
        blackdrag blackdrag added a comment - 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?
        Hide
        Alessio Stalla added a comment -

        Nope, I ran the test again with 1.8.9-SNAPSHOT from Git and it still fails nondeterministically.

        Show
        Alessio Stalla added a comment - Nope, I ran the test again with 1.8.9-SNAPSHOT from Git and it still fails nondeterministically.
        Hide
        blackdrag blackdrag added a comment -

        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.

        Show
        blackdrag blackdrag added a comment - 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.
        Hide
        Alessio Stalla added a comment -

        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.

        Show
        Alessio Stalla added a comment - 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.
        Hide
        blackdrag blackdrag added a comment -

        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

        Show
        blackdrag blackdrag added a comment - 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
        Hide
        blackdrag blackdrag added a comment -

        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

        Show
        blackdrag blackdrag added a comment - 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

          People

          • Assignee:
            blackdrag blackdrag
            Reporter:
            David Smith
          • Votes:
            4 Vote for this issue
            Watchers:
            7 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: