[rajiv.shivane]

adinn  wrote:

Thanks for the confirmation. I was beginning to doubt my own sanity or, worse, my ability to read code correctly! (some of my best code has been both readable and, arguably, borderline insane :-)

Wow, that's an interesting outcome. I had never considered that this code might be hostage to a weak reference.

Ha ha ha ... who would have thunk! Definitely the insanity is on our side, not yours!

adinn  wrote:

Glad to hear it is now working. Let me know how much it helps performance once you are able to run a test. If it is really significant then I need to do a bit of explaining to one or two people who have mentioned a similar performance issue.

I will work with the customers and get the numbers tomorrow. From the debugging logs we took the other day, it looked like this fix should make a lot of difference in their app that uses many JAXB Bean each with many properties. Looks like at run time a sub-class of "com.sun.xml.internal.bind.v2.runtime.unmarshaller.Receiver" is created for each of property access (not each bean!) .. and there were many requests to LoadCache looking for the Receiver class (which is in boot classpath) using the application classloader. Fingers crossed!

[rajiv.shivane]

adinn  wrote:

Glad to hear it is now working. Let me know how much it helps performance once you are able to run a test. If it is really significant then I need to do a bit of explaining to one or two people who have mentioned a similar performance issue.

I heard back from the user sooner than expected, clearly they were eager to try out the fix

Here are their server startup times:

No agent: 350s

JInsight with byteman-3.0.11: 956s

JInsight with byteman-4.0.2-SNAPSHOT: 480s

The LoadCache fix along with 4.0.2 move has halved the startup time. Can't wait to ship the new version!

However, there is still scope for improvement. Will give you an update when we are able to investigate further.

Thanks,

Rajiv

[rajiv.shivane]

Hi Andrew,

rajiv.shivane  wrote:

The LoadCache fix along with 4.0.2 move has halved the startup time. Can't wait to ship the new version!

However, there is still scope for improvement. Will give you an update when we are able to investigate further.

We were profiling the updated version. The following line is still hot:

//LoadCache.lookupClass(...) - Line 94
Class[] classes = inst.getInitiatedClasses(loader);

We added a log-point on this line to log the current thread, the classname and the baseLoader parameters.

Here is a snippet of the output log:

[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.RejoinAwareNonstopStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.RejoinAwareNonstopStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.RejoinAwareNonstopStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.RejoinAwareNonstopStore:null
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.NonstopStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.NonstopStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.NonstopStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.NonstopStore:null
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.transaction.xa.XATransactionStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.transaction.xa.XATransactionStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.transaction.xa.XATransactionStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.transaction.xa.XATransactionStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.transaction.AbstractTransactionStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.transaction.AbstractTransactionStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.transaction.AbstractTransactionStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.transaction.AbstractTransactionStore:null
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.store.AbstractStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.AbstractStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.AbstractStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.AbstractStore:null
[localhost-startStop-1]net.sf.ehcache.bootstrap.BootstrapCacheLoader:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.bootstrap.BootstrapCacheLoader:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.bootstrap.BootstrapCacheLoader:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.bootstrap.BootstrapCacheLoader:null
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.RejoinAwareNonstopStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.RejoinAwareNonstopStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.RejoinAwareNonstopStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.RejoinAwareNonstopStore:null
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.NonstopStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.NonstopStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.NonstopStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.NonstopStore:null
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.transaction.xa.XATransactionStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.transaction.xa.XATransactionStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.transaction.xa.XATransactionStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.transaction.xa.XATransactionStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.transaction.AbstractTransactionStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.transaction.AbstractTransactionStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.transaction.AbstractTransactionStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.transaction.AbstractTransactionStore:null
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.store.AbstractStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.AbstractStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.AbstractStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.AbstractStore:null
[localhost-startStop-1]net.sf.ehcache.bootstrap.BootstrapCacheLoader:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.bootstrap.BootstrapCacheLoader:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.bootstrap.BootstrapCacheLoader:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.bootstrap.BootstrapCacheLoader:null
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.RejoinAwareNonstopStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.RejoinAwareNonstopStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.RejoinAwareNonstopStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.RejoinAwareNonstopStore:null
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.NonstopStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.NonstopStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.NonstopStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.constructs.nonstop.store.NonstopStore:null
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.transaction.xa.XATransactionStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.transaction.xa.XATransactionStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.transaction.xa.XATransactionStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.transaction.xa.XATransactionStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null
[localhost-startStop-1]net.sf.ehcache.transaction.AbstractTransactionStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.transaction.AbstractTransactionStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.transaction.AbstractTransactionStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.transaction.AbstractTransactionStore:null
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.TerracottaStore:null
[localhost-startStop-1]net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$AppClassLoader@349885916
[localhost-startStop-1]net.sf.ehcache.store.Store:sun.misc.Launcher$ExtClassLoader@1002021887
[localhost-startStop-1]net.sf.ehcache.store.Store:null

Specifically the following entry occurs multiple times: net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177

I am not clear on the expected behavior, but I was hoping that a class-name+class-loader combination will appear only once in the logs. Could multiple-log entries mean that cache is not working as expected?

The complete log is accessible at: https://gist.github.com/rshivane/143ea5666bb9b16021b655931c285c3c

Thanks,

Rajiv

[adinn]

Hi Rajiv,

rajiv.shivane  wrote:

Hi Andrew,

We were profiling the updated version. The following line is still hot:

//LoadCache.lookupClass(...) - Line 94 Class[] classes = inst.getInitiatedClasses(loader);

. . .

Specifically the following entry occurs multiple times: net.sf.ehcache.store.Store:java.net.URLClassLoader@106374177

I am not clear on the expected behavior, but I was hoping that a class-name+class-loader combination will appear only once in the logs. Could multiple-log entries mean that cache is not working as expected?

Hmm, interesting :-)

It's quite possible that a lookup might fail to find one or more classes several times. In this case it looks very much like this is happening for reasons that are only to be expected. I'll explain that in a second but, first, I'll note that you con observe a pattern in the input that begins to hint at i) what is actually happening here and ii) why this cache is being used in the first place.

The repeats are not just for class Store.There are also repeats for classes TerracottaStore, AbstractStore, AbstractTransactionStore, XATransactionStore, NonstopStore and RejoinAwareNonstopStore. From the names these appear to be elements of either an interface or class hierarchy. That points to what is going on here which is that Byteman is trying to work out whether to inject into a newly loaded class, probably one of the Store classes right down at the bottom of this class/interface hierarchy. This also implies that there must be either interface rules or overriding rules (or both) in your rule set. The LoadCache lookups are happening because Byteman is having to traverse the supers/extends hierarchy of this class in order to see if a rule applies to any of the super classes or indirectly extended interfaces.

You might reasonably question why a cache populated using calls to inst.getIniitiatedClasses(loader) is needed for this purpose. Why doesn't Byteman just check the call getSuper() or getInterfaces() on the original Class<?> passed to the Transformer. Well, there's a good reason for that only it's more complicated than you might expect.

The super traversal needs to happen in the middle of trying to decide whether or not to transform a class i.e. in a callout from the JVM to the agent Transformer. Now, it might seem counter-intuitive to you but the JVM might only be in the early stages of loading the class it handed over to the Transformer. It will not necessarily have loaded and resolved the super class or any implemented interfaces. So, what happens if you call getSuper() or getInterfaces()? Well, the JVM just loads the relevant classes and hands them over. However, it knows it is doing this from inside a callout to a Transformer. It is not willing to re-enter the Transformer code (that's just how it is). So, if you try to use either of these methods you will be able to walk up the super/interface hierarchy looking for rules which apply to the current class and be able to inject them. However, as a result you miss your  chance to transform any of the supers that were not loaded. So, if you have a rule for CLASS ^AppFile METHOD open() you might successfully inject into LargeBinaryAppFile.open() but miss the chance to inject into BinaryAppFile.open() or AppFile.open().

Actually, the same problem also can occurs during the actual bytecode transformation once you have decided a ruel applies. Occasionally during trigger injection the injector code has to work out the minimal common super type for a slot in a local variable frame. If two paths through the code converge with a value of type A in one path and type B in another then the bytecode needs to be generated to correctly mark the frame slot at the join point as having type C where C is the lowest common super or A and B. You can cheat and guess Object but that actually causes verify errors in rare cases. So, once again you need to traverse the class (or interface) hierarchy but avoid loading classes.

So, this is the problem that classes BytecodeChecker and LoadedFileChecker and their helper class Loadcache exist to work around -- searching the super hierarchy without loading any classes. You don't know if the super actually has been loaded or not. However, you have the bytecode that is being transformed so you can always find the super name by reading it out of the bytecode. The same applies for the names of directly implemented interfaces. So that allows you to check one level of super or implemented interface rules. You also know the loader that the original class belongs to and that is enough to find the info needed to continue the lookup, the super's super and implemented interfaces or the interfaces that the current ones extend.

Now the best and cheapest option is to find out whether the super or interface already exists as a loaded class. If you can find a class then you can just rely on getSuper() or getInterfaces() from there on. You might naively just look through the full list of loaded classes until you find one with the correct name. However, that is fallible because different loaders may load the same class. Class LoadCache does a structured lookup, searching the loaded classes list of each successive loader from the original loader right up to the boot loader. It caches any classes it finds in the map for that loader and in the map for the originating loader because the same old classes often get looked up. However, in cases where the super or implemented interfaces have not been loaded there is no class to cache. What happens then?

Well, at that point a different strategy has to be adopted. If you cannot find an already loaded class you could still find the info you need from its bytecode. So, Byteman tries to load the .class file as a resource. This works for most classloaders, the bootstrap and system loader, jar loaders etc. I have not yet heard of cases where it fails but no doubt they exist. Once you have the super bytecode you can read out the super and implemented interface names, check those for rules and then rinse and repeat at the next level of the super/interface hierarchy. It would be possible to cache the bytecode in some equivalent of the LoadCache. However, since cases where large class hierarchies are loaded bottom up are i) rare and ii) don't often include a lot of classes there is not a lot of saving to be bought by doing this.

So, this appears to be what is happening here. The repeated lookups occur when one of the  store classes way down in a class hierarchy gets loaded bottom up. Note that this will happen when you have overriding or interface rules even though those rules may not apply to any of the Store classes. Imagine you have a CLASS ^Foo rule. Byteman can only find out that those rules don't apply to FooStore by checking the full hierarchy and finding that FooStore does not have Foo as a super.

Can you confirm whether or not i) the Store hierarchy involves classes or interfaces (or both) and ii) you are using overriding rules or interface rules (or both)? I think Byteman might be doing work to list indirectly implemented interfaces when there are no overriding rules which would mean it may be doing some of this lookup in cases where it is not needed.

Also, would you be able to confirm whether or not the LoadCache lookups are happening during transformation or during frame checking? If you log all calls to Transformer.getClassChecker and also add a log statement in TransformContext.findLeastCommonSuper you will be able to use the latter to identify which calls to getClassChecker are for frame lookups. If they are all (or mostly) for the latter case then improving the interface listing code is not really going to make any difference.

regards,

Andrew Dinn

[rajiv.shivane]

Hi Andrew,

First, thank you for the detailed explanation. Thanks to the comments in the code, I surmised why you couldn't use .getSuper() to navigate the hierarchy ... but your explanation lays it out very clearly. Thanks again for taking the time.

adinn  wrote:

Can you confirm whether or not i) the Store hierarchy involves classes or interfaces (or both) and ii) you are using overriding rules or interface rules (or both)? I think Byteman might be doing work to list indirectly implemented interfaces when there are no overriding rules which would mean it may be doing some of this lookup in cases where it is not needed.

Yes, Store hierarchy involves both classes and interfaces. Hierarchy view below (click to zoom). And yes, I am using overriding rules *and* interface rules. (The overriding/interface rules are not for ehcache ... but I realize that it doesn't matter, byteman still needs to check every class hierarchy to see if the override/interface rules will match).

adinn  wrote:

Also, would you be able to confirm whether or not the LoadCache lookups are happening during transformation or during frame checking? If you log all calls to Transformer.getClassChecker and also add a log statement in TransformContext.findLeastCommonSuper you will be able to use the latter to identify which calls to getClassChecker are for frame lookups. If they are all (or mostly) for the latter case then improving the interface listing code is not really going to make any difference.

I will have the schedule some time with the customer, this may take some time to confirm.

adinn  wrote:

However, since cases where large class hierarchies are loaded bottom up are i) rare and ii) don't often include a lot of classes there is not a lot of saving to be bought by doing this.

This assumption might not be holding up in our case. From the LoadCache log https://gist.github.com/rshivane/143ea5666bb9b16021b655931c285c3c  there are attempts to lookup same mysql/ehcache/jets3t classes again and again. I haven't verified class hierarchy for each of them, but from the names they look like they are part of same hierarchy (Connection, ConnectionImpl etc), like the ehcache Store hierarchy.

Also, thanks to inflation during reflection, there are a whole lot of calls to lookup sun.reflect.MethodAccessorImpl:java.net.URLClassLoader@106374177 (see the full LoadCache Log)

Given that there are many retries to lookup same class, along with inst.getInitiatedClasses(loader) still being hottest call in the profiler, makes me wonder if we can't optimize this further. getInitiatedClasses is probably cloning the class name array as it crosses the JNI boundary and we are iterating on the array (as opposed to a Map lookup). For example, when we load the .class as a resource, could we cache the BytecodeChecker in Transformer.java?

Thanks,

Rajiv

[adinn]

Hi Rajiv,

Apologies for the delayed response -- I have been busy investigating some issues associated with the latest OpenJDK security update release.

rajiv.shivane  wrote:

adinn   wrote:

Also, would you be able to confirm whether or not the LoadCache lookups are happening during transformation or during frame checking? If you log all calls to Transformer.getClassChecker and also add a log statement in TransformContext.findLeastCommonSuper you will be able to use the latter to identify which calls to getClassChecker are for frame lookups. If they are all (or mostly) for the latter case then improving the interface listing code is not really going to make any difference.

I will have the schedule some time with the customer, this may take some time to confirm.

Ok, thanks. It would help a lot to know whether frame checking tests are involved

adinn   wrote:

However, since cases where large class hierarchies are loaded bottom up are i) rare and ii) don't often include a lot of classes there is not a lot of saving to be bought by doing this.

This assumption might not be holding up in our case. From the LoadCache log https://gist.github.com/rshivane/143ea5666bb9b16021b655931c285c3c  there are attempts to lookup same mysql/ehcache/jets3t classes again and again. I haven't verified class hierarchy for each of them, but from the names they look like they are part of same hierarchy (Connection, ConnectionImpl etc), like the ehcache Store hierarchy.

Also, thanks to inflation during reflection, there are a whole lot of calls to lookup sun.reflect.MethodAccessorImpl:java.net.URLClassLoader@106374177 (see the full LoadCache Log)

There is a lot of interesting detail in that log.  A lot of the lookups are actually multiplied as traces because the trace shows a failure to find the class in a deployment loader and then again in the system, extension and bootstrap loaders. However, there are still quiet a lot of repeats.

I think it is pointless caching results for a DelegatingClassLoader. Lookups for a given class seem never to be repeated for the same loader. Caching the classes found on the next lookup is worth it though.

Given that there are many retries to lookup same class, along with inst.getInitiatedClasses(loader) still being hottest call in the profiler, makes me wonder if we can't optimize this further. getInitiatedClasses is probably cloning the class name array as it crosses the JNI boundary and we are iterating on the array (as opposed to a Map lookup). For example, when we load the .class as a resource, could we cache the BytecodeChecker in Transformer.java?

Yes, I think it might be wise to modify the LoadCache so it will retain either a Class found in the initiated classes list or a byte[] obtained as a resource. We may not be able to associate the byte[] with the exact parent loader which loaded it but we can still associate it with the loader which requested it. I'll raise a JIRA and look at possible implementations.

Thanks very much for reporting this issue and providing the detailed trace info that pins it down. Much appreciated!

regards,

Andrew Dinn

[rajiv.shivane]

Hi Andew,

adinn  wrote:

Yes, I think it might be wise to modify the LoadCache so it will retain either a Class found in the initiated classes list or a byte[] obtained as a resource. We may not be able to associate the byte[] with the exact parent loader which loaded it but we can still associate it with the loader which requested it.

So we tried exactly that and found a few surprising findings!

First, we added a cache for BytecodeChecker in Transformer.getClassChecker. The idea was to cache the BytecodeChecker once we created it and for future calls if we have a BytecodeChecker don't even try looking up the LoadCache, just use cached BytecodeChecker

The code changes are here: Introduced BytecodeChecker cache · noothir/byteman@d3e74d0 · GitHub

This change by itself did not make any difference to the server startup time.

Then, we changed Transformer.getClassChecker to never use LoadCache and use only the BytecodeChecker cache.

This change is here: Remove loadcache optimization, always use ByteCodeChecker cache. · noothir/byteman@4fe2d6b · GitHub

Now here's the surprise! With this change, the server startup time is pretty much same as the startup time without any agent!

It looks like when we have a class loader hierarchy with each classloader having hurdreds-thousands of initiated-classes, it is faster to parse the bytecode than to search the loaded class in a nested for loop (first across class loader hierarchy then across the list of loaded classes within that class loader). This probably also explains why getInitiatedClasses was showing up as the hotspot.

I notice LoadCache has been around since 2012. Was there a test/benchmark that required you to introduce LoadCache?

Thanks,

Rajiv

[adinn]

Hi Rajiv,

Thanks for getting back to me on this issue. I am afraid I took a while to respond as I have been very busy with OpenJDK work.

rajiv.shivane  wrote:

So we tried exactly that and found a few surprising findings!

First, we added a cache for BytecodeChecker in Transformer.getClassChecker. The idea was to cache the BytecodeChecker once we created it and for future calls if we have a BytecodeChecker don't even try looking up the LoadCache, just use cached BytecodeChecker

The code changes are here: Introduced BytecodeChecker cache · noothir/byteman@d3e74d0 · GitHub

This change by itself did not make any difference to the server startup time.

Then, we changed Transformer.getClassChecker to never use LoadCache and use only the BytecodeChecker cache.

This change is here: Remove loadcache optimization, always use ByteCodeChecker cache. · noothir/byteman@4fe2d6b · GitHub

Now here's the surprise! With this change, the server startup time is pretty much same as the startup time without any agent!

It looks like when we have a class loader hierarchy with each classloader having hurdreds-thousands of initiated-classes, it is faster to parse the bytecode than to search the loaded class in a nested for loop (first across class loader hierarchy then across the list of loaded classes within that class loader). This probably also explains why getInitiatedClasses was showing up as the hotspot.

Well, yes, that's a very interesting result. I'll respond to that in a second.

I notice LoadCache has been around since 2012. Was there a test/benchmark that required you to introduce LoadCache?

The test case I used for this was starting up the JBoss AS5 app server back in the days where it took around 20 seconds for a minimal start up and up to 2 minutes with many deployed services -- it was the worst case I could use as regards class loading since that was a large part of what the app server was doing and it involved loading many classes. Installing one non-overrrdiing, non-interface rule (carefully defined so it would never get injected) at start time added no measurable time. A single overriding rule or single non-overriding interface rule added about 5%. One of each added about 10% I didn't investigate where all this time was going as I felt that was not a terrible result.

However, clearly I should l have revisited that. The latest EAP does minimal start in 1-2 seconds and full startup in 10 seconds.Some of that is down to loading less code but most of it is down to better algorithms (including more multi-threaded execution). So, the latest EAP has a much higher ratio of load- to execute-time, probably not dissimilar to your test app.

I guess the benefit you are finding from just using resource loading is twofold, the cost of traversing the loaded classes arrays will be significant for your deployment but so also will be the cost of creating a new copy of the array at successive lookups in each loader. The cache was added because the cost of caching is fairly cheap and it avoids repeat scanning for repeat lookups which do happen some of the time. However, I expect multiple lookups are far from being the common case, whether the lookup happens during super-chain chasing or frame checking.

One of the problems with using the cache to store resource-loaded class bytecode is that this might end up storing quite a lot of new data, turning the speed problem into a space problem. One solution might be to use a bounded-capacity LRU associative cache. If a class is going to be found more than once then it is likely to happen in close temporal proximity (as shown by by your log traces). So, LRU removal of entries is probably a good policy. Another might be just not to cache anything and just take the hit of loading bytecode every time.

I'm also not sure how bad this might be for smaller apps that don't do much loading. I guess from your figures (where you are doing a lot of loading) the trade-off might not matter too much as it any costs will probably be small in absolute terms even if it is a larger %ge relative to the time spent loading. I'll do some experiments and see what looks like the best thing to do. If you can provide any hard numbers on numbers of classes loaded, number of scans made & number of load cache hits in your user's app that would be very useful.

I still have quite a lot of OpenJDK work to complete so it may take some time before I can provide a fix (a week, maybe two?).

regards,

Andrew Dinn

[adinn]

Hi Rajiv,

I have looked into this and you are right that loading a class as a byte[] every time is a better approach than searching loaded class lists. I used Wildfly 10 (which load a lot of classes intensively at startup) to test this and the savings in startup time without the cache when using overriding and/or interface rules varied from a few hundred microseconds to several worst case being when you have an overriding CLASS rule and an overriding INTERFACE rule). Of course, for apps which load only a small number of classes it may be cheaper to traverse the loaded classes list but the cost difference in those cases should also be small (not many byte[] loads will occur). So, I think this is the best option for all cases.

I have raised BYTEMAN-367 for this (and closes BYTEMAN-365 which it invalidates) which involves removing the cache and the loaded class list traversal. It w9ill appear in releases 4.0.3 and 3.0.13. I have just deployed a 4.0.3-SNAPSHOT release to the Sonatype snapshots repo if you would like to try it. I will schedule a release in the next week or two.

Thank you very much for investigating and reporting this issue. and apologies for the small delay in preparing a fix.

regards,

Andrew Dinn

[rajiv.shivane]

Hi Andrew,

The performance numbers I reported were with LoadCache disable *but* introducing a ByteCheckerCache. See: Comparing bytemanproject:50d3719f493958a7486ae54abb86e9d8c767a1c2...noothir:4fe2d6b63e9ff3de6be5127e1d5f1b24c9626304 · b…

I was looking at the following commit in github: remove LoadCache - -fixes BYTEMAN-367 · bytemanproject/byteman@c54e8a9 · GitHub

Looks like LoadCache is gone, but there is no ByteCheckerCache.

We have not tested the configuration with both LoadCache and ByteCheckerCache disabled. It would take some time to work with the customer and validate such a configuration.

Thanks,

Rajiv

[adinn]

Hi Rajiv,

I took the LoadCache out because it is clearly degrading performance in cases where load delays will be noticeable -- so removal is a fairly clear win. I am happy to consider adding an alternative cache for byte[] class definitions loaded during super and interface checking. However, I am wary of doing that without doing some more detailed testing to ensure that the hit rate for some given cache model (bounded, LRU, set-associative) can justify the  resulting  byte[] storage cost. So, before adding a new cache I would prefer to instrument the byte checker code in order to measure byte[] load patterns and sizes and decide what sort of caching model to adopt.

I have raised BYTEMAN-368 to cover this task. I will instrument the latest code to record and print checker load stats (I'll make the code conditional on an environment setting) and experiment using Wildfly as a test case. If you want to use the same instrumentation code to record info from your client's setup I can make it available in a snapshot release.

regards,

Andrew Dinn

[rajiv.shivane]

Thanks Andew, I would like to use the snapshot build with the additional instrumentation.

I was looking at the details of BYTEMAN-368. If I understood correctly, you mention caching byte[]s. If you look at the change we tried (Comparing bytemanproject:50d3719f493958a7486ae54abb86e9d8c767a1c2...noothir:4fe2d6b63e9ff3de6be5127e1d5f1b24c9626304 · b… ) , we were caching BytecodeChecker objects, not byte[]. What we had seen was the BytecodeChecker objects were very light weight ... just the names of super classes/interfaces. Do you think that would work better than caching byte[]s?

[adinn]

Hi Rajiv,

rajiv.shivane  wrote:

Thanks Andew, I would like to use the snapshot build with the additional instrumentation.

Ok, I'll reply here when it is ready.

rajiv.shivane  wrote:

I was looking at the details of BYTEMAN-368. If I understood correctly, you mention caching byte[]s. If you look at the change we tried (Comparing bytemanproject:50d3719f493958a7486ae54abb86e9d8c767a1c2...noothir:4fe2d6b63e9ff3de6be5127e1d5f1b24c9626304 · b… ) , we were caching BytecodeChecker objects, not byte[]. What we had seen was the BytecodeChecker objects were very light weight ... just the names of super classes/interfaces. Do you think that would work better than caching byte[]s?

I don't suppose it is going to make a lot of difference since we are talking about a small object. However, I would guess that caching only the byte[] and dropping then recreating the checker as needed is the better option.

Firstly, that lowers the retained data size, albeit at the expense of reallocating and initiialising a new checker in the cases where entries are reused.  The initialization cost is neither here nor there -- just a couple of field writes. More importantly, most of the GCs are tuned to make transient allocations of small objects almost free and, conversely, this results in more cost for the less frequent case where Java code holds on to an object,  In this case adding a reference from the cache will promote the BytecodeChecker to mature space (the cache itself will persist long enough that it is sure to be promoted). I think you would do better to avoid that promotion because any BytecodeChecker is probably going to get dropped out of cache later. I expect dropping of cached references will be necessary to allow the cache size to be bounded. Also, it is probably a good strategy. References to checked supers or interfaces are likely to occur in a cluster when certain parts of the class base get loaded and then only rarely happen again.

Of course the same promote and then drop will happen with the cached byte[] array itself but that cannot be avoided. Adding extra data to the mature space is still worth avoiding.

regards,

Andrew Dinn

[rajiv.shivane]

adinn  wrote:

Ok, I'll reply here when it is ready.

Thanks!

adinn  wrote:

I don't suppose it is going to make a lot of difference since we are talking about a small object. However, I would guess that caching only the byte[] and dropping then recreating the checker as needed is the better option.

Firstly, that lowers the retained data size, albeit at the expense of reallocating and initiialising a new checker in the cases where entries are reused.  The initialization cost is neither here nor there -- just a couple of field writes. More importantly, most of the GCs are tuned to make transient allocations of small objects almost free and, conversely, this results in more cost for the less frequent case where Java code holds on to an object,  In this case adding a reference from the cache will promote the BytecodeChecker to mature space (the cache itself will persist long enough that it is sure to be promoted). I think you would do better to avoid that promotion because any BytecodeChecker is probably going to get dropped out of cache later. I expect dropping of cached references will be necessary to allow the cache size to be bounded. Also, it is probably a good strategy. References to checked supers or interfaces are likely to occur in a cluster when certain parts of the class base get loaded and then only rarely happen again.

Is the byte[] you are planning on caching the class bytes?

Typically a class file is about 5KB. The retained size of ByteCodeChecker is mainly the ClassStructureAdapter, which in turn is mainly the four fields:

    private boolean isInterface = false;
    private String[] interfaces = null;
    private String superName = null;
    private String outerClass = null;

Compared to caching the class bytes (5KB), caching the ByteCodeChecker (these four fields) should consume much less memory. Also caching ByteCodeChecker means we do not need to parse/visit the bytecode next time.

I might be misunderstanding the byte[] you are referring to.

Thanks,

Rajiv

[adinn]

Hi Rajiv,

rajiv.shivane  wrote:

Is the byte[] you are planning on caching the class bytes?

Typically a class file is about 5KB. The retained size of ByteCodeChecker is mainly the ClassStructureAdapter, which in turn is mainly the four fields:

    private boolean isInterface = false;     private String[] interfaces = null;     private String superName = null;     private String outerClass = null;

Compared to caching the class bytes (5KB), caching the ByteCodeChecker (these four fields) should consume much less memory. Also caching ByteCodeChecker means we do not need to parse/visit the bytecode next time.

I might be misunderstanding the byte[] you are referring to.

Ah, sorry, I was indeed referring to the class file byte[] -- under the mistaken belief that the the Checker would need to retain a reference to it in order to recompute the details of the supers and interfaces. Clearly, ByteCodeChecker instances include all the necessary data and there is little or no danger of incurring any significant storage cost by retaining them in a cache. Apologies for being dense -- too much context-switching.

regards,

Andrew Dinn