Tracking down slow running requests
35 views
Skip to first unread message
Dave
Oct 20, 2009, 11:05:50 PM10/20/09
to FusionReactor
Hi All,
I'm having some issues tracking down the root-cause of a handful of
very slow running requests.
It's a 64bit CF8 server & occasional we see many requests essentially
"hang" as strange places, such as:
java.lang.String.toLowerCase(null:???) and
java.lang.Class.getClassLoader0(null:???)[Native Method].
The only way to recover the CF server from this state is to restart
the service. I'm a little lost as to how to troubleshoot these calls
because they seem very low level.
Thanks,
Dave
I'm having some issues tracking down the root-cause of a handful of
very slow running requests.
It's a 64bit CF8 server & occasional we see many requests essentially
"hang" as strange places, such as:
java.lang.String.toLowerCase(null:???) and
java.lang.Class.getClassLoader0(null:???)[Native Method].
The only way to recover the CF server from this state is to restart
the service. I'm a little lost as to how to troubleshoot these calls
because they seem very low level.
Thanks,
Dave
Jeff S.
Oct 21, 2009, 9:49:09 AM10/21/09
to FusionReactor
Do you have your datasources wrapped (so you can view the JDBC tab w/
useful info)? What kind of pages does it hang on- are they making
<cfhttp /> calls, or a bunch of queries (potentially heavy/slow
queries)?
A more complete stack trace may help people answer the question.
Are you using any 3rd party libraries, or doing anything "special" on
the slow pages (using JavaLoader along w/ some 3rd Party Java classes
that do something potentially long running)?
Sorry I couldn't really help more.
useful info)? What kind of pages does it hang on- are they making
<cfhttp /> calls, or a bunch of queries (potentially heavy/slow
queries)?
A more complete stack trace may help people answer the question.
Are you using any 3rd party libraries, or doing anything "special" on
the slow pages (using JavaLoader along w/ some 3rd Party Java classes
that do something potentially long running)?
Sorry I couldn't really help more.
Darren Pywell
Oct 21, 2009, 3:35:17 PM10/21/09
to FusionReactor
Hi Dave,
These are low level methods indeed. Problems down in java.langString
very often point memory issues or CPU starvation. If it's CPU
starvation it must be very extreme (which is also possibly induced by
memory starvation - we've seen java run 1000x slower when the heap is
exhausted due to the excessive garbage collection).
Have you taken a look at the memory and the CPU usage. Take a look in
the resource-*.log files at the time when you see these pauses.
Jeff is right on the money with his suggestion of posting a more
complete stack trace. This may help us to get more insight.
Hope that helps,
Darren
These are low level methods indeed. Problems down in java.langString
very often point memory issues or CPU starvation. If it's CPU
starvation it must be very extreme (which is also possibly induced by
memory starvation - we've seen java run 1000x slower when the heap is
exhausted due to the excessive garbage collection).
Have you taken a look at the memory and the CPU usage. Take a look in
the resource-*.log files at the time when you see these pauses.
Jeff is right on the money with his suggestion of posting a more
complete stack trace. This may help us to get more insight.
Hope that helps,
Darren
John Hawksley (Fusion Team)
Oct 21, 2009, 5:25:49 PM10/21/09
to FusionReactor
Just to add my 2 cents; I've done a lot of profiling work in very
disparate VM environments with different business applications, and in
every case, we see that java.lang.String (and it's underlying type,
arrays of char) are by far and away the largest number of objects on
the heap.
They're not necessarily the /largest/ set of objects on the heap, but
they're the most common.
We find operations on Strings are therefore also very common, so (as
Darren has said) it's not necessarily a fault situation to find lots
of stacks are performing string operations when the slowdown/hang
occurs.
All the best,
-John
disparate VM environments with different business applications, and in
every case, we see that java.lang.String (and it's underlying type,
arrays of char) are by far and away the largest number of objects on
the heap.
They're not necessarily the /largest/ set of objects on the heap, but
they're the most common.
We find operations on Strings are therefore also very common, so (as
Darren has said) it's not necessarily a fault situation to find lots
of stacks are performing string operations when the slowdown/hang
occurs.
All the best,
-John
Jeff S.
Oct 21, 2009, 5:52:58 PM10/21/09
to FusionReactor
I've ran into heap space problems in the past when processing very
large strings. The most recent example I can think of was:
---------------------------------
CODE THAT RAN OUT OF HEAP SPACE:
---------------------------------
<cfsavecontent variable="sGeneratedText">
<cfloop query="qSomeBigQuery">
#qSomeBigQuery.column1# - #qSomeBigQuery.column2# <br />
</cfloop>
</savecontent>
<cffile action="append" file="#myFile#" output="#sGeneratedText#" />
---------------------------------
CODE THAT COMPLETED W/O DYING:
---------------------------------
<cfloop query="qSomeBigQuery">
<cfset sGeneratedText = "#qSomeBigQuery.column1# -
#qSomeBigQuery.column2# <br />" />
<cffile action="append" file="#myFile#" output="#sGeneratedText#" />
</cfloop>
The code that uses a ton of <cffile /> calls would open many more file
handles / outputstreams (or whatever goes on in java behind the scenes
when using cffile), but it would not crash due to the huge string
passed into the output attribute of the cffile call in the first
example...
On Oct 21, 5:25 pm, "John Hawksley (Fusion Team)"
large strings. The most recent example I can think of was:
---------------------------------
CODE THAT RAN OUT OF HEAP SPACE:
---------------------------------
<cfsavecontent variable="sGeneratedText">
<cfloop query="qSomeBigQuery">
#qSomeBigQuery.column1# - #qSomeBigQuery.column2# <br />
</cfloop>
</savecontent>
<cffile action="append" file="#myFile#" output="#sGeneratedText#" />
---------------------------------
CODE THAT COMPLETED W/O DYING:
---------------------------------
<cfloop query="qSomeBigQuery">
<cfset sGeneratedText = "#qSomeBigQuery.column1# -
#qSomeBigQuery.column2# <br />" />
<cffile action="append" file="#myFile#" output="#sGeneratedText#" />
</cfloop>
The code that uses a ton of <cffile /> calls would open many more file
handles / outputstreams (or whatever goes on in java behind the scenes
when using cffile), but it would not crash due to the huge string
passed into the output attribute of the cffile call in the first
example...
On Oct 21, 5:25 pm, "John Hawksley (Fusion Team)"
charlie arehart
Oct 22, 2009, 12:05:03 AM10/22/09
to fusion...@googlegroups.com
Good stuff shared in this thread today. :-)
Jeff, one other thing: you don't mention what edition of CF you run
(Standard or Enterprise). If the latter, are you running (or have you ever
run) the CF Server Monitor? If so, I would wonder if you may have the "start
memory tracking" button enabled. While some have that and things run fine,
others find it kills their server.
Now, if you (or others reading this) might say, "well, I don't have that
interface open. We looked at it and decided it didn't give us what hoped",
that's where the danger lies. It doesn't matter if you have the interface
open. Like FR, that just displays the data that's collected all the time.
Those start buttons (in that Enterprise CF Server Monitor interface), once
set, remain set even when the interface is closed. Many have found that
"stopping" the memory tracker was a solution to unusual problems (memory,
CPU, or otherwise). Just worth a shot, while we await more details.
/charlie
Dave
Oct 25, 2009, 5:10:31 PM10/25/09
to FusionReactor
Hi Darren,
The server is certainly experiencing CPU starvation (99-100%
utilisation), however I can't see anything to point to memory/heap
starvation. According to resource.log, that server had very high CPU
utalisation for the past hour, however used memory was sitting at
around 35-55%, with a delta of around 10% (up/down) for each row in
the resource.log file, which indicates that GC was running.
There were 8 very long running requests at the time, with most of them
originating from the TransferORM softReferenceAdapter.
None of the threads were waiting on external resources such as JDBC/
HTTP, although we do use Javaloader and a handful of Java classes.
The other interesting thing from the stack trace is that a lot of
threads where waiting on locks.
eg:
"Reference Handler" daemon prio=10 in Object.wait()
java.lang.Object.wait(Object.java:???)[Native Method]
- waiting on <0x410101e9> (a java.lang.ref.Reference$Lock)
AND
"jms-fifo-2" prio=5 in Object.wait()
java.lang.Object.wait(Object.java:???)[Native Method]
- waiting on <0x1bf388fd> (a jrun.jms.core.threads.FIFOQueue)
Even FR was waiting on locks:
"FusionReactor Web Server (Server Thread Pool Member Thread-680)"
prio=5 in Object.wait()
java.lang.Object.wait(Object.java:???)[Native Method]
- waiting on <0x108ff831> (a com.intergral.fusionreactor.core.e.c$_c)
java.lang.Object.wait(Object.java:485)
com.intergral.fusionreactor.core.e.c$_c.run(ThreadPoolImpl.java:138)
I'm assuming that <0x108ff831> is the memory address of the method we
are waiting on. Is there any way to associate that with the ThreadID
and therefore see what is at the root of the waiting/locks?
I've included the full stack trace of one of the threads below. I'm
not sure if I should post the entire stack trace as they are very
large.
Thread Stack Trace
Trace Time: 11:39:48.766 21-Oct-2009
Thread ID: 0x3131 (12593)
Thread Name: jrpp-1043
Priority: 5
Hashcode: 906396441
State: RUNNABLE
"jrpp-1043" prio=5 runnable
java.lang.String.toLowerCase(null:???)
java.lang.String.toLowerCase(null:???)
coldfusion.tagext.validation.CFTypeValidatorFactory.getValidator
(CFTypeValidatorFactory.java:71)
coldfusion.runtime.UDFMethod.validateValueType(UDFMethod.java:151)
coldfusion.runtime.UDFMethod._validateArg(UDFMethod.java:785)
coldfusion.runtime.UDFMethod._validateArg(UDFMethod.java:802)
cfcandidates2eCandidate40BED7468572FABBE4FA4D0BE4186925872etransfer525672312$funcACTIONAFTERUPDATETRANSFEREVENT.runFunction
(D:\JO3\jobOffice\config\transfer\definitions
\candidates...@BED7468572FABBE4FA4D0BE418692587.transfer:263)
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:59)
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:2272)
cfSoftReferenceAdapter2ecfc1767853770$funcACTIONAFTERUPDATETRANSFEREVENT.runFunction
(D:\JO3\jobOffice\transfer\com\events\adapter\SoftReferenceAdapter.cfc:
100)
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:59)
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:2272)
cfAfterUpdateObserverCollection2ecfc98942520$funcFIREACTIONMETHOD.runFunction
(D:\JO3\jobOffice\transfer\com\events\collections
\AfterUpdateObserverCollection.cfc:44)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2471)
cfAbstractBaseObservable2ecfc1410406389$funcFIREEVENT.runFunction(D:
\JO3\jobOffice\transfer\com\collections\AbstractBaseObservable.cfc:74)
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:59)
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:2272)
cfEventManager2ecfc820165474$funcFIREEVENT.runFunction(D:\JO3\jobOffice
\transfer\com\events\EventManager.cfc:238)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2471)
cfEventManager2ecfc820165474$funcFIREAFTERUPDATEEVENT.runFunction(D:
\JO3\jobOffice\transfer\com\events\EventManager.cfc:189)
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:59)
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:2272)
cfTransfer2ecfc1432092572$funcUPDATE.runFunction(D:\JO3\jobOffice
\transfer\com\Transfer.cfc:269)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2471)
cfTransfer2ecfc1432092572$funcSAVE.runFunction(D:\JO3\jobOffice
\transfer\com\Transfer.cfc:178)
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:59)
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:2272)
cfEmailTransfer2ecfc878281797$funcSAVEEMAIL.runFunction(D:
\JO3\jobOffice\sys\jo\core\transfer\EmailTransfer.cfc:36)
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:59)
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:2272)
cfEmailFactory2ecfc1508413328$funcSAVEEMAIL.runFunction(D:
\JO3\jobOffice\sys\jo\core\factory\EmailFactory.cfc:130)
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:59)
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:2272)
cfEmailConfigurationManager2ecfc669832351$funcCOPYEMAILATTACHMENTS.runFunction
(D:\JO3\jobOffice\sys\jo\core\m2listener\EmailConfigurationManager.cfc:
493)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:463)
coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:453)
coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:320)
coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2222)
coldfusion.tagext.lang.InvokeTag.doEndTag(InvokeTag.java:362)
cfEventInvoker2ecfc294220709$funcINVOKELISTENER.runFunction(D:
\JO3\jobOffice\MachII\framework\invokers\EventInvoker.cfc:67)
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:59)
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:2272)
cfNotifyCommand2ecfc494342107$funcEXECUTE.runFunction(D:\JO3\jobOffice
\MachII\framework\commands\NotifyCommand.cfc:68)
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:59)
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:2272)
cfEventHandler2ecfc1608753602$funcHANDLEEVENT.runFunction(D:
\JO3\jobOffice\MachII\framework\EventHandler.cfc:62)
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:59)
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:2272)
cfRequestHandler2ecfc1676430457$funcHANDLEEVENT.runFunction(D:
\JO3\jobOffice\MachII\framework\RequestHandler.cfc:330)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2471)
cfRequestHandler2ecfc1676430457$funcHANDLENEXTEVENT.runFunction(D:
\JO3\jobOffice\MachII\framework\RequestHandler.cfc:278)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2471)
cfRequestHandler2ecfc1676430457$funcPROCESSEVENTS.runFunction(D:
\JO3\jobOffice\MachII\framework\RequestHandler.cfc:219)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2471)
cfRequestHandler2ecfc1676430457$funcHANDLEREQUEST.runFunction(D:
\JO3\jobOffice\MachII\framework\RequestHandler.cfc:149)
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:59)
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:2272)
cfmach2dii2ecfm917874472.runPage(D:\JO3\wwwroot\mach-ii.cfm:128)
coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:196)
coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:388)
coldfusion.runtime.CfJspPage._emptyTcfTag(CfJspPage.java:2661)
cfindex2ecfm665012002.runPage(D:\JO3\wwwroot\be\index.cfm:18)
coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:196)
coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:388)
coldfusion.filter.CfincludeFilter.invoke(CfincludeFilter.java:65)
coldfusion.filter.ApplicationFilter.invoke(ApplicationFilter.java:279)
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.b
(FusionReactorFilter.java:386)
com.intergral.fusionreactor.filter.FusionReactorFilter.c
(FusionReactorFilter.java:264)
com.intergral.fusionreactor.filter.FusionReactorFilter.doFilter
(FusionReactorFilter.java:174)
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:
286)
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)
The server is certainly experiencing CPU starvation (99-100%
utilisation), however I can't see anything to point to memory/heap
starvation. According to resource.log, that server had very high CPU
utalisation for the past hour, however used memory was sitting at
around 35-55%, with a delta of around 10% (up/down) for each row in
the resource.log file, which indicates that GC was running.
There were 8 very long running requests at the time, with most of them
originating from the TransferORM softReferenceAdapter.
None of the threads were waiting on external resources such as JDBC/
HTTP, although we do use Javaloader and a handful of Java classes.
The other interesting thing from the stack trace is that a lot of
threads where waiting on locks.
eg:
"Reference Handler" daemon prio=10 in Object.wait()
java.lang.Object.wait(Object.java:???)[Native Method]
- waiting on <0x410101e9> (a java.lang.ref.Reference$Lock)
AND
"jms-fifo-2" prio=5 in Object.wait()
java.lang.Object.wait(Object.java:???)[Native Method]
- waiting on <0x1bf388fd> (a jrun.jms.core.threads.FIFOQueue)
Even FR was waiting on locks:
"FusionReactor Web Server (Server Thread Pool Member Thread-680)"
prio=5 in Object.wait()
java.lang.Object.wait(Object.java:???)[Native Method]
- waiting on <0x108ff831> (a com.intergral.fusionreactor.core.e.c$_c)
java.lang.Object.wait(Object.java:485)
com.intergral.fusionreactor.core.e.c$_c.run(ThreadPoolImpl.java:138)
I'm assuming that <0x108ff831> is the memory address of the method we
are waiting on. Is there any way to associate that with the ThreadID
and therefore see what is at the root of the waiting/locks?
I've included the full stack trace of one of the threads below. I'm
not sure if I should post the entire stack trace as they are very
large.
Thread Stack Trace
Trace Time: 11:39:48.766 21-Oct-2009
Thread ID: 0x3131 (12593)
Thread Name: jrpp-1043
Priority: 5
Hashcode: 906396441
State: RUNNABLE
"jrpp-1043" prio=5 runnable
java.lang.String.toLowerCase(null:???)
java.lang.String.toLowerCase(null:???)
coldfusion.tagext.validation.CFTypeValidatorFactory.getValidator
(CFTypeValidatorFactory.java:71)
coldfusion.runtime.UDFMethod.validateValueType(UDFMethod.java:151)
coldfusion.runtime.UDFMethod._validateArg(UDFMethod.java:785)
coldfusion.runtime.UDFMethod._validateArg(UDFMethod.java:802)
cfcandidates2eCandidate40BED7468572FABBE4FA4D0BE4186925872etransfer525672312$funcACTIONAFTERUPDATETRANSFEREVENT.runFunction
(D:\JO3\jobOffice\config\transfer\definitions
\candidates...@BED7468572FABBE4FA4D0BE418692587.transfer:263)
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:59)
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:2272)
cfSoftReferenceAdapter2ecfc1767853770$funcACTIONAFTERUPDATETRANSFEREVENT.runFunction
(D:\JO3\jobOffice\transfer\com\events\adapter\SoftReferenceAdapter.cfc:
100)
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:59)
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:2272)
cfAfterUpdateObserverCollection2ecfc98942520$funcFIREACTIONMETHOD.runFunction
(D:\JO3\jobOffice\transfer\com\events\collections
\AfterUpdateObserverCollection.cfc:44)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2471)
cfAbstractBaseObservable2ecfc1410406389$funcFIREEVENT.runFunction(D:
\JO3\jobOffice\transfer\com\collections\AbstractBaseObservable.cfc:74)
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:59)
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:2272)
cfEventManager2ecfc820165474$funcFIREEVENT.runFunction(D:\JO3\jobOffice
\transfer\com\events\EventManager.cfc:238)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2471)
cfEventManager2ecfc820165474$funcFIREAFTERUPDATEEVENT.runFunction(D:
\JO3\jobOffice\transfer\com\events\EventManager.cfc:189)
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:59)
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:2272)
cfTransfer2ecfc1432092572$funcUPDATE.runFunction(D:\JO3\jobOffice
\transfer\com\Transfer.cfc:269)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2471)
cfTransfer2ecfc1432092572$funcSAVE.runFunction(D:\JO3\jobOffice
\transfer\com\Transfer.cfc:178)
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:59)
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:2272)
cfEmailTransfer2ecfc878281797$funcSAVEEMAIL.runFunction(D:
\JO3\jobOffice\sys\jo\core\transfer\EmailTransfer.cfc:36)
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:59)
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:2272)
cfEmailFactory2ecfc1508413328$funcSAVEEMAIL.runFunction(D:
\JO3\jobOffice\sys\jo\core\factory\EmailFactory.cfc:130)
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:59)
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:2272)
cfEmailConfigurationManager2ecfc669832351$funcCOPYEMAILATTACHMENTS.runFunction
(D:\JO3\jobOffice\sys\jo\core\m2listener\EmailConfigurationManager.cfc:
493)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:463)
coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:453)
coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:320)
coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2222)
coldfusion.tagext.lang.InvokeTag.doEndTag(InvokeTag.java:362)
cfEventInvoker2ecfc294220709$funcINVOKELISTENER.runFunction(D:
\JO3\jobOffice\MachII\framework\invokers\EventInvoker.cfc:67)
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:59)
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:2272)
cfNotifyCommand2ecfc494342107$funcEXECUTE.runFunction(D:\JO3\jobOffice
\MachII\framework\commands\NotifyCommand.cfc:68)
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:59)
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:2272)
cfEventHandler2ecfc1608753602$funcHANDLEEVENT.runFunction(D:
\JO3\jobOffice\MachII\framework\EventHandler.cfc:62)
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:59)
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:2272)
cfRequestHandler2ecfc1676430457$funcHANDLEEVENT.runFunction(D:
\JO3\jobOffice\MachII\framework\RequestHandler.cfc:330)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2471)
cfRequestHandler2ecfc1676430457$funcHANDLENEXTEVENT.runFunction(D:
\JO3\jobOffice\MachII\framework\RequestHandler.cfc:278)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2471)
cfRequestHandler2ecfc1676430457$funcPROCESSEVENTS.runFunction(D:
\JO3\jobOffice\MachII\framework\RequestHandler.cfc:219)
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:59)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2471)
cfRequestHandler2ecfc1676430457$funcHANDLEREQUEST.runFunction(D:
\JO3\jobOffice\MachII\framework\RequestHandler.cfc:149)
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:59)
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:2272)
cfmach2dii2ecfm917874472.runPage(D:\JO3\wwwroot\mach-ii.cfm:128)
coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:196)
coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:388)
coldfusion.runtime.CfJspPage._emptyTcfTag(CfJspPage.java:2661)
cfindex2ecfm665012002.runPage(D:\JO3\wwwroot\be\index.cfm:18)
coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:196)
coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:388)
coldfusion.filter.CfincludeFilter.invoke(CfincludeFilter.java:65)
coldfusion.filter.ApplicationFilter.invoke(ApplicationFilter.java:279)
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.b
(FusionReactorFilter.java:386)
com.intergral.fusionreactor.filter.FusionReactorFilter.c
(FusionReactorFilter.java:264)
com.intergral.fusionreactor.filter.FusionReactorFilter.doFilter
(FusionReactorFilter.java:174)
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:
286)
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)
Darren Pywell
Oct 28, 2009, 12:36:54 PM10/28/09
to FusionReactor
Hi Dave,
Lot's of things do wait on locks in a JVM so that in itself is not
something that means that things are wrong. Also when the VM is going
very slow it means that sometimes we see things waiting were we
wouldn't expect it.
It's possible for example when you are taking a stack trace that you
will see requests (even FR requests) waiting on a synchronizer. That's
because it takes time to generate a stack trace (in fact probably only
a few milliseconds normally) but if the VM is going very slow this can
take a long time, making the stack track look "odd". It can give the
impression that something is holding everything thing up that is not.
This is why analyzing whole stack traces is often necessary and you
can need extra information like is there CPU starvation just to know
what you're looking at.
This is a very deep stack trace (something like 18 levels of CFML code
deep) with about 220 java stack frames. But CPU starvation could
mislead us here because if the machine is going slow then operations
that actually *do* something just as string manipulation can take
along time. Is the CPU utilization from the JVM or the system?
Cheers,
Darren
> cfcandidates2eCandidate40BED7468572FABBE4FA4D0BE4186925872etransfer525672312$funcACTIONAFTERUPDATETRANSFEREVENT.runFunction
> cfEmailConfigurationManager2ecfc669832351$funcCOPYEMAILATTACHMENTS.runFunction
Lot's of things do wait on locks in a JVM so that in itself is not
something that means that things are wrong. Also when the VM is going
very slow it means that sometimes we see things waiting were we
wouldn't expect it.
It's possible for example when you are taking a stack trace that you
will see requests (even FR requests) waiting on a synchronizer. That's
because it takes time to generate a stack trace (in fact probably only
a few milliseconds normally) but if the VM is going very slow this can
take a long time, making the stack track look "odd". It can give the
impression that something is holding everything thing up that is not.
This is why analyzing whole stack traces is often necessary and you
can need extra information like is there CPU starvation just to know
what you're looking at.
This is a very deep stack trace (something like 18 levels of CFML code
deep) with about 220 java stack frames. But CPU starvation could
mislead us here because if the machine is going slow then operations
that actually *do* something just as string manipulation can take
along time. Is the CPU utilization from the JVM or the system?
Cheers,
Darren
> (D:\JO3\jobOffice\config\transfer\definitions
> \candidates.Candid...@BED7468572FABBE4FA4D0BE418692587.transfer:263)
> 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:59)
> 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:2272)
> cfSoftReferenceAdapter2ecfc1767853770$funcACTIONAFTERUPDATETRANSFEREVENT.runFunction
> 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:59)
> 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:2272)
> (D:\JO3\jobOffice\transfer\com\events\adapter\SoftReferenceAdapter.cfc:
> 100)
> 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:59)
> 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:2272)
> cfAfterUpdateObserverCollection2ecfc98942520$funcFIREACTIONMETHOD.runFunction
> 100)
> 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:59)
> 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:2272)
Dave
Oct 28, 2009, 3:49:28 PM10/28/09
to FusionReactor
Thanks Darren,
What you are saying makes perfect sense.
The CPU utalization was from the JVM. IE, JVM @ 99% CPU, System & 100%
CPU.
The question is; how do I go about locating what it is in the JVM that
is monopolizing the CPU?
This is a dedicated CF app server and recently it's been getting in
this state around once a week.
Regards,
Dave
> ...
>
> read more »
What you are saying makes perfect sense.
The CPU utalization was from the JVM. IE, JVM @ 99% CPU, System & 100%
CPU.
The question is; how do I go about locating what it is in the JVM that
is monopolizing the CPU?
This is a dedicated CF app server and recently it's been getting in
this state around once a week.
Regards,
Dave
>
> read more »
Darren Pywell
Oct 29, 2009, 3:31:24 PM10/29/09
to FusionReactor
Probably the most important thing to do is to look at the *entire*
stack trace when this happens. Take a look at what requests are
running and look at what they are doing within the code. Sometime's
I'm afraid there is no subsitute for experience here as you have to
analyze each thread and take a look what problems / conflicts / issues
etc it could be causing.
You've got to consider this along with other factors such as the
number of threads running, the number of stack frames etc, all of
which can affect the performance of the JVM in certain cases. I'm
sorry there is no simple answer other than investigate the data.
Cheers,
Darren
> ...
>
> read more »- Hide quoted text -
>
> - Show quoted text -
stack trace when this happens. Take a look at what requests are
running and look at what they are doing within the code. Sometime's
I'm afraid there is no subsitute for experience here as you have to
analyze each thread and take a look what problems / conflicts / issues
etc it could be causing.
You've got to consider this along with other factors such as the
number of threads running, the number of stack frames etc, all of
which can affect the performance of the JVM in certain cases. I'm
sorry there is no simple answer other than investigate the data.
Cheers,
Darren
>
> read more »- Hide quoted text -
>
> - Show quoted text -
Reply all
Reply to author
Forward
0 new messages