Slow shiro initialization on Google App Engine

[Geir Engdahl <ge...@gmail.com>]

Hi,

I am using Shiro 1.2.0 in an App Engine project, and have run into some
issues with extremely long instance startup times (it frequently reaches the
60 second limit and times out entirely). It looks like it is Shiro-related
from the server logs (excerpt):

D 2012-08-29 13:38:52.691
org.apache.shiro.web.env.IniWebEnvironment getDefaultIni: Discovered
non-empty INI configuration at location '/WEB-INF/shiro.ini'.  Using for
configuration.
D 2012-08-29 13:38:53.596
org.apache.shiro.config.IniFactorySupport createInstance: Creating instance
from Ini [sections=main]
D 2012-08-29 13:39:14.337
org.apache.shiro.web.filter.authc.FormAuthenticationFilter setLoginUrl:
Adding login url to applied paths.
D 2012-08-29 13:39:29.246
org.apache.commons.beanutils.converters.AbstractConverter setDefaultValue:
Setting default value: false

As you can see it takes 20 seconds IniFactorySupport.createInstance to the
next log line. I have two realms in my shiro.ini file:

# =======================
# Shiro INI configuration
# =======================

[main]
# Objects and their properties are defined here, 
# Such as the securityManager, Realms and anything
# else needed to build the SecurityManager

# password hashing specification
sha256Matcher = org.apache.shiro.authc.credential.HashedCredentialsMatcher
sha256Matcher.hashAlgorithmName=SHA-256

dsRealm = com.gebweb.items.server.DatastoreRealm
dsRealm.credentialsMatcher = $sha256Matcher

fbCredentialsMatcher =
com.gebweb.items.server.facebook.FacebookCredentialsMatcher
fbRealm = com.gebweb.items.server.facebook.FBRealm
fbRealm.credentialsMatcher = $fbCredentialsMatcher
securityManager.realms = $dsRealm, $fbRealm

[users]
# The 'users' section is for simple deployments
# when you only need a small number of statically-defined 
# set of User accounts.

[roles]
# The 'roles' section is for simple deployments
# when you only need a small number of statically-defined
# roles.

[urls]
# The 'urls' section is used for url-based security
# in web applications.  We'll discuss this section in the
# Web documentation

I've searched around, and found no-one with the same problem, so I think I'm
doing something wrong. I have a couple of theories at this point:
1. I'm running out of memory and there is some disk swapping going on (but I
have tried doubling the available RAM from 128 MB to 256 MB and it makes no
difference).
2. There is a problem with one of the Realms (I tried commenting out each
realm from the .ini file one by one, but both attempts yielded similar
results - maybe both are broken?)
3. Parsing annotations is causing the slowness. I don't know how to
configure Shiro so annotations are turned off. If anyone knows, I'd be happy
to try it.

Full stacktrace (and logs) + the custom realms references from the shiro.ini
file are available at http://gebweb.net/shiro/ .

Would much appreciate it if anyone has any ideas.

Geir



--
View this message in context: http://shiro-user.582556.n2.nabble.com/Slow-shiro-initialization-on-Google-App-Engine-tp7577760.html
Sent from the Shiro User mailing list archive at Nabble.com.

Re: Slow shiro initialization on Google App Engine

[Geir Engdahl <ge...@gmail.com>]

Les Hazlewood-2 wrote
> 
> 
> Could it be that ClassLoader lookup (or repeated ClassLoader lookup,
> as would be done with reflection-based configuration like shiro.ini)
> is slow on Google App Engine?  Is there a latency based on where the
> actual class files reside?
> 
> 

I wrote a custom shiroEnvironmentClass which sets up the necessary
configuration programmatically, and it sped up the startup from timing out
at around 60 seconds to finishing in less than a second

org.apache.shiro.web.env.EnvironmentLoader initEnvironment: Shiro
environment initialized in 320 ms.

I still don't know why the reflection-based builder was so slow in the App
Engine environment, while other users did not see this issue.

Thanks for the pointers,

Geir



--
View this message in context: http://shiro-user.582556.n2.nabble.com/Slow-shiro-initialization-on-Google-App-Engine-tp7577760p7577776.html
Sent from the Shiro User mailing list archive at Nabble.com.

Re: Slow shiro initialization on Google App Engine

[Les Hazlewood <lh...@apache.org>]

Hi Geir,

Based on the stack trace, the 1.2.0 ReflectionBuilder source code [1]
shows it is failing during a Commons BeanUtils call that looks a
JavaBeans PropertyDescriptor on a configured object in shiro.ini:

PropertyDescriptor descriptor =
PropertyUtils.getPropertyDescriptor(object, propertyName);

The relevant stack trace indicates that the ClassLoader lookup of the
bytes of the actual object class (down to FileInputStream) is failing:

Caused by: com.google.apphosting.api.DeadlineExceededException: This
request (1f30ed149a83a157) started at 2012/08/29 11:38:38.702 UTC and
was still executing at 2012/08/29 11:39:38.196 UTC.
	at com.google.appengine.runtime.Request.process-1f30ed149a83a157(Request.java)
	at java.io.FileInputStream.readBytes(Native Method)
	at java.io.FileInputStream.read(FileInputStream.java:231)
	at sun.misc.Resource.getBytes(Resource.java:124)
	at java.net.URLClassLoader.defineClass(URLClassLoader.java:273)
	at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:616)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:266)
	at java.lang.Class.getDeclaredMethods0(Native Method)
	at java.lang.Class.privateGetDeclaredMethods(Class.java:2444)
	at java.lang.Class.getDeclaredMethods(Class.java:1808)
	at java.beans.Introspector$1.run(Introspector.java:1324)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.beans.Introspector.getPublicDeclaredMethods(Introspector.java:1322)
	at java.beans.Introspector.getTargetMethodInfo(Introspector.java:1188)
	at java.beans.Introspector.getBeanInfo(Introspector.java:423)
	at java.beans.Introspector.getBeanInfo(Introspector.java:189)
	at org.apache.commons.beanutils.PropertyUtilsBean.getPropertyDescriptors(PropertyUtilsBean.java:980)


Could it be that ClassLoader lookup (or repeated ClassLoader lookup,
as would be done with reflection-based configuration like shiro.ini)
is slow on Google App Engine?  Is there a latency based on where the
actual class files reside?

I'm not entirely sure why you're experiencing this particular issue -
I know that other GAE users use Shiro without problems - I just can't
speak to this particular issue.

[1] https://svn.apache.org/repos/asf/shiro/tags/shiro-root-1.2.0/core/src/main/java/org/apache/shiro/config/ReflectionBuilder.java

HTH,

--
Les Hazlewood | @lhazlewood
CTO, Stormpath | http://stormpath.com | @goStormpath | 888.391.5282
Stormpath wins GigaOM Structure Launchpad Award! http://bit.ly/MvZkMk