Debugging thread dumps and server problems in ColdFusion MX 6.1 and 7.0

This article describes the generation and diagnosis of thread dumps in the ColdFusion MX Server configuration with the built-in JRun server and ColdFusion MX J2EE configuration with the standalone JRun server. It contains specific examples to show which threads are important and which can be ignored.

The diagnosis information in the article can also be useful for ColdFusion MX J2EE versions running on WebLogic, IBM WebSphere and other supported J2EE platforms. For generating thread dumps on these platforms, refer to vendor-specific documentation.

There are several tools available to the developer to help diagnose performance problems or unresponsive systems. Some of the techniques vary slightly from one operating system to another. Developers need to be aware of these diagnostic aids to help themselves and technical support quickly get to the root cause.

It's important to use the correct terminology when describing and diagnosing server problems. For example, crash andhangs are terms often used interchangeably to describe system (application server) state but they are very different and may require slightly different methods to diagnose. Here are some common terms and their definitions.

Crash

The ColdFusion server process stops running/disappears (this could be jrun.exe/jrun or the weblogic/websphere server process). Java itself has crashed and there may be a hotspot log (hs*.log) to help diagnose the problem.

Hung

The ColdFusion server is unresponsive. ColdFusion (the jrun.exe/Windows process) still appears in task manager and doesn't appear to be taking high CPU but is also not serving any new pages. ("ps -ef" command (Unix/Linux))

Spinning

The ColdFusion process is taking high CPU resources (approaching 100%). On Windows 2 CPU systems, this would be 50% CPU usage for jrun.exe.

Thread Dump

A list of all running Java threads in a ColdFusion server. For JRun-based systems, "simultaneous request" threads in thread dumps are prefixed with either jrpp-nn (External Web Server) or web-nn (JRun Web Server). Some others are scheduler-nn, jndi-nn, skimmer-nn.

Stack Trace

An individual thread's execution stack (snapshot) that contains the call stack at the time the thread dump was taken or when an exception was thrown (in the case where the stack is found in the ColdFusion log files, such as exception.log). Some use the terms 'stack trace' and 'thread dump' interchangeably but they are not the same (even though some Sun docs use them interchangeably). This often causes confusion.

Also review ColdFusion logs (application.log, server.log, exception.log, etc.) to help diagnose problems along with using thread dumps.

Upgrade the ColdFusion server to the latest supported patches

Before attempting to debug problems, check the ColdFusion support site for the latest hot fixes and updaters for ColdFusion MX 6.1 or 7.0. It's always best to run the latest version and patches.

Generating a full thread dump

Follow the steps below to capture a full thread dump when the system is in an unresponsive state. Each full thread dump is a snapshot of every thread in the system at that moment in time.

Windows (any configuration): When running as a Windows service (Recommended)

(requires the process "log on" parameters with system-level privileges)

Windows (Server configuration): When running from a DOS window

Windows (J2EE Configuration with JRun):

Unix/Linux (Server configuration)

Unix/Linux (J2EE configuration with JRun)

What do the various "states" of the threads mean?

Threads in a dump typically have the following states:

runnable

Means the thread is running or ready to run. Threads that have stack traces with .cfc or .cfm should be inspected.



Others without .cfc/.cfm in the stack are often in harmless wait states and can be ignored.

waiting for monitor entry

Waiting to enter a synchronized code block. Rare to see this. Synchronize blocks should execute quickly and if the code takes long enough to end up in a thread dump or more than one, it's worth investigating.

waiting on monitor

Generally can be ignored if the top of the stack shows an Object.wait() method

in Object.wait()

Waiting for an object. Sometimes this means idle and can be ignored but if the stack trace for the Object.wait() thread has a running .cfm/.cfc, investigate if this is blocking with another thread.

Thread names and their relevance to reading the thread dump

Most threads listed in the thread dump are related to system activities, not user code and can be ignored while analyzing thethread dump. These include: jndi-nn,skimmer-nn, jms-fifo-nn,Transaction Domain*, RMI*,Finalizer, and Reference Handler.

The jrpp-nn (simultaneous request threads) andweb-nn (JRun Web Server) are the primary ones to look at. scheduler-nn, and Thread-nn threads are the second group that are sometimes relevant if not in Object.wait(). Thread-nn threads can be spawned by things such as database driver code.

Reading the thread dump

Open thread_dump.log, out.txt or[servername]-out.log in a web browser and search for the phrase "Full thread dump:".

For example: Full thread dump Java HotSpot(TM) Server VM (1.4.2_05-b04 mixed mode):

There will be one instance of the phrase for each thread dump generated. To avoid confusion, it's best to work from the bottom up and search for "Full Thread Dump" and take the LAST thread dump into a separate file so text searches don't go across thread dumps - at least initially. Later, to determine whether a thread (jrpp-28) is "progressing", the user will need to search across multiple thread dumps.

If Control+[Pause|Break] or "kill -3" (Unix/Linux) was executed since first examining the thread dump file, refresh the browser and search for the last occurrence of "Full thread dump:". The list of threads is below the "Full thread dump:" line. Each thread has a stack (aka stack trace). Unfortunately, there is no timestamp.

There are generally a large number of threads. The important ones typically are the jrpp-nn threads, especially the ones containing function names likecoldfusion.runtime.xxxxxx ormacromedia.jdbc.xxxxx. If using the JRun Web Server (on port 8300 or 8500), threads are namedweb-nn.

jrpp-nn threads apply to commercial web servers such as Apache, Microsoft IIS and SunOne using the ColdFusion MX connector (aka the JRun connector).

Note: The number of available Worker Threads (jrpp) is dynamic, based on recent activity. There may be more Worker Threads than the number of "Simultaneous Requests" set in the Administrator. Only "Simultaneous Requests" number of these can actively be executing ColdFusion templates. The extra threads reflect both available threads and incoming ColdFusion requests which are queued up for processing and must wait their turn before the template executes.

Thread dumps can be large. If the ColdFusion MX logs show the same error over and over, try to match it up with a thread inside the thread dump file. If it matches, take a snippet of one of the stack traces in the thread dump and save it for technical support. Always send the entire thread dump file for analysis to support.

Typical thread entry for a request

From line 3, notice this thread is executing the templatelongrun.cfm at line 12.

The calls from various JRun functions to the CfmServlet and to the coldfusion.filter functions will always be present when running a template. The classname cflongrun2ecfm320255489 comes from the filename that longrun.cfm was compiled into (if the option to 'Save Class Files' is enabled in the ColdFusion MX Administrator). The .class file for longrun.cfm is \WEB-INF\cfclasses\cflongrun2ecfm320255489.class. This name is constructed by prepending "cf" to the filename with non-alphanumeric characters replaced by their hexadecimal equivalent. For example; the dot (.) is 2e in hexadecimal. Directory separators are replaced with two underscores "__". The trailing number is a Java-supplied hash code.

The lines highlighted in RED are the important ones. They begin at an executing .cfm or .cfc and any lines above (lines 2 and 3 in the example above). The lines below the .cfc and .cfm line - generally - describe the context of the running template. For example, if macromedia.jdbc.sqlserver ormacromedia.jdbc.oracle appears below the .cfm or .cfc, we know there is a database interaction (cfquery,cfstoredproc, etc).

In the example above, the lines in BLUE - or some subset of them depending on the request - usually aren't relevant to figuring out the problem so it's important not to be distracted by them.

Deadlocks

Deadlocks can be caused by one thread holding a resource needed by another thread or group of threads. This is the so-called thread wait pileup and can cause dozens of successive "timeout waiting for an available thread to run" type errors in the logs. A thread dump with a stuck system will often reveal one thread causing the problem. The root cause could be user code, code in the core ColdFusion or JRun engine or some outside influence such as a database problem, network issue, etc.

Thread dump examples

Example 1: 'Simultaneous request' threads waiting for incoming request (can be ignored typically)

Symptom: Steady state. These are often the threads you can ignore while reading a thread dump. (ColdFusion MX 7 examples shown)

or this:

Example 2: JRun Web Server idle thread (can be ignored typically)

Symptom: Steady state

Example 3: ColdFusion MX 6.1 Thread Pooling issue - deadlock causing server hang

Symptom: All threads (requests) hang and eventually timeout. All versions that use JRun4 Updater 5 or above (CF 7.0.1) have this fixed. 6.1 updater has a post 6.1 Updater patch (57510) for this problem. If using 6.1, apply BOTH the 6.1 Updater and the 57510 hot fix patch.

Example 4: Idle waiting to run when a request comes in. (can be ignored typically)

Symptom: Steady state. jrpp-1has finished a request and is waiting for another one from the connector on the same connection.

Example 5: socketRead() - waiting for database response or processing a database response

Symptom: Slow response time. (may or may not be normal - see below)

This thread is executing either a cfquery orcfstoredproc tag at line 13 of productsearch.cfm. Most often, users will be looking at debugging problems that have their root cause in some kind of database action. The macromedia.jdbc.sqlserver.* (or oracle/informix/sequelink, etc) in the stack tells us it's a database action. Given that most applications use cfquery and queries could take a few seconds, it's not unusual to see this signature in a thread dump.

In this case, web-0 is waiting for a response from the database or processing a database response - thesocketRead0() call - so this might be normal or it could be a problem if the SPECIFIC jrpp-nn - or in this case the JRun Web Server "web-0" thread - doesn't progress over time (2-3 thread dumps).

There are also situations where the database driver could cause a hang and show this thread dump signature but GENERALLY, most application thread dumps could have a few of these and be perfectly normal.

When there are database related issues and the server is unresponsive, it's common to see multiple threads showing the same CFQUERY line running (productsearch.cfm:13) and perhaps another, single thread accessing or updating the same table (productupdate.cfm:45). This might indicate a deadlock somewhere in the database. Run the SQL code outside ColdFusion MX to see if it's something other than a ColdFusion MX problem. For example, an index may be corrupt or missing.

Example 6: Purging client variables in the Windows registry causes high memory/system hang

Symptom: CPU spins at 100% - and high memory usage - about every hour after startup (large memory use too).

Here's a common one that some fall into going from development to production. The default for storing client variables is "REGISTRY". Once the number of records in the registry is large, the query to get all records and delete expired client records can take 100% CPU for minutes at a time.

Registry client storage should never be used for production systems but often developers fall into this by accident by not explicitly specifying a data source (and the ColdFusion admin defaulting to "REGISTRY"). Since the registry isn't a real database, ColdFusion has to retrieve the entire registry client tree (high memory usage) and compare the date/time one at a time to decide whether to purge a record. This is a CPU-intensive operation with an hourly purge that may only delete a few records.

Since this is a system task, it's running in a scheduler thread instead of a jrpp thread. Here's a case where a scheduler thread is relevant.

Note: If using a 2 processor system on Windows, task manager would show a processor at 50% utilization which is the equivalent of 100% CPU on a single CPU system.

Example 7: Refreshing of cached query - - causes a slowdown or hang

Symptom: Requests back up and request backlog is high. Server can either seem hung or unresponsive. Memory usage is not high.

A hang long enough to record a cached query refresh in the thread dump may have several associated issues.

• Is the user bringing back a huge query? The user might not think so if using <cfquery MaxRows=>. If the query has a large number of rows, all other pages that hit the cached query will block until the first user hitting the query (after the <cfquery cachedWithin=..> time limit value) gets a resultset from the database (the "Waiting for monitor entry" below).
• <cfquery maxrows=N> bug. ColdFusion MX (until ColdFusion MX 7.0.1 CHF2) didn't pass maxrows to the underlying driver (statement.setMaxRows()) so it's possible that ColdFusion would bring back the entire resultset first, then only show "N" number of rows. This could delay the query or use large amounts of memory and could contribute to the slowdown. ColdFusion 5 did respect MaxRows so some users migrating to 6.1 might see this performance hit.

Without the thread dump, the user might change the<cfquery cachedWithin=..> time limit value of the cached query to make it SOONER which only makes the problem worse.

N jrpp (Simultaneous Request) threads blocked at this point.

+ some other request thread in runnable - the one trying to refresh the cached query.

ColdFusion MX 6.1 workaround for CFQUERY MaxRows issue

Use database-specific row limit hints. Ex: For SQL Server:

Example 8: ColdFusion MX 7.0.1 (Standard only) CFDOCUMENT hang - eventually hangs server.

Symptom: One CFDOCUMENT thread throws an error and all the other CFDOCUMENT threads hang behind it eventually using up all simultaneous requests and hanging. (Fixed in ColdFusion MX 7.0.1 CHF2). This one can't really be diagnosed without source code but seeing 8 simultaneous requests at line 3 of the same template in a thread dump is suspicious (or in this case at CFDOCUMENT calls doing PDF generation). This can help support begin to diagnose the problem.