Steven Erat's Blog
 
 
Viewing By Entry
 
 

TalkingTree  Help! My ColdFusion MX Server is Slow!!!!

 

Determining Root Cause for Slow Application

I've often seen ColdFusion users complain that their server/application is running very slowly, not handling requests as fast as normal, or just plain "hung". Many would suggest examining log files to determine the status and recent history of the ColdFusion server in order to find clues that might reveal what the server was actually doing. While this troubleshooting step can be useful, it can only get you so far.
What's often overlooked is the ability to generate a "Full Thread Dump" from ColdFusion MX as a means to precisely determine exactly what the server was doing at exactly that moment, something that you wouldn't be able to otherwise garner from the logs alone.

Macromedia has a ColdFusionMX TechNote describing how to produce a Full Thread Dump, but there has been very little written so far describing what to do with it then. To that end, here is a reply I recently sent to the CFTalk mailing list:


You should take several full thread dumps in succession with a small interval in between them. Then to examine the thread dump, look for JRun Proxy Service threads beginning with jrpp-xxx where xxx is a number and jrpp-xxx is the thread id. Specifically, to find the running threads that are handling .cfm requests, search for the string (excluding the quotes) ".cfm:". This will lead you to a template and its path with a line number at the end after the colon. You'll also see other mentions of .cfm: further down in the stack of a particular thread, but it the top most one that was executing at that instant. Truncated example:

"jrpp-96" prio=5 tid=0x477e5008 nid=0xc50 runnable [698f000..698fdbc]
at coldfusion.tagext.NativeCfx.processRequest(Native Method)
at coldfusion.tagext.lang.CFSearchTag.doStartTag(CFSearchTag.java:207)
at coldfusion.runtime.CfJspPage._emptyTag(CfJspPage.java:1871)
at cf_cachelists2ecfm612782408.runPage(/opt/apache/htdocs/_cachelists.cfm:30)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:357)
{snip}



Here, jrpp-96 is the JRun thread which is handling the template /opt/apache/htdocs/_cachelists.cfm. That template is currently executing a tag that is either on line 30 or ends on line 30. In this case the tag is CFSEARCH. If you find that this thread stack exists in subsequent full thread dumps that were taken at short intervals, where the same thread id, same template, and same operation is occurring for both thread stacks, then that should be sufficient proof that the cfm request has been executing for the duration of the interval between the two thread dump instances.

Typically the number of jrpp thread stacks having cfm templates in the stack in a single full thread dump will not exceed the number of Simultaneous Requests set in the CFAdmin, also known as the activeHandler limit for JRun people. The full thread dump is precise enough to do full accounting of all running threads, showing exactly what they are doing at that instant. <br/>

Its important to emphasize that observing the actions of threads in one thread dump loses the context of time. That's what ColdFusion was doing at that instant, but one thread dump by itself says nothing about how long a thread runs. Rather, its best to look for the same template running with the same thread id across two or more thread dumps taken in rapid succession. It requires some effort to extract and analyze the threads in various thread dumps, but looking at one thread dump alone is not useful for determining what's slowing down the application response times.

Once that is done and you have a list of templates involved and operations that were being executed, then you can focus your effort to debug just that area.

Additional thread stack examples:

1) Reading data back from an ODBC Socket connection

"jrpp-45" prio=5 tid=0x47373e78 nid=0x2f4 runnable [2bae000..2bafdbc]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at java.io.DataInputStream.readFully(DataInputStream.java:266)
at macromedia.sequelink.net.TrEndPoint.recv(Unknown Source)
at macromedia.sequelink.net.Session.channelRecv(Unknown Source)
at macromedia.sequelink.net.Session.recv(Unknown Source)
at macromedia.sequelink.net.Session.recvIIOPHeader(Unknown Source)
at macromedia.sequelink.net.Session.recv(Unknown Source)
at macromedia.sequelink.net.Session.recv(Unknown Source)
at macromedia.sequelink.net.Session.reply(Unknown Source)
at macromedia.sequelink.ssp.Chain.send(Unknown Source)
at macromedia.sequelink.ctxt.stmt.StatementContext.execDirect(Unknown Source)
at macromedia.jdbc.sequelink.SequeLinkImplStatement.execute(Unknown Source)
at macromedia.jdbc.slbase.BaseStatement.commonExecute(Unknown Source)
at macromedia.jdbc.slbase.BaseStatement.executeInternal(Unknown Source)
at macromedia.jdbc.slbase.BaseStatement.execute(Unknown Source)

- locked {0x158ce0c0}(a macromedia.jdbc.sequelink.SequeLinkConnection)
at coldfusion.server.j2ee.sql.JRunStatement.execute(JRunStatement.java:212)
at coldfusion.sql.Executive.executeQuery(Executive.java:974)
at coldfusion.sql.Executive.executeQuery(Executive.java:886)
at coldfusion.sql.SqlImpl.execute(SqlImpl.java:229)
at coldfusion.tagext.sql.QueryTag.doEndTag(QueryTag.java:447)
at cf_additionalresources2ecfm1082472973.runPage(/opt/apache/htdocs/additionalresources.cfm:41)

{snip}

2) CFHTTP trying to connect to the remote resource

"jrpp-12" prio=5 tid=0x3c342580 nid=0x72c in Object.wait() [3e7ee000..3e7efdbc]
at java.lang.Object.wait(Native Method)
- waiting on {0x10933140} (a HTTPClient.HTTPConnection$EstablishConnection)
at java.lang.Thread.join(Thread.java:1009)
- locked {0x10933140} (a HTTPClient.HTTPConnection$EstablishConnection)
at HTTPClient.HTTPConnection.getSocket(HTTPConnection.java:3184)
at HTTPClient.HTTPConnection.sendRequest(HTTPConnection.java:2931)
- locked {0x109312b8}(a HTTPClient.HTTPConnection)
at HTTPClient.HTTPConnection.handleRequest(HTTPConnection.java:2767)
at HTTPClient.HTTPConnection.setupRequest(HTTPConnection.java:2559)
at HTTPClient.HTTPConnection.Get(HTTPConnection.java:916)
at coldfusion.tagext.net.HttpTag.createConnection(HttpTag.java:1526)
at coldfusion.tagext.net.HttpTag.connHelper(HttpTag.java:703)
at coldfusion.tagext.net.HttpTag.doEndTag(HttpTag.java:990)
at cfdsp_htm2ecfm1703620815.runPage(/opt/apache/htdocs/dsp_htm.cfm:45)

{snip}

Reference
Debugging stack traces in ColdFusion MX

 


Comments

A caveat on taking Thread Dumps... About 3 thread dumps taken in succession from the time of hanging should be sufficient to determine what the server was doing and what threads were running. Wait about 15 seconds between each, and this way they can be compared to see which threads are completed across the dumps and which threads are stuck or hanging.

Do not generate 20 or 30 thread dumps each time. And worse yet, I recommend not sending Macromedia Support a huge log having tons of thread dumps in it. An over abundance of thread dumps can slow down the troubleshooting process. :)




 

 

Calendar

 
Sun Mon Tue Wed Thu Fri Sat
        1 2 3
4 5 6 7 8 9 10
11 12 13 14 15 16 17
18 19 20 21 22 23 24
25 26 27 28 29 30 31

Search This Site

 
This is an exact search only

About This Site

 
I live west of Boston and used to work at Adobe with ColdFusion and Flex, specializing in Unix & Linux. I recently graduated from CDIA in Pro Digital Photography. Curious about my banner image?

More about me

Recent Entries

 
Christmas Eve Service makes F..
How To Filter by File Type in..
Perspective on ColdFusion's B..
Power Mac G5: The lights are ..
My Application to CDIABU in R..

Recent Comments

 
Posted By Andy Allan:
Fantastic work Steve.

Posted By charlie arehart:
Oh wow, awesome to hear that the relative quiet was an imposed one, and that the gag order has been lifted. Now I'm really excited to hear what may co ...

Posted By Steven Erat:
Thanks for your encouragement Charlie. I have to say that even though I'm trying to be positive and use this time to improve my web skills, most of t ...

recently played

 
Snap Judgments
by WNYC, New York Public Radio
on On The Media
On The Media, WNYC, New York Public Radio

now playing, a plug-in for itunes

Categories

 
RSS Adobe (31)
RSS Bicycling (9)
RSS Blogging (37)
RSS Books (13)
RSS Breeze (12)
RSS CFMX Podcasts (10)
RSS ColdFusion (420)
RSS Computer Technology (50)
RSS Events (25)
RSS Flash (3)
RSS Flex (18)
RSS Gadgets (10)
RSS HiTech Industry (16)
RSS Java (25)
RSS Learning (57)
RSS Linux (70)
RSS Mac OS X (22)
RSS Macromedia (28)
RSS Meetup (34)
RSS New England (62)
RSS Odds & Ends (25)
RSS Outdoors (32)
RSS Personal (29)
RSS Photography (109)
RSS Photoshop (29)
RSS Podcasts (18)
RSS Rants (19)
RSS Restaurants (8)
RSS Science (34)
RSS Spain (16)
RSS Travel (42)
RSS Video (20)
RSS Webcam (3)
RSS Writing (10)

Blogs I Read

 
Scrum Sucks
Ben Forta
Ray Camden
Kinky Solutions
Gary Gilbert
Red Hat Blogs
O'Reilly Digital Media
O'Reilly Radar
John Nack
The Strobist
Scott Kelby
Matt Kloskowski
Joe McNally
Digital Photography School
Engadget
Science Blog

RSS

 


Add to Google
Add to My Yahoo!

Aggregated By

 


Consumed By Feed-Squirrel.com
Aggregated by ColdFusionBlogger.org

Credits and Stuff

 
BlogCFC - Free ColdFusion Powered Blog Software
CJM Group - ColdFusion Website Hosting


 
 
blog | photos | flickr | referers | webcam | stats | about | contact
 
Copyright © 2009 Steven Erat. All rights reserved.
This is a personal weblog. The opinions expressed here represent my own and not those of my employer