How to reduce the time before script execution begins

[John]

We're wondering if you have any guidance as to how we may reduce the interval between the entry of our filter and the execution of the first line of our script code (via GaelykServlet). There are frequent cases where the time of the log message from our filter is more than a second before the log message emitted at the beginning of the script.

We don't observe anything similar while running in the development server, so it seems likely that the delay might be related to retrieving the script files from wherever they're deployed in the appengine network. Unfortunately, I don't see any logging in the GroovyScriptEngine, where the retrieval and compilation is done, so there's not much to go on. Since I can't pinpoint whether the time is primarily taken in Gaelyk code or in GroovyServlet/GroovyScriptEngine, I figured I'd ask here, since everyone using Gaelyk would at least have some familiarity with AppEngine.

Of course, what I ultimately need to do is reduce the time between getting the request and running he script, so any ideas will be appreciated!

Thanks for taking time to read (and think about) this!
John

[Guillaume Laforge]

Hi John,

This "onse second" is for the first execution of that groovlet or template, or is it *every* time?

The first hit might take more time as the groovlet / template need be parsed and compiled, but subsequent hits are calling a compiled class somehow (in memory like any other loaded class), so there's no particular "fetching" of the script to be happenning there that could really slow things down.

There's a bit of logic in the Gaelyk filter to craft the final URL, and then the Gaelyk servlets to figure out to which groovlet corresponds that URL and send it the request, etc.

I haven't really measured that time though.

If you're using the routing system, though, I can tell you that if you're using some complex regular expressions for the routes, I noticed that sometimes it can take a fair bit of time to figure out which route matches the incoming URI. In some of the Gaelyk test cases, I have tests for that that I found quite slow when using some wide open regex (with double ** and things like that).

Also are you using the caching feature that you can apply to your routes to cache the output of groovlets and templates?

They also improve greatly the perceived responsiveness of your apps, as the content is delivered right from the filter rather than going through the servlets. So it might make sense to investigate that as well.

That's all I can really think of right now off the top of my head.

Guillaume

John

--
You've received this message because you've subscribed to the Gaelyk Google Group.
To send an email to the group, please write to: gae...@googlegroups.com
To unsuscribe from this group: gaelyk+un...@googlegroups.com
To show more options: http://groups.google.fr/group/gaelyk?hl=en

--
Guillaume Laforge
Groovy Project Manager
SpringSource, a division of VMware

Blog: http://glaforge.appspot.com/

Twitter: @glaforge

Google+: http://gplus.to/glaforge

[John]

Thanks very much, Guillaume!

We're still trying to figure out the circumstances that correlate with a slow load. It may be related to compiling the script for the first time, but without explicit logging, it's not easy to track which appengine instances have already compiled a given script. We don't observe this slowness in the development server; it seems unlikely that the route dispatching would be so dramatically slower on AppEngine. That's why I became concerned that GroovyScriptEngine looks like it's causing the script resource to be opened even if it has already been compiled.

I became concerned that the GroovyScriptEngine could be trying to read the script on each call because it looks like Groovy's AbstractHttpServlet.getResourceConnection will be used each time the script is referenced, and that calls openConnection if the servletContext.getContext returns non-null.

Since I don't see anything doing logging in this area, it's not clear what's occasionally slow. It would be nice to have log entries when the GroovyScriptEngine compiles a script (cache-miss), and also logging to indicate how long it takes to compute isSourceNewer(), since this loops through dependencies seeming to open each one.

Is there an easy way to set the CompilerConfig used by the GroovyScriptEngine? I'm curious whether changing the CompilerConfig.minimumCompilationInterval to 48.hours might reduce the delay we observe since that would (effectively) avoid the opening of the referenced classes: it appears the DEFAULT object provides a value of 100ms for this.

Maybe I'll see about putting some logging in at the level of GaelykServlet and see what can be manipulated from that point. Is there any guidance/examples for appropriate logging that would help me to put add it in a way that would make it easier to pull into a future version?

[Guillaume Laforge]

Hi John,

On Tue, Feb 14, 2012 at 01:18, John <jwb...@gmail.com> wrote:
> Thanks very much, Guillaume!
>
> We're still trying to figure out the circumstances that correlate with a
> slow load. It may be related to compiling the script for the first time, but
> without explicit logging, it's not easy to track which appengine instances
> have already compiled a given script. We don't observe this slowness in the
> development server; it seems unlikely that the route dispatching would be so
> dramatically slower on AppEngine. That's why I became concerned that
> GroovyScriptEngine looks like it's causing the script resource to be opened
> even if it has already been compiled.
>
> I became concerned that the GroovyScriptEngine could be trying to read the
> script on each call because it looks like Groovy's
> AbstractHttpServlet.getResourceConnection will be used each time the script
> is referenced, and that calls openConnection if the
> servletContext.getContext returns non-null.
>
> Since I don't see anything doing logging in this area, it's not clear what's
> occasionally slow. It would be nice to have log entries when the
> GroovyScriptEngine compiles a script (cache-miss), and also logging to
> indicate how long it takes to compute isSourceNewer(), since this loops
> through dependencies seeming to open each one.
>
> Is there an easy way to set the CompilerConfig used by the
> GroovyScriptEngine?

The GroovyScriptEngine used in the GroovyServlet (extended by
GaelykServlet) is private, but Groovy allows you to access such
private information if needed. And then, on the GroovyScriptEngine,
there's a getter to get the CompilerConfiguration.
A bit cleaner would be to extend GroovyServlet to override the
createGroovyScriptEngine() method to provide your own, or simply to
keep track of it so you can access it more easily.

> I'm curious whether changing the
> CompilerConfig.minimumCompilationInterval to 48.hours might reduce the delay
> we observe since that would (effectively) avoid the opening of the
> referenced classes: it appears the DEFAULT object provides a value of 100ms
> for this.

There's a bug in the reloading of GroovyScriptEngine that may very
well come into play.
But it's not been properly fixed yet, as it's a bit tricky.
Perhaps it's related to that, but I'm not sure.

> Maybe I'll see about putting some logging in at the level of GaelykServlet
> and see what can be manipulated from that point. Is there any
> guidance/examples for appropriate logging that would help me to put add it
> in a way that would make it easier to pull into a future version?

The GroovyScriptEngine doesn't have any logging, but the GroovyServlet
is using the servlet context logger.

Guillaume