Hello all,

I saw a slow thread on one of my servers this evening and when I viewed the
stack trace it showed it was blocked and waiting for FusionReactor to make a
monitor entry. I have included the stack below and was curious what the
groups thoughts are on this issue.

Is this common? Avoidable?

Thanks for your time and help.

Aaron Greenlee
http://aarongreenlee.com/

Thread Stack Trace
Trace Time:   19:12:18.360 26-Feb-2011
Request ID:   454175
Script Name:  redacted
Started:      19:11:27.911 26-Feb-2011
Exec Time:    50449ms
Memory Used:  (86%)1,694,550KB
Memory Free:  262,313KB
Thread ID:    0x8b8 (2232)
Thread Name:  jrpp-1691
Priority:     5
Hashcode:     2084474851
State:        BLOCKED

"jrpp-1691" prio=5 waiting for monitor entry

com.intergral.fusionreactor.core.u.m(FusionReactor.java:399)
- waiting on <0x2e126d8b> (a java.util.LinkedHashMap held by thread 80,
FusionReactor Web Server (Server Thread Pool Member Thread-24))
com.intergral.fusionreactor.filter.FusionReactorFilter.b(FusionReactorFilte r.java:448)
com.intergral.fusionreactor.filter.FusionReactorFilter.c(FusionReactorFilte r.java:254)
com.intergral.fusionreactor.filter.FusionReactorFilter.doFilter(FusionReact orFilter.java:164)
jrun.servlet.FilterChain.doFilter(FilterChain.java:94)
coldfusion.monitor.event.MonitoringServletFilter.doFilter(MonitoringServlet Filter.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$ThreadThrottle.invokeRunnable(ThreadPool.java:42 8)
jrunx.scheduler.WorkerThread.run(WorkerThread.java:66)

Hi Aaron;

At first glance, this is FR waiting to 'finish' a request - i.e. the
request has finished and has actually been flushed to the client, and
FR is waiting to do its housekeeping.  The other named thread, thread
80, holds the monitor for an internal tracking structure.  Without
getting a trace for this other thread, it's difficult to say what's
going on.  It could be anything that's operating on the list of
requests: Request Details (briefly), Running Requests, Request History
etc.

Waiting for monitors is exceedingly common in Java as they are used
extensively - not only by FusionReactor - to regulate entry into
critical sections of code.  We take great pains to ensure the time
spent inside these sections is a short as possible, but contention
does occur occasionally.

Do you have a complete trace for this point in time?  If so, whatever
thread 80's doing  ("Server Thread Pool Member Thread-24", part of the
FR internal web server) is holding the lock.  Like I said, this might
be updating display pages.  Was the server very loaded?  Did many
people have Request History or Running Requests open?

Best regards,
-John

On Feb 27, 2:17 am, Aaron Greenlee <aarongreen...@gmail.com> wrote:

Thanks for your response, John.

I was the only person monitoring Fusion Reactor and this server was only
serving 3-4 requests a second when I caught this long running request.

I've been using Fusion Reactor for about a year in my development
environment but we only recently purchased it for our production servers.
So, I tend to spend a lot of time just poking around trying to learn more
about FR and the way our site is actually behaving. I have not observed a
repeat of this issue and will assume it was isolated. 99.9% of our requests
are under 300ms so it should be easy to see if this happens again.

Do you have any tips on capturing the stack trace for other threads when an
issue like this occurs? I have my CP warnings set to save the stack trace
once it sees a request hit 10 seconds but I'm not sure how I would provide
you with the trace for thread 80.

Respectfully,

Aaron Greenlee

Aaron, assuming you don't catch it in one of your CP alerts (which would
include the thread dump in the body), you can also obtain one by going to
Resources>List All Threads, then click the button "stack trace all".

/charlie

From: fusionreactor@googlegroups.com [mailto:fusionreactor@googlegroups.com]
On Behalf Of Aaron Greenlee
Sent: Monday, February 28, 2011 3:43 PM
To: fusionreactor@googlegroups.com
Subject: [fusionreactor] Re: FusionReactor - Waiting for Monitor Entry

Thanks for your response, John.

I was the only person monitoring Fusion Reactor and this server was only
serving 3-4 requests a second when I caught this long running request.

I've been using Fusion Reactor for about a year in my development
environment but we only recently purchased it for our production servers.
So, I tend to spend a lot of time just poking around trying to learn more
about FR and the way our site is actually behaving. I have not observed a
repeat of this issue and will assume it was isolated. 99.9% of our requests
are under 300ms so it should be easy to see if this happens again.

Do you have any tips on capturing the stack trace for other threads when an
issue like this occurs? I have my CP warnings set to save the stack trace
once it sees a request hit 10 seconds but I'm not sure how I would provide
you with the trace for thread 80.

Respectfully,

Aaron Greenlee

--
You received this message because you are subscribed to the Google Groups
"FusionReactor" group.
To post to this group, send email to fusionreactor@googlegroups.com.
To unsubscribe from this group, send email to
fusionreactor+unsubscribe@googlegroups.com.
For more options, visit this group at
http://groups.google.com/group/fusionreactor?hl=en.

Hi Aaron, Charlie,

Yes that's what I'd suggest, thanks Charlie.  It's not impossible to see contention like this; after all this is what the monitor/lock functionality is for.  We would only really start to worry when a 2-party (or worse) deadlock occurs (where one thread holds lock A, and another holds lock B, and both are waiting for the other lock).

If you can get us a trace it would be useful, but I would say that (fingers crossed) this is just an isolated incident :-)

Best regards,
-John

On 28/02/2011 23:16, charlie arehart wrote:

Aaron, assuming you don’t catch it in one of your CP alerts (which would include the thread dump in the body), you can also obtain one by going to Resources>List All Threads, then click the button “stack trace all”.

 

/charlie

 

From: fusionreactor@googlegroups.com [mailto:fusionreactor@googlegroups.com] On Behalf Of Aaron Greenlee
Sent: Monday, February 28, 2011 3:43 PM
To: fusionreactor@googlegroups.com
Subject: [fusionreactor] Re: FusionReactor - Waiting for Monitor Entry

 

Thanks for your response, John.

 

I was the only person monitoring Fusion Reactor and this server was only serving 3-4 requests a second when I caught this long running request.

 

I've been using Fusion Reactor for about a year in my development environment but we only recently purchased it for our production servers. So, I tend to spend a lot of time just poking around trying to learn more about FR and the way our site is actually behaving. I have not observed a repeat of this issue and will assume it was isolated. 99.9% of our requests are under 300ms so it should be easy to see if this happens again.

 

Do you have any tips on capturing the stack trace for other threads when an issue like this occurs? I have my CP warnings set to save the stack trace once it sees a request hit 10 seconds but I'm not sure how I would provide you with the trace for thread 80.

 

Respectfully,

 

Aaron Greenlee

--
You received this message because you are subscribed to the Google Groups "FusionReactor" group.
To post to this group, send email to fusionreactor@googlegroups.com.
To unsubscribe from this group, send email to fusionreactor+unsubscribe@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/fusionreactor?hl=en.

--
You received this message because you are subscribed to the Google Groups "FusionReactor" group.
To post to this group, send email to fusionreactor@googlegroups.com.
To unsubscribe from this group, send email to fusionreactor+unsubscribe@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/fusionreactor?hl=en.

-- 
John Hawksley
Senior Engineer

Voice: +49 7031 221 502 | Fax: +49 7031 221 524
www.intergral.com

Intergral GmbH - Schickardstr 32 - D-71034 Boeblingen - Germany
Geschaeftsfuehrer: David Tattersall, Darren Pywell
Sitz der Gesellschaft: Boeblingen

Here is a recent thread dump as a follow-up to this issue. This server was
just updated to FR 4.0.5. Is there anything I can adjust in Fusion Reactor
to help avoid this blocking? Thanks!

All Running Request Stack Traces

Thread Stack Trace
Trace Time:   10:31:11.181 05-Feb-2012
Request ID:   1918
Script Name:
 http://tv.adobe.com/index.cfm/watch/adc-presents/create-an-rss-reader...
Started:      10:30:25.161 05-Feb-2012
Exec Time:    46020ms
Memory Used:  (67%)1,394,898KB
Memory Free:  665,901KB
Thread ID:    0xaf (175)
Thread Name:  jrpp-35
Priority:     5
Hashcode:     2083017854
State:        BLOCKED

"jrpp-35" prio=5 waiting for monitor entry

com.intergral.fusionreactor.core.v.m(FusionReactor.java:486)
- waiting on <0x3fa91c56> (a java.util.LinkedHashMap held by thread 92,
FusionReactor Web Server (Server Thread Pool Member Thread-31))
com.intergral.fusionreactor.filter.FusionReactorFilter.c(FusionReactorFilte r.java:500)
com.intergral.fusionreactor.filter.FusionReactorFilter.d(FusionReactorFilte r.java:262)
com.intergral.fusionreactor.filter.FusionReactorFilter.doFilter(FusionReact orFilter.java:171)
jrun.servlet.FilterChain.doFilter(FilterChain.java:94)
coldfusion.monitor.event.MonitoringServletFilter.doFilter(MonitoringServlet Filter.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$ThreadThrottle.invokeRunnable(ThreadPool.java:42 8)
jrunx.scheduler.WorkerThread.run(WorkerThread.java:66)

Thread Stack Trace
Trace Time:   10:31:11.181 05-Feb-2012
Request ID:   1915
Script Name:
 http://tv.adobe.com/index.cfm/watch/digital-video/introducing-adobe-p...
Started:      10:30:23.226 05-Feb-2012
Exec Time:    47955ms
Memory Used:  (78%)1,610,562KB
Memory Free:  450,237KB
Thread ID:    0xb1 (177)
Thread Name:  jrpp-37
Priority:     5
Hashcode:     1541841016
State:        RUNNABLE

"jrpp-37" prio=5 runnable

org.apache.oro.text.regex.Perl5Matcher.__interpret(null:???)
org.apache.oro.text.regex.Perl5Matcher.contains(null:???)
org.apache.oro.text.regex.Util.substitute(null:???)
org.apache.oro.text.regex.Util.substitute(null:???)
coldfusion.runtime.StringFunc.REReplace(StringFunc.java:724)
coldfusion.runtime.CFPage.REReplace(CFPage.java:2749)
cfApplication2ecfc1868353865$funcONREQUESTEND._factor1(C:\inetpub\adobetv4\ atv4\Application.cfc:195)
cfApplication2ecfc1868353865$funcONREQUESTEND.runFunction(C:\inetpub\adobet v4\atv4\Application.cfc:183)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:472)
coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:405)
coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java :368)
coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:55)
coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:321)
coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:220)
coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:491)
coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:337)
coldfusion.runtime.AppEventInvoker.invoke(AppEventInvoker.java:88)
coldfusion.runtime.AppEventInvoker.onRequestEnd(AppEventInvoker.java:323)
coldfusion.filter.ApplicationFilter.invoke(ApplicationFilter.java:377)
coldfusion.filter.RequestMonitorFilter.invoke(RequestMonitorFilter.java:48)
coldfusion.filter.MonitoringFilter.invoke(MonitoringFilter.java:40)
coldfusion.filter.PathFilter.invoke(PathFilter.java:94)
coldfusion.filter.ExceptionFilter.invoke(ExceptionFilter.java:70)
coldfusion.filter.ClientScopePersistenceFilter.invoke(ClientScopePersistenc eFilter.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.filter.CachingFilter.invoke(CachingFilter.java:62)
coldfusion.CfmServlet.service(CfmServlet.java:200)
coldfusion.bootstrap.BootstrapServlet.service(BootstrapServlet.java:89)
jrun.servlet.FilterChain.doFilter(FilterChain.java:86)
com.intergral.fusionreactor.filter.FusionReactorFilter.c(FusionReactorFilte r.java:428)
com.intergral.fusionreactor.filter.FusionReactorFilter.d(FusionReactorFilte r.java:262)
com.intergral.fusionreactor.filter.FusionReactorFilter.doFilter(FusionReact orFilter.java:171)
jrun.servlet.FilterChain.doFilter(FilterChain.java:94)
coldfusion.monitor.event.MonitoringServletFilter.doFilter(MonitoringServlet Filter.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$ThreadThrottle.invokeRunnable(ThreadPool.java:42 8)
jrunx.scheduler.WorkerThread.run(WorkerThread.java:66)

Thread Stack Trace
Trace Time:   10:31:11.243 05-Feb-2012
Request ID:   2021
Script Name:
 http://tv.adobe.com/index.cfm/show/learn-production-premium-cs5
Started:      10:30:53.818 05-Feb-2012
Exec Time:    17425ms
Memory Used:  (98%)2,023,171KB
Memory Free:  37,628KB
Thread ID:    0x9b (155)
Thread Name:  jrpp-15
Priority:     5
Hashcode:     759605283
State:        BLOCKED

"jrpp-15" prio=5 waiting for monitor entry

com.intergral.fusionreactor.core.v.m(FusionReactor.java:486)
- waiting on <0x3fa91c56> (a java.util.LinkedHashMap held by thread 92,
FusionReactor Web Server (Server Thread Pool Member Thread-31))
com.intergral.fusionreactor.filter.FusionReactorFilter.c(FusionReactorFilte r.java:500)
com.intergral.fusionreactor.filter.FusionReactorFilter.d(FusionReactorFilte r.java:262)
com.intergral.fusionreactor.filter.FusionReactorFilter.doFilter(FusionReact orFilter.java:171)
jrun.servlet.FilterChain.doFilter(FilterChain.java:94)
coldfusion.monitor.event.MonitoringServletFilter.doFilter(MonitoringServlet Filter.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$ThreadThrottle.invokeRunnable(ThreadPool.java:42 8)
jrunx.scheduler.WorkerThread.run(WorkerThread.java:66)

Thread Stack Trace
Trace Time:   10:31:11.259 05-Feb-2012
Request ID:   2027
Script Name:
 http://tv.adobe.com/index.cfm/jp/watch/cs-55-web-premium-feature-tour...
Started:      10:30:56.111 05-Feb-2012
Exec Time:    15148ms
Memory Used:  (81%)1,672,653KB
Memory Free:  388,146KB
Thread ID:    0xb7 (183)
Thread Name:  jrpp-40
Priority:     5
Hashcode:     2121053254
State:        RUNNABLE

"jrpp-40" prio=5 runnable

java.util.zip.Deflater.deflateBytes(Deflater.java:???)[Native Method]
java.util.zip.Deflater.deflate(Deflater.java:290)
java.util.zip.DeflaterOutputStream.deflate(DeflaterOutputStream.java:159)
java.util.zip.DeflaterOutputStream.write(DeflaterOutputStream.java:118)
java.util.zip.GZIPOutputStream.write(GZIPOutputStream.java:72)
com.intergral.fusionreactor.filter.c.c.write(GzipResponseStream.java:328)
coldfusion.runtime.CachedBufferedOutputStream.flushBuffer(CachedBufferedOut putStream.java:86)
coldfusion.runtime.CachedBufferedOutputStream.flush(CachedBufferedOutputStr eam.java:129)
sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:278)
sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122)
java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212)
java.io.PrintWriter.flush(PrintWriter.java:276)
coldfusion.runtime.NeoJspWriter.flush(NeoJspWriter.java:316)
coldfusion.runtime.NeoPageContext.flushOutput(NeoPageContext.java:1981)
coldfusion.filter.BrowserFilter.invoke(BrowserFilter.java:42)
coldfusion.filter.NoCacheFilter.invoke(NoCacheFilter.java:46)
coldfusion.filter.GlobalsFilter.invoke(GlobalsFilter.java:38)
coldfusion.filter.DatasourceFilter.invoke(DatasourceFilter.java:22)
coldfusion.filter.CachingFilter.invoke(CachingFilter.java:62)
coldfusion.CfmServlet.service(CfmServlet.java:200)
coldfusion.bootstrap.BootstrapServlet.service(BootstrapServlet.java:89)
jrun.servlet.FilterChain.doFilter(FilterChain.java:86)
com.intergral.fusionreactor.filter.FusionReactorFilter.c(FusionReactorFilte r.java:428)
com.intergral.fusionreactor.filter.FusionReactorFilter.d(FusionReactorFilte r.java:262)
com.intergral.fusionreactor.filter.FusionReactorFilter.doFilter(FusionReact orFilter.java:171)
jrun.servlet.FilterChain.doFilter(FilterChain.java:94)
coldfusion.monitor.event.MonitoringServletFilter.doFilter(MonitoringServlet Filter.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) ...

read more »

Hi Aaron,

I've just had a look through the trace and the key to this is figuring
out what the FR internal web server is doing with 0x3fa91c56, which is
the map of currently-running requests.  We synchronize this map because
it's used a lot concurrently, and naturally we try to make the
synchronized blocks as small as possible.  Unfortunately the trace you
posted is for running requests, rather than the complete system, so the
thread which locked 0x3fa91c56 isn't shown.

If/when this recurs, could you do a full trace by doing FusionReactor ->
Resources -> List All Threads -> Stack Trace All, then post the result
or send us a mail at supp...@fusion-reactor.com, and we'll get right on it!

Many thanks,
-John

On 5/2/12 17:41 , Aaron Greenlee wrote:

...

read more »

Thank you for the reply. I'll try capture a full stack trace.

Aaron