groovy
  1. groovy
  2. GROOVY-4001

Grapes/Grab spending time checking remote repositories every 3rd run?

    Details

    • Type: Bug Bug
    • Status: Closed Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 1.7.0
    • Fix Version/s: 2.0-rc-1
    • Component/s: Grape
    • Labels:
      None
    • Environment:
      Groovy Version: 1.7.0, Java HotSpot(TM) 64-Bit Server VM (build 14.3-b01-101, mixed mode), OSX 10.6.2, 2.8GHz Core2Duo mac book pro, 4G memory, SSD disk, 100Mbit internet
    • Number of attachments :
      3

      Description

      This is a performance issue with grapes. I have two groovy files:

      • A httpServer.groovy (attached) which runs an embedded jetty server and responds to http post requests
      • A httpClient.groovy (attached) which runs HttpBuilder and does a http post to the server in the other script

      both groovy files download dependencies using @Grab annotations and they both work.

      Weirdness ensues in the following scenario:

      1. I have network connectivity enabled
      2. I delete my grapes cache
      3. I start the server script and wait of it to come up
      4. I run an infinite bash while loop which executes the client script and collects timings: 'while true ; do time groovy -d httpClient.groovy ; done'


      Console logs of both client and server runs attached. It turns out that the client script takes about 4 seconds to run two times and then every third time it takes 25-30 seconds to run. I've verified this over hundreds of runs and it does not seem like a random occurrence of say network congestion or cpu load. In the attached console logs we can see that the server takes 1-5ms to handle requests, but the client script trundles along in a sequence of 4s, 4s, 25s, 4s, 4s, 25s etc.

      If I turn off my nic the timings become deterministic: 4s, 4s, 4s

      I have also tried running against the RC2 release of the http-builder package with identical results. As I believe the snapshot and RC2 versions are served by different remote repos, this would lower the probability that this is a remote repo issue. I also removed my ~/.groovy/grapeConfig.xml before the test.

      So a couple of questions:

      1. what is going on here
      2. is there any way to force debug logging for grapes during script execution to find out what it is actually doing


      I suspect this issue might be caused by the check-for-new-version-every-time snapshot jar handling logic. If so, maybe it would be a good idea to have an extra parameter to the grab annotation:

       
        @Grab(..., checkmodified=false)
      
      

      just as we do for repositories in the grapeConfig.xml file. This would basically instruct the resolver to not check the remote repos for a new version of this particular jar once one matching the version is in the local cache...even if the version has 'SNAPSHOT' or 'RC2' at the end. As we don't always have control over 3rd party versioning (http-builder latest stable is for example RC2 which I suspect is treated the same way as a snapshot release), it would be nice to be able to force your script to run in 4 seconds insted of 30. Grapes gurus, you'll probably have a better solution, but figured I'd throw it out there.

      In summary, the above behavior makes calling the http-builder from groovy using grapes useless for me as the 30s delay is not acceptable in my current context. Any ideas or suggestions would be most welcome.

        Activity

        Hide
        Matias Bjarland added a comment -

        Apologies for attaching the same file three times.

        Show
        Matias Bjarland added a comment - Apologies for attaching the same file three times.
        Hide
        Merlyn Albery-Speyer added a comment -

        Looks to be a reasonable solution to me.

        Show
        Merlyn Albery-Speyer added a comment - Looks to be a reasonable solution to me.
        Hide
        Merlyn Albery-Speyer added a comment - - edited

        I get the pattern you outlined. I switched to the RC2 version to remove the GrabResolver from the mix:

        //@GrabResolver(name='',  root='http://repository.codehaus.org')
        @Grab('org.codehaus.groovy.modules.http-builder:http-builder:0.5.0-RC2')
        

        With:

              <ibiblio name="codehaus" root="http://repository.codehaus.org/" m2compatible="true"/>
              <ibiblio name="ibiblio" m2compatible="true"/>
              <ibiblio name="java.net2" root="http://download.java.net/maven/2/" m2compatible="true"/>
        

        I get:
        19s, 4s, 4s, 19s, 4s, 4s, 19s, etc.

        With:

              <ibiblio name="codehaus" root="http://repository.codehaus.org/" m2compatible="true" checkmodified="false"/>
              <ibiblio name="ibiblio" m2compatible="true" checkmodified="false"/>
              <ibiblio name="java.net2" root="http://download.java.net/maven/2/" m2compatible="true" checkmodified="false"/>
        

        I get pretty much the same numbers:
        19s, 4s, 4s, 19s, 4s, 4s, 19s, etc.

        So I doubt that this is a checkmodified configuration issue.

        Show
        Merlyn Albery-Speyer added a comment - - edited I get the pattern you outlined. I switched to the RC2 version to remove the GrabResolver from the mix: //@GrabResolver(name='', root='http://repository.codehaus.org') @Grab('org.codehaus.groovy.modules.http-builder:http-builder:0.5.0-RC2') With: <ibiblio name= "codehaus" root= "http: //repository.codehaus.org/" m2compatible= " true " /> <ibiblio name= "ibiblio" m2compatible= " true " /> <ibiblio name= "java.net2" root= "http: //download.java.net/maven/2/" m2compatible= " true " /> I get: 19s, 4s, 4s, 19s, 4s, 4s, 19s, etc. With: <ibiblio name= "codehaus" root= "http: //repository.codehaus.org/" m2compatible= " true " checkmodified= " false " /> <ibiblio name= "ibiblio" m2compatible= " true " checkmodified= " false " /> <ibiblio name= "java.net2" root= "http: //download.java.net/maven/2/" m2compatible= " true " checkmodified= " false " /> I get pretty much the same numbers: 19s, 4s, 4s, 19s, 4s, 4s, 19s, etc. So I doubt that this is a checkmodified configuration issue.
        Hide
        Merlyn Albery-Speyer added a comment -

        I tried building a distribution of groovy using the latest snapshot of ivy. No change in the behaviour.

        Show
        Merlyn Albery-Speyer added a comment - I tried building a distribution of groovy using the latest snapshot of ivy. No change in the behaviour.
        Hide
        Merlyn Albery-Speyer added a comment - - edited

        This setting may be the answer:

        <chain name="downloadGrapes" returnFirst="true">

        in ~/.groovy/grapeConfig.xml:

        <ivysettings>
        <settings defaultResolver="downloadGrapes"/>
        <resolvers>
        <chain name="downloadGrapes" returnFirst="true">
        <filesystem name="cachedGrapes">
        <ivy pattern="$

        {user.home}/.groovy/grapes/[organisation]/[module]/ivy-[revision].xml"/>
        <artifact pattern="${user.home}

        /.groovy/grapes/[organisation]/[module]/[type]s/[artifact][revision]([classifier]).[ext]"/>
        </filesystem>
        <!-- todo add 'endorsed groovy extensions' resolver here -->
        <ibiblio name="codehaus" root="http://repository.codehaus.org/" m2compatible="true"/>
        <ibiblio name="ibiblio" m2compatible="true"/>
        <ibiblio name="java.net2" root="http://download.java.net/maven/2/" m2compatible="true"/>
        </chain>
        </resolvers>
        </ivysettings>

        http://ant.apache.org/ivy/history/2.0.0-alpha2/resolver/chain.html

        Show
        Merlyn Albery-Speyer added a comment - - edited This setting may be the answer: <chain name="downloadGrapes" returnFirst="true"> in ~/.groovy/grapeConfig.xml: <ivysettings> <settings defaultResolver="downloadGrapes"/> <resolvers> <chain name="downloadGrapes" returnFirst="true"> <filesystem name="cachedGrapes"> <ivy pattern="$ {user.home}/.groovy/grapes/ [organisation] / [module] /ivy- [revision] .xml"/> <artifact pattern="${user.home} /.groovy/grapes/ [organisation] / [module] / [type] s/ [artifact] [revision] ( [classifier] ). [ext] "/> </filesystem> <!-- todo add 'endorsed groovy extensions' resolver here --> <ibiblio name="codehaus" root="http://repository.codehaus.org/" m2compatible="true"/> <ibiblio name="ibiblio" m2compatible="true"/> <ibiblio name="java.net2" root="http://download.java.net/maven/2/" m2compatible="true"/> </chain> </resolvers> </ivysettings> http://ant.apache.org/ivy/history/2.0.0-alpha2/resolver/chain.html
        Hide
        Matias Bjarland added a comment -

        A year later...

        Figured as some time and a few groovy versions have passed by it might be worth commenting on this issue again.

        Given the following groovy script:

        test.groovy
         
        #!/usr/bin/env groovy
        
        @Grab('org.fusesource.jansi:jansi:1.5')
        @Grab('net.sf.jopt-simple:jopt-simple:3.2')
        @Grab('com.amazonaws:aws-java-sdk:1.1.8')
        @Grab('org.codehaus.gpars:gpars:0.11')
        
        import org.fusesource.jansi.*
        
        println "Initializing..."
        

        we get a run time of 30 seconds on a late model mac book pro with an SSD (i.e. not a problem with hardware) and a 100/10Mbit internet connection (i.e. not a problem with network connectivity). Note also that all the referenced resources have specific versions on them (not ranges etc) and that they are not snapshots. I am left a bit confused as to why ivy would even want to go out and check repositories if it has already found an exact match for the artifact in the local repo.

        Adding the returnFirst="true" flag in the grapeConfig.xml as per previous comment on this issue drops the execution time down to 2.4 seconds which is more or less acceptable. 30 seconds for a println is in my book a catastrophe and disqualifies the @Grab annotation from being used in a lot of scenarios.

        Now I agree that it is nice to have an actual fix with the grapeConfig.xml file. This however removes the portability of a script. I can now not send this file to my colleague or deploy it to a hundred servers without going through some secret ivy voodoo (grapeConfig.xml) on each machine where the script is deployed.

        I would therefore still advocate an addition to the @Grab annotation where we could have something like:

        Possible @Grab Annotation Syntax
          @Grab(..., returnFirst=true)
        

        where I think that the default should be returnFirst=true. Also I still think it would be really useful if there was a:

          @Grab(..., debug=true)
        

        or a system property we could set, or any other way to get grapes to actually log what it is doing and spending those 30 seconds of my life on.

        Show
        Matias Bjarland added a comment - A year later... Figured as some time and a few groovy versions have passed by it might be worth commenting on this issue again. Given the following groovy script: test.groovy #!/usr/bin/env groovy @Grab('org.fusesource.jansi:jansi:1.5') @Grab('net.sf.jopt-simple:jopt-simple:3.2') @Grab('com.amazonaws:aws-java-sdk:1.1.8') @Grab('org.codehaus.gpars:gpars:0.11') import org.fusesource.jansi.* println "Initializing..." we get a run time of 30 seconds on a late model mac book pro with an SSD (i.e. not a problem with hardware) and a 100/10Mbit internet connection (i.e. not a problem with network connectivity). Note also that all the referenced resources have specific versions on them (not ranges etc) and that they are not snapshots. I am left a bit confused as to why ivy would even want to go out and check repositories if it has already found an exact match for the artifact in the local repo. Adding the returnFirst="true" flag in the grapeConfig.xml as per previous comment on this issue drops the execution time down to 2.4 seconds which is more or less acceptable. 30 seconds for a println is in my book a catastrophe and disqualifies the @Grab annotation from being used in a lot of scenarios. Now I agree that it is nice to have an actual fix with the grapeConfig.xml file. This however removes the portability of a script. I can now not send this file to my colleague or deploy it to a hundred servers without going through some secret ivy voodoo (grapeConfig.xml) on each machine where the script is deployed. I would therefore still advocate an addition to the @Grab annotation where we could have something like: Possible @Grab Annotation Syntax @Grab(..., returnFirst= true ) where I think that the default should be returnFirst=true. Also I still think it would be really useful if there was a: @Grab(..., debug= true ) or a system property we could set, or any other way to get grapes to actually log what it is doing and spending those 30 seconds of my life on.
        Hide
        Matias Bjarland added a comment -

        Another year passes by...

        I can add a small addendum to this issue. To enable logging for the ivy resolution in a specific groovy execution you can use the "ivy.message.logger.level" system property:

        $ groovy -Divy.message.logger.level=4 test.groovy
        
        Show
        Matias Bjarland added a comment - Another year passes by... I can add a small addendum to this issue. To enable logging for the ivy resolution in a specific groovy execution you can use the "ivy.message.logger.level" system property: $ groovy -Divy.message.logger.level=4 test.groovy
        Hide
        blackdrag blackdrag added a comment -

        I looked into this a bit and I decided for now to use a modified default configuration given to grape. It can be overridden by a local config any time, so I guess this should be ok. At least it solves your problem. Groovy 2.0 beta 4 will contain that change.

        Show
        blackdrag blackdrag added a comment - I looked into this a bit and I decided for now to use a modified default configuration given to grape. It can be overridden by a local config any time, so I guess this should be ok. At least it solves your problem. Groovy 2.0 beta 4 will contain that change.

          People

          • Assignee:
            blackdrag blackdrag
            Reporter:
            Matias Bjarland
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: