Blog

21
December 2013

Gavin Pickin

FusionReactor - A little help from my friends and my Blog is up to Full Speed

CFML Server, FusionReactor, Techie Gotchas

If you have been reading my blog over the last few weeks, you might have noticed a few things change this week. I have been running this blog on ContentBox, for a few reasons, one to check it out, and two because I was having trouble deciding, and I knew more about ContentBox via ColdBox Developer Week videos than the other CFML options out there. So far, I have quite liked using it, although I haven't themed it myself, or added any GAVIN styled modules to it, but there has been one BIG issue for me, SPEED. I wasn't sure why there was a speed issue, but I was determined to find out, before just giving ContentBox a "speed" black label. This week, I looked into it deeper, and if you didn't notice, the site is flying now, much like it should have been, so if you thought my site was slow, please don't attribute it to ContentBox... there was something else at fault... read more, and you'll find out what, and how I found it.

A little background. I have been involved with a server migration, we got some snazzy new hardware, which might not be the latest and greatest, but compared to what we were running things on, these are awesome servers. Having 32gb of ram, with SSD drives for the CF box and the DB box, sites fly like I didn't think was possible, and everytime I go back to get a site off the old servers, I am quickly reminded of what we had to deal with. This blog runs on a box with ColdFusion 9 and Railo 4.1, its not fully loaded yet, so performance should be slick. All of our other sites running on this machine, ColdFusion, and Railo seem to be extremely quick, the only slow one, this blog. At this point, I was concerned it might be related to ContentBox, or a piece of it, maybe running on Railo, or MySql... but I was trying to give it the benefit of the doubt, because, I wanted it to be successful. So, time to dive deeper, and see where the problem lies.

The first thing I usually do is look into slow queries running on our MySql Server. I was running MariaDB for a while, but had to roll it back to MySql, but I'll save the rest of that story for another day. Nothing on MySql was close to being slow, which is strange, so I decided to check Railo logs and see what was going on. The requests all seemed equally slow, nothing especially obvious.

This is when I realized it was time to try out FusionReactor. I had seen a couple of presentations at CF Objective, and talked to the FusionReactor guys, and it looked like an amazing product, its been on our list of products to get setup, on the new servers, no point installing it on servers we were migrating off of. I downloaded the trial, and ran into a couple of issues, which I discussed here, but once I got my act together, I installed FusionReactor, setup the monitor for ColdFusion and Railo, and now, its down to business.

I let it run for a little while, so I could compare my blog with the other Railo sites, and get a gauge. I was correct in my assumption, the blog was consistently running much slower than all the other sites. I checked for slow requests, and almost all of the slow requests, were coming from this blog. I guess slow jdbc queries, and none of them were from my blog, so my assumption about the database queries not being an issue were right too. I clicked on the "Relations" tab in the slow requests, and scrolled down all the related calls. On a given request, there were several queries, all 1 ms and 0ms, obviously not the issue, and then I notice, all of the Hibernate calls are very slow, some taking 1-3 seconds, and some over 5 seconds.

I found the source, Hibernate was running like a dog... but why? I do not use Hibernate much yet, most of our sites are legacy, and we're not in the ORM world yet, so this makes sense why this is the only site running slow, its the only site using Hibernate. Since Hibernate is out of my area of expertise, I decided to hit up a couple of friends on Twitter, and quick as a fiddle, Brad Wood was there to help out. He admits he is not a Hibernate expert either, but he would he happy to have a look, and see where the issue is. He hadn't heard of any ContentBox sites with this issue, but most he knew of were running MSSQL, so I gave him a login to FusionReactor, and he jumped in.

After confirming my findings, he jumped into the stacktrace for the Hibernate request. This is a very cool feature, being able to see that from inside FusionReactor, it really helps you dig into the request more... and from that, he noticed a couple of things out of place.

java.lang.Throwable.getStackTraceElement(Throwable.java:???)[Native Method] java.lang.Throwable.getOurStackTrace(Throwable.java:826) - locked <0x17e57191> (a java.lang.Exception) java.lang.Throwable.getStackTrace(Throwable.java:815) railo.commons.io.SystemUtil._getCurrentContext(SystemUtil.java:837) railo.commons.io.SystemUtil.getCurrentContext(SystemUtil.java:830) railo.runtime.debug.DebuggerImpl.addImplicitAccess(DebuggerImpl.java:675) railo.runtime.type.scope.UndefinedImpl.debugCascadedAccess(UndefinedImpl.java:218) railo.runtime.type.scope.UndefinedImpl.debugCascadedAccess(UndefinedImpl.java:214) railo.runtime.type.scope.UndefinedImpl.getCollection(UndefinedImpl.java:317) system.aop.matcher_cfc$cf._1(/home/www/www.gpickin.com/coldbox/system/aop/Matcher.cfc:111) system.aop.matcher_cfc$cf.udfCall(/home/www/www.gpickin.com/coldbox/system/aop/Matcher.cfc:???) railo.runtime.type.UDFImpl.implementation(UDFImpl.java:94) railo.runtime.type.UDFImpl._call(UDFImpl.java:307) railo.runtime.type.UDFImpl.call(UDFImpl.java:211) railo.runtime.type.scope.UndefinedImpl.call(UndefinedImpl.java:700) railo.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:712) railo.runtime.PageContextImpl.getFunction(PageContextImpl.java:1503) system.aop.matcher_cfc$cf._1(/home/www/www.gpickin.com/coldbox/system/aop/Matcher.cfc:75) system.aop.matcher_cfc$cf.udfCall(/home/www/www.gpickin.com/coldbox/system/aop/Matcher.cfc:???) railo.runtime.type.UDFImpl.implementation(UDFImpl.java:94) railo.runtime.type.UDFImpl._call(UDFImpl.java:307) railo.runtime.type.UDFImpl.call(UDFImpl.java:211) railo.runtime.ComponentImpl._call(ComponentImpl.java:581) railo.runtime.ComponentImpl._call(ComponentImpl.java:499) railo.runtime.ComponentImpl.call(ComponentImpl.java:1715) railo.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:712) railo.runtime.PageContextImpl.getFunction(PageContextImpl.java:1503)

It seemed to get stuck on a couple of lines, which looking at the ContentBox code was a simple if statement.

if( len(instance.annotation) AND structKeyExists(arguments.metadata, instance.annotation)){

Looking at the stack trace, he wondered what all of the UDFImpl calls were. Being I am using Railo, he jumped into the source code, its really handy in these types of situations when you have the source code available... and in a minute or two (he has a local clone of the source) he had a lot more information. 

All over that Java file, was a bunch of these calls, and they were the slow point

if(debug) debugCascadedAccess(pc,scopes[i].getTypeAsString(),key);

Now I think to myself, oh damn it, did someone leave Debugging mode on? Its a production server, it shouldn't be on anyways right... but it was, and it was left on. I've had a pretty good week for doing stupid things... and this is just another one on the list. 

debug=pc.getConfig().debug() && ((ConfigImpl)pc.getConfig()).hasDebugOptions(ConfigImpl.DEBUG_IMPLICIT_ACCESS);

This bit of code was really slow, and it mentioned one of Railo's cool debugging features (when not used in production LOL)... Implicit Access... which allows you to identify which variables are being called without their scopes. The only downside is, its really really slow to do so. 

I turned off Implicit Access, and all Debugging, and within seconds, the site was lightning fast, like it should be.

So lessons learned?

FusionReactor, is an amazing product, its hard to not see the value in the product, in the few hours I was playing with it, I am sold. I know Railo is releasing a similar tool, specific for Railo, which will get you deeper into their server, but its hard to compete with such a solid, enterprise tool like FusionReactor. I will probably love it more when I learn more of what it can do.

Implicit Access Debugging is awesome, just NEVER use it on Production.
Debugging in General should not be used in Production. 
Next time something is running slow, I'm going to make sure Debugging is turned OFF.

Brad Wood is a good guy, and was really helpful, and I owe him a few dinners at least, at cfObjective, or In The Box Pre-Conference

ContentBox is not slow, all the slow issues related to my blog had nothing to do with ContentBox, but all about me and my server being in Debug mode. That was the only negative so far with my blog, I'm really happy with ContentBox, now I really have to theme it, and develop a few modules. Maybe those will be blog posts you'll see on here soon.
Same can be said of Hibernate, It looks pretty guilty for a while, until we dug into the source

Having the Source good available for the server you are working on, is "Really Helpful". Railo is a great product, and having the source code is just another plus in their column.

Another lesson, you should come back and read more of my blog posts, because I'm worthy of being laughed at... and I'll make a lot of mistakes, so there might be a lot of good things to learn from me :)

Thanks for reading,

Gavin

by Brad Wood
12/22/2013 11:22:11 AM

Looking forward to more ContentBox blog entries now that everything's running smoothly.

Blog Search