Re: FusionReactor Group: every request taking too long

[James Holmes]

Have you taken stack traces while the pages run?

mxAjax / CFAjax docs and other useful articles:
http://www.bifrost.com.au/blog/

2009/2/20 Snake <snake...@snakepit.net>:
> Greetings Chaps,
>
>
>
> On one of my servers I have every single request is taking ages to run, even
> cfadmin pages, no matter how simple the page is.
>
> I cannot see any culprits that could be the cause. Any tips ?

[Snake]

Yes I have, but I can't say anything leapt out at me, but then I probably
don't know what I am looking for :-)

Russ

[James Holmes]

If you do a stack trace on a running thread and keep refreshing it,
you can see if the thread is stuck or waiting on something; if the
trace looks the same for a few seconds, that's your bottleneck.

mxAjax / CFAjax docs and other useful articles:
http://www.bifrost.com.au/blog/



2009/2/20 Snake <snake...@snakepit.net>:
>

> Yes I have, but I can't say anything leapt out at me, but then I probably
> don't know what I am looking for :-)
>
> Russ
>
> -----Original Message-----
> From: fusion...@googlegroups.com [mailto:fusion...@googlegroups.com]
> On Behalf Of James Holmes
> Sent: 20 February 2009 12:49
> To: fusion...@googlegroups.com
> Subject: FusionReactor Group: Re: every request taking too long
>
>

[Darren Pywell [FusionDebug Team]]

James this is a great suggestion and I often do the same looking for
problems... simply look where it pauses or spends time.

It's often a resource starvation issue when Java starts going slower.
Make sure that the memory isn't being collected for long periods.

Darren

On Feb 20, 4:00 pm, James Holmes <james.hol...@gmail.com> wrote:
> If you do a stack trace on a running thread and keep refreshing it,
> you can see if the thread is stuck or waiting on something; if the
> trace looks the same for a few seconds, that's your bottleneck.
>
> mxAjax / CFAjax docs and other useful articles:http://www.bifrost.com.au/blog/
>

> 2009/2/20 Snake <snake.li...@snakepit.net>:

>
>
>
> > Yes I have, but I can't say anything leapt out at me, but then I probably
> > don't know what I am looking for :-)
>
> > Russ
>
> > -----Original Message-----
> > From: fusion...@googlegroups.com [mailto:fusion...@googlegroups.com]
> > On Behalf Of James Holmes
> > Sent: 20 February 2009 12:49
> > To: fusion...@googlegroups.com
> > Subject: FusionReactor Group: Re: every request taking too long
>
> > Have you taken stack traces while the pages run?
>
> > mxAjax / CFAjax docs and other useful articles:
> >http://www.bifrost.com.au/blog/
>

> > 2009/2/20 Snake <snake.li...@snakepit.net>:

[Snake]

Ok, here is a stack traces that is not changing when refreshed, can you tell
me anything useful from this? All requests seem to be stuck here.

java.lang.Object.wait(Object.java:???)[Native Method]
- waiting on <0xdec63d> (a
edu.emory.mathcs.backport.java.util.concurrent.Semaphore$FairSync$Node)
java.lang.Object.wait(Object.java:443)
edu.emory.mathcs.backport.java.util.concurrent.TimeUnit.timedWait(TimeUnit.j
ava:301)
edu.emory.mathcs.backport.java.util.concurrent.helpers.WaitQueue$WaitNode.do
TimedWait(WaitQueue.java:79)
edu.emory.mathcs.backport.java.util.concurrent.Semaphore$FairSync.attempt(Se
maphore.java:346)
edu.emory.mathcs.backport.java.util.concurrent.Semaphore.tryAcquire(Semaphor
e.java:571)
coldfusion.CfmServlet.lock(CfmServlet.java:255)
coldfusion.CfmServlet.service(CfmServlet.java:174)
coldfusion.bootstrap.BootstrapServlet.service(BootstrapServlet.java:89)
jrun.servlet.FilterChain.doFilter(FilterChain.java:86)
com.intergral.fusionreactor.filter.FusionReactorFilter.B(null:???)
com.intergral.fusionreactor.filter.FusionReactorFilter.A(null:???)
com.intergral.fusionreactor.filter.FusionReactorFilter.doFilter(null:???)
jrun.servlet.FilterChain.doFilter(FilterChain.java:94)
coldfusion.monitor.event.MonitoringServletFilter.doFilter(MonitoringServletF
ilter.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:26
6)
jrunx.scheduler.WorkerThread.run(WorkerThread.java:66)

--------------------

[charlie arehart]

Russ (and others interested in troubleshooting based on stack traces), while
usually one would see a reference in the stack trace to a .cfm (or .cfc)
file, with the line number of the code in question, you don't have that
here, which does make it more challenging.

We see that it's in a lock wait, but it's not due to a CFLOCK, I don't
think, as we'd see that listed as a line of CFML code in the stack trace.
Maybe one of the FR guys or someone else here may recognize something.
Perhaps it's significant that the wait is on the:
edu.emory.mathcs.backport.java.util.concurrent.Semaphore

I will note that a google search for this finds someone else with what seems
the exact same issue:

http://www.jonhartmann.com/index.cfm/2009/2/5/ColdFusion-Instance-Issue

While his first thread dump is different, his second is nearly identical.
Sadly, despite many comments (and his own updates in the blog entry), he had
found no solution yet.

I wonder if it may have to do with thread pooling, but I can't quite tell
where.

I see that he, like you, shows reference to
"coldfusion.monitor.event.MonitoringServletFilter.doFilter". Are you running
the CF8 monitor as well as FR? I don't think it's significant. In fact,
please do confirm if perhaps you are NOT running it, because perhaps you're
on CF Standard. Indeed, please remind us what version of CF this is. Might
help.

/charlie

-----Original Message-----
From: fusion...@googlegroups.com [mailto:fusion...@googlegroups.com]
On Behalf Of Snake
Sent: Wednesday, March 04, 2009 12:36 PM
To: fusion...@googlegroups.com
Subject: FusionReactor Group: Re: every request taking too long

[Snake]

Charlie,

It is CF8 and the server monitoring is not being used.


Russ

[charlie arehart]

Russ, I had also asked if it was Standard (or Enterprise). Could be
significant to the matter of thread locking.

[Snake]

It is enterprise

[Snake]

I have also noticed that the CFAdmin seems to be one of the causes of this
problem, specifically whenever I am setting up security sandboxes, then it
seems all the requests start to take a very long time to run, including the
cfadmin pages

[Snake]

Does FusionReactor have a way to breakdown memory usage and find out what
requests and what variable scopes are consuming how much memory, like the
CF8 server monitor does?

Russ

[Darren Pywell [FusionDebug Team]]

Hi Russ,

The issue here is typically related to the Request Management Features
of CF8 Enterprise. It's possible in the Enterprise Edition to set
Request limits and Queue timeouts on the Request Tuning Screen of the
CF Administrator.

I think that problem is that the engine is looking to find a "slot" to
process the request in but there are not slots available. It then
looks to the queue to remove any requests that have exceeded the Queue
Timeout limit and if it doesn't find any then it puts the request into
a kind of "wait" state until either it times out, or a slot becomes
available. So if the requests are hanging here then you may need to
either lower the "Timeout requests waiting in queue after [nnnn]
seconds", or increase the number of requests that can be run (both of
which can also cause problems!)

All this may be pointing to an issue in the application that requests
are taking too long or it may be that the server is starved of
resource. Take a stack trace with FusionReactor's All Threads and see
what the other threads are hanging on.

Hope that helps,
Darren

[charlie arehart]

I think Darren's note here may have been a reply to Snake's earlier
questions about requests being in a thread state that was locked.

As to the question below, Russ (who goes by the nickname Snake, for those
following along), no. FR does not "have a way to breakdown memory usage and

find out what requests and what variable scopes are consuming how much
memory, like the

CF8 server monitor does".

I'll offer the answer as I understand it, and FR folks can chime in with
follow up.

There are a couple of things to understand about this matter. First, the CF8
monitor's ability to do that (which some should be told is available only in
CF8 Enterprise) is based on the fact that CF8 enterprise has enabled hooks
into itself to report that info. FusionReactor itself doesn't weave itself
into CF the same way, so doesn't have access to that info. More on that in a
moment.

Second, it's worth noting that the CF 8 monitor feature to provide that
memory info ("start memory tracking") is in fact an expensive operation, and
one that has even brought some servers down when enabled by users. (Some of
you know that I've written as extensively on the CF8 monitor as I have on
FusionReactor, so I'm speaking from experience. Not just trying to pick on
the CF8 Monitor. Each tool has its strengths.) So that feature is optional
and can be enabled/disabled.

Third, the fact that the CF 8 monitor shows that info is simply because CF8
Enterprise exposes that info in an Admin API. Anyone can get it. You don't
need to use the CF8 monitor (though most typically do.) My point is that
FusionReactor *could* in fact get access to the info, and show it. But FR's
designed as a tool that works the same on any J2EE server. Since the API is
CF-specific, it's not a feature in FR to present that info (for now, though
perhaps that may change.)

But you may well be asking this from the perspective that you do NOT run CF8
Enterprise, and therefore wish you could have access to the info. Again,
the problem is that FR does not weave itself into the internals of CF the
way the "memory tracking" feature can. That took Adobe engineers to enable
that. It would be difficult (if not impossible) for Intergral to enable that
without Adobe's involvement, and naturally Adobe regard this as a benefit
for upgrading to Enterprise.

So we on the outside (no running CF 8 Enterprise) are indeed left out in the
cold. The closest you can come, in my opinion, is that it may be very
valuable for people to at least know how many CF sessions they have. In my
experience, a great deal of memory can be lost to an unepectedly high number
of sessions. I blogged about a simple tool that can report that for you
(http://www.carehart.org/blog/client/index.cfm/2009/1/22/tracking_count_of_s
essions_per_application). I highly recommend folks get and run that code
(free, and simple to use). And it reports the same whether you're using CF
or J2EE sessions (an option many may not notice in the CF Admin session mgt
settings).

Actually, something we might ask FR to add would be a means to track the
number of J2EE sessions. They could do that and still have it work for all
J2EE app servers. The only negative is that those using CF without enabling
J2EE sessions could be confused. I'd argue the info should only be shown if
in fact J2EE sessions are enabled, and not left showing 0 (the way the Jrun
Metrics do) if J2EE sessions are not enabled.

Hope that's helpful, Russ.

/charlie




-----Original Message-----
From: fusion...@googlegroups.com [mailto:fusion...@googlegroups.com]

On Behalf Of Darren Pywell [FusionDebug Team]
Sent: Monday, March 09, 2009 11:38 AM
To: FusionReactor

[Snake]

Thanks Charlie.
I can confirm your comment that memory tracking is an expensive operation,
while I was using this feature it was in fact compounding the problem and
infinitely consuming memory. So while I thought I was still seeing the
original problem, I was in fact seeing a new problem created by the server
monitor itself consuming all the memory, but you cannot see that it is
causing it from the server monitor itself. It also turns out that enabling
the memory trackers causes problems for fusebox and other frameworks, making
them run very slowly and invariably timeout. This is presumably due to all
the components being loaded and tracked my the memory tracker.

I have also since discovered the Fusebox and other frameworks report false
memory usage in the cf server monitor as well, each request and application
scope will show as using several TB of memory, thus creating false
positives.


Russ

[James Holmes]

A CF Standard install could make use of the Java SizeOf() class:

http://sizeof.sourceforge.net/

http://sourceforge.net/projects/sizeof

Some custom code would be necessary to create a monitor based on this,
but it does work.

mxAjax / CFAjax docs and other useful articles:
http://www.bifrost.com.au/blog/

2009/3/10 charlie arehart <charli...@carehart.org>:

[Snake]

Ok here is another example. All the hung requests seem to look like this
when it happens, and it regularly seems to be caused by me using the
cfadmin.

"jrpp-631" prio=5 in Object.wait()

java.lang.Object.wait(Object.java:???)[Native Method]
- waiting on <0x1ad4835> (a

-----Original Message-----
From: fusion...@googlegroups.com [mailto:fusion...@googlegroups.com]

On Behalf Of Darren Pywell [FusionDebug Team]
Sent: 09 March 2009 15:38
To: FusionReactor

[Snake]

And another

coldfusion.server.j2ee.pool.ObjectPool.checkIn(ObjectPool.java:263)
- waiting on <0xd25883> (a coldfusion.server.j2ee.sql.pool.JDBCPool held by
thread 487, jrpp-14)
coldfusion.server.j2ee.sql.pool.JDBCPool.returnConnection(JDBCPool.java:817)
coldfusion.server.j2ee.sql.pool.JDBCPool.connectionClosed(JDBCPool.java:299)
coldfusion.server.j2ee.sql.JRunConnection.sendCloseEvent(JRunConnection.java
:307)
coldfusion.server.j2ee.sql.JRunConnectionHandle.close(JRunConnectionHandle.j
ava:56)
coldfusion.sql.DataSrcImpl.clear(DataSrcImpl.java:180)
coldfusion.sql.DataSrcImpl.clearSqlProxy(DataSrcImpl.java:25)
coldfusion.filter.DatasourceFilter.invoke(DatasourceFilter.java:26)
coldfusion.CfmServlet.service(CfmServlet.java:175)