Infinispan 4.2.1.FINAL as 2nd level hib cache, very slow startup

[tlvenn]

Hi,

I remember discussing this briefly with Galder sometimes ago and I didnt follow up back then.

My console shows that 10seconds are eaten by IS at startup.

We recently profiled our webapp startup and we noticed that IS is throwing 13 225 NoSuchMethodException !!

It might explain partially why it is so slow.

Please see the attache screenshot, for reference IS is instanciated around 500 caches.

[sannegrinovero]

Hi Chris,

that's a good catch and certainly worth investigating, but it doesn't justify 10 seconds delay, as we have much quicker startup in several tests.

It is more likely that you're waiting for some timeout. I guess this is a clustered configuration, and the node you're starting is waiting to find some peers, you can configure a shorter timeout, or tune the number of expected nodes; if you can have him ping an existing node satisfying the join request is should start very quickly, if this is a developers environment and you're not expecting it to join another node, you should configure it for LOCAL only so that the clustering stack isn't started at all.

[tlvenn]

The thing is, even with a config as short as: <infinispan/>

it still takes about 10 seconds as shown below:

20:01:10,868 [main] INFO  infinispan.factories.GlobalComponentRegistry - [No session]Infinispan version: Infinispan 'Ursus' 4.2.1.FINAL

20:01:19,171 [main] INFO  core.controller.IndexManagerImpl - [No session]Building indices for com.......

[sannegrinovero]

Both org.infinispan.util.BeanUtils and standard Java serialization make extensive use of NoSuchMethodException to introspect the classes, so they might be the cause of all those invocations, but that's pretty standard behaviour so we need to understand why this is slower for you.

Since you're profiling it, could you look at where the time is spent?

Why do you think the 10 seconds are spent by these exceptions?

If you could send a test and attach it to a new JIRA issue, I'll be glad to have a deep look.

[tlvenn]

Throwing 13000 exceptions while probing classes is not desirable, it's for sure time consuming as a lot of things happen when an exception is thrown in the JVM, like creating the stack trace etc... I am pretty sure you could cache some reflection lookups to avoid unnecessary over head.

I will have a look on where the time is going and I am not saying that those 10seconds are created by those exceptions alone, but it cant help.

It's impossible to create a test as we are talking about a pretty complex and huge web app that I just cant bundle but I will see what I can find with the profiler.

Thanks for your hints, hopefully we can find what is going on...

[sannegrinovero]

Hi Chris,

I've been looking into why it's inspecting these classes, and it seems to me that it's not needed at all; so I've asked on the dev. mailing list where some other developers agreed that maybe we can remove it; though before doing it I would like to hear who added this code initially.

Could you try patching it yourself, and see if the performance improves? what I did is in method

"org.infinispan.factories.AbstractComponentRegistry.getOrCreateComponent(Class<T>, String)"

I replaced

// see if this has been injected externally.

component = getFromConfiguration(componentClass);

with component = null;

not one of our 1000+ tests failed, so I would be curious to hear from you if this solves the issue while I figure out what this code's purpose was.

[sannegrinovero]

the link to the discussion on the mailing list:

http://infinispan.markmail.org/thread/xdqj4kyrgyjjbvy4

feel free to join there to report your findings and support your cause

Also consider that stacktraces are created lazily, so if an exception is swallowed no stacktrace is generated: not saying they are extremely cheap, but not expensive either.

[sannegrinovero]

Chris,

those illegal invocations are going to be removed in version 5.0.0.

thanks for reporting !

This is the patch in case you want to try it out:

https://github.com/maniksurtani/infinispan/commit/3bb5748b587025449021f459f1315a55cfbad226

[tlvenn]

Glad you worked out those exceptions, just checked with the 5.0.0-FINAL and they are gone

However unfortunately, it didnt solve at all my startup performance issue, still near 10sec with 4.X and with the 5.X, it's crazy worse, a wooping 2 minutes....

00:22:43,482 [main] INFO  infinispan.factories.GlobalComponentRegistry - [No session]ISPN000128: Infinispan version: Infinispan 'Pagoa' 5.0.0.FINAL

00:25:09,891 [main] INFO  core.controller.IndexManagerImpl - [No session]Building indices for com...

I restarted our webapp with yourkit and find attached the hotspots and the call tree. I didnt profile the whole IS initialization, it was taking way too long with the profiler but at least 283 entity regions were created and 158 collections so it should be plenty enough.

[tlvenn]

I am also suprise by the level of recursivity that seems to happen when the cache is created.

[sannegrinovero]

Hi Chris,

thanks, those graphs are very useful. It seems you're the first user using so many caches, keep your feedback coming.

I've opened ISPN-1315 to track the amount of loggers, and sent a patch for 5.1. I'm deploying a 5.1.0-SNAPSHOT to the maven repositories right now containing a patch, could you please try it out and see if it starts in a reasonable time?

[tlvenn]

Tried 5.1.0-Snapshot and it did solve the issue with the IS logger sub system. Times are back to what i was seeing with 4.2.X :

14:39:38,397 [main] INFO  infinispan.factories.GlobalComponentRegistry - [No session]ISPN000128: Infinispan version: Infinispan 'Brahma' 5.1.0-SNAPSHOT

14:40:20,604 [main] INFO  core.controller.IndexManagerImpl - [No session]Building indices for com................

Calltree and Hotspot for this version:

Let me know if there is anything further I can provide. I still feel than 10sec is way too long for creating those caches

Thanks for the help !

[sannegrinovero]

thanks again Chris,

I've opened an issue to track this one, but it's not going to give you a big win anyway as it seems Infinispan is now taking "only" 40% of your time, the rest being consumed by Hibernate. As an Hibernate developer I'm interested in more details of that as well, but only if it affects Hibernate4 as we already made many improvements in this area.

On the Infinispan issue, I'm unlikely to be able to try solving it this month, would you like to try patching it yourself and sending it to us?

Seems you're already on a good track, and have an excellent test to check the effectiveness of your changes.

[manik]

This could have to do with all of the annotation scanning going on in that method.  I didn't cache the annotation scanning originally since typically I'd expect each component to be "scanned" for annotations just once.  However, when you create several hundred named caches, this gets scanned that many times.  :-)

One option is to cache the results of annotation scanning, but another interesting approach (since these are internal components that get scanned) is to use Jandex in Infinispan's build process, so that annotations of internal types are pre-scanned and indexed for quick runtime lookup.

[manik]

Have a look at https://github.com/infinispan/infinispan/pull/535 - this contains a patch that uses Jandex at build time and refers to the index at runtime.  If you feel like building from my topic branch and giving this a go, I'd love to hear your feedback.