Debugging stuck threads

[Dave]

Hi All,

I'm just getting started with FusionRactor and I'm hoping someone can
point me in the right direction.

I'm running a relatively busy CF8 site, and a couple of times a day we
see all requests to a single the ColdFusion server "stop", following
by all running requests getting a timeout message.

Monitoring Running Requests during a "lockup" I can see lots of
threads are blocked, "waiting for monitor"

I located the blocking thread, and here is the top of its stack:

ava.lang.Thread.sleep(Thread.java:???)[Native Method]
coldfusion.util.UUIDUtils.uniqueTOD(UUIDUtils.java:148)
coldfusion.util.UUIDUtils.createUUID(UUIDUtils.java:101)
coldfusion.runtime.CFPage.CreateUUID(CFPage.java:3742)

Which relates to my code: "variables.properties.requestKey =
createUUID();"

My question is where to from here? IE, what documentation can I read
to learn how to resolve this issue.



Stack traces:
--One blocked thread
Thread Stack TraceTrace Time: 13:32:55.114 24-Jan-2008Request ID:
34480Script Name: http://203.89.225.202/realestate/artwork/index.cfmStarted:
13:32:29.63 24-Jan-2008Exec Time: 26051msMemory Used:
(72%)996,224KBMemory Free: 370,815KBThread ID: 0x19db (6619)Thread
Name: jrpp-85Priority: 5Hashcode: 14931412State:
BLOCKED"jrpp-85" prio=5 waiting for monitor
entrycoldfusion.util.UUIDUtils.uniqueTOD(UUIDUtils.java:144)- waiting
on <0x1853c96> (a java.lang.Class held by thread 2981, jrpp-43

--Another blocked thread
Thread Stack TraceTrace Time: 13:34:01.913 24-Jan-2008Request ID:
34482Script Name: http://203.89.225.202/realestate/media/index.cfmStarted:
13:32:40.650 24-Jan-2008Exec Time: 81263msMemory Used:
(73%)1,000,164KBMemory Free: 366,875KBThread ID: 0x19dd
(6621)Thread Name: jrpp-87Priority: 5Hashcode:
22726318State: BLOCKED"jrpp-87" prio=5 waiting for monitor
entrycoldfusion.util.UUIDUtils.uniqueTOD(UUIDUtils.java:144)- waiting
on <0x1853c96> (a java.lang.Class held by thread 2981,
jrpp-43)coldfusion.util.UUIDUtils.createUUID(UUIDUtils.java:
101)coldfusion.runtime.CFPage.CreateUUID(CFPage.java:3742)



-- Blocking thread

Thread Stack Trace
Trace Time: 13:35:30.299 24-Jan-2008
Thread ID: 0xba5 (2981)
Thread Name: jrpp-43
Priority: 5
Hashcode: 17382075
State: TIMED_WAITING

"jrpp-43" prio=5 sleeping

java.lang.Thread.sleep(Thread.java:???)[Native Method]
coldfusion.util.UUIDUtils.uniqueTOD(UUIDUtils.java:148)
coldfusion.util.UUIDUtils.createUUID(UUIDUtils.java:101)
coldfusion.runtime.CFPage.CreateUUID(CFPage.java:3742)
cfSysLog2ecfc968650921$funcINIT.runFunction(C:\AdVenda\sys\log
\SysLog.cfc:5)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:418)
coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)
coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:
360)
coldfusion.runtime.UDFMethod
$ArgumentCollectionFilter.invoke(UDFMethod.java:324)
coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:
56)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:448)
coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:308)
coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2260)
cfMessage2ecfc1587426427$funcINIT.runFunction(C:\AdVenda\sys\log
\Message.cfc:8)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:418)
coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:
360)
coldfusion.runtime.UDFMethod
$ArgumentCollectionFilter.invoke(UDFMethod.java:324)
coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:
56)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:448)
coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:308)
coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2260)
cfAssetManagerEngine2ecfc1791769890$funcCHECKMESSAGEQUEUE.runFunction(C:
\AdVenda\sys\qm\cfcEngines\AssetManagerEngine.cfc:33)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:418)
coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)
coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:
360)
coldfusion.runtime.UDFMethod
$ArgumentCollectionFilter.invoke(UDFMethod.java:324)
coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:
56)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:448)
coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:308)
coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2260)
cfAssetManagerEngine2ecfm800849836.runPage(C:\Inetpub\wwwroot\qmEngines
\AssetManagerEngine.cfm:19)
coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:192)
coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:366)
coldfusion.filter.CfincludeFilter.invoke(CfincludeFilter.java:65)
coldfusion.filter.ApplicationFilter.invoke(ApplicationFilter.java:279)
coldfusion.filter.RequestMonitorFilter.invoke(RequestMonitorFilter.java:
48)
coldfusion.filter.MonitoringFilter.invoke(MonitoringFilter.java:40)
coldfusion.filter.PathFilter.invoke(PathFilter.java:86)
coldfusion.filter.ExceptionFilter.invoke(ExceptionFilter.java:70)
coldfusion.filter.ClientScopePersistenceFilter.invoke(ClientScopePersistenceFilter.java:
28)
coldfusion.filter.BrowserFilter.invoke(BrowserFilter.java:38)
coldfusion.filter.NoCacheFilter.invoke(NoCacheFilter.java:46)
coldfusion.filter.GlobalsFilter.invoke(GlobalsFilter.java:38)
coldfusion.filter.DatasourceFilter.invoke(DatasourceFilter.java:22)
coldfusion.CfmServlet.service(CfmServlet.java:175)
coldfusion.bootstrap.BootstrapServlet.service(BootstrapServlet.java:
89)
jrun.servlet.FilterChain.doFilter(FilterChain.java:86)
com.intergral.fusionreactor.filter.FusionReactorFilter.G(null:???)
com.intergral.fusionreactor.filter.FusionReactorFilter.B(null:???)
com.intergral.fusionreactor.filter.FusionReactorFilter.doFilter(null:???)
jrun.servlet.FilterChain.doFilter(FilterChain.java:94)
coldfusion.monitor.event.MonitoringServletFilter.doFilter(MonitoringServletFilter.java:
42)
coldfusion.bootstrap.BootstrapFilter.doFilter(BootstrapFilter.java:46)
jrun.servlet.FilterChain.doFilter(FilterChain.java:94)
jrun.servlet.FilterChain.service(FilterChain.java:101)
jrun.servlet.ServletInvoker.invoke(ServletInvoker.java:106)
jrun.servlet.JRunInvokerChain.invokeNext(JRunInvokerChain.java:42)
jrun.servlet.JRunRequestDispatcher.invoke(JRunRequestDispatcher.java:
284)
jrun.servlet.ServletEngineService.dispatch(ServletEngineService.java:
543)
jrun.servlet.jrpp.JRunProxyService.invokeRunnable(JRunProxyService.java:
203)
jrunx.scheduler.ThreadPool
$DownstreamMetrics.invokeRunnable(ThreadPool.java:320)
jrunx.scheduler.ThreadPool
$ThreadThrottle.invokeRunnable(ThreadPool.java:428)
jrunx.scheduler.ThreadPool
$UpstreamMetrics.invokeRunnable(ThreadPool.java:266)
jrunx.scheduler.WorkerThread.run(WorkerThread.java:66)


Thanks,
Dave

[John Hawksley (Fusion Team)]

Hi Dave,

Thanks for getting in touch with us. Firstly, a quick explanation
about what you're seeing here. The CF code to generate a UUID has
basically gone to sleep (for a millisecond) in order to guarantee that
the UUID it generates (which has a time component) is unique.

Unfortunately there are some knock-on effects to this. A bug in the
JDK actually causes the System Clock to accelerate for every call to
createUUID:

KB ref: http://kb.adobe.com/selfservice/viewContent.do?externalId=tn_19007&sliceId=2
JVM Bug: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4500388

N.b. The original JVM bug is listed as fixed, but the fix does not
work. The failure is documented in subsequent bug 6435126, and not
listed as yet having been fixed. Adobe list the worst-case scenario
of the clock gaining several seconds per minute.

The blocking threads are caused because the ColdFusion Java
implementation of "uniqueTOD" has been synchronized, i.e. only one CF
thread can ever run this method at the same time. If anything happens
to cause this method to "spin", everything else will sit and wait
forever. Problems with the system clock changing (perhaps it is being
reset externally by an network time service) might cause this. Has
the clock been changed?

I would, on the whole, recommend getting off of the CF implementation
of createUUID and onto a third-party one. Adobe also list this as an
option in the KB article ("Using Code").

Sorry we couldn't be more helpful!
-John