Here at Ping Identity, we've been living with an error that sometimes every now and then when a user tries to download one of our software files. We haven't been able to resolve it ourselves despite months of debugging, searching the web for similar errors, and looking through stack traces via SeeFusion. We're stumped, and it's time to call in the community for reinforcements. Can any of you experts help us resolve this error?
We're using ColdFusion 8,0,0,176276 Standard on Windows Server 2003, Standard Edition, with Java version 1.6.0_18. We also run PaperThin's content management system, CommonSpot, version 5.0.3.
The error occurs, at times, when CommonSpot code tries to place a named lock while accessing one of its cache files. Here's the salient content of the error message:
Message:
A timeout occurred while attempting to lock CS_Page_Cache_1_8/p5134-c0-l90-t0-dMOZ.read. The error occurred on line 158.
Stack trace:
java.lang.InterruptedException at coldfusion.runtime.RWLock.waitForLock(RWLock.java:146) at coldfusion.runtime.RWLock.requestWriteLock(RWLock.java:124) at coldfusion.runtime.RWLock.requestLock(RWLock.java:46) at coldfusion.runtime.LockManager.requestNamedLock(LockManager.java:73) at coldfusion.tagext.lang.LockTag.doStartTag(LockTag.java:186) at cfcached2dpage2drender2ecfm1332875835.runPage(D:\Inetpub\wwwroot\commonspot\utilities\cached-page-render.cfm:158) at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:192) at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:366) at coldfusion.runtime.CfJspPage._emptyTag(CfJspPage.java:2644) at cfmaster2ecfm532680640._factor9(D:\Inetpub\wwwroot\commonspot\master.cfm:186) at cfmaster2ecfm532680640.runPage(D:\Inetpub\wwwroot\commonspot\master.cfm:1) at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:192) at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:366) at coldfusion.runtime.CfJspPage._emptyTag(CfJspPage.java:2644) at cfdownload2ecfm971068451.runPage(D:\Inetpub\pic2009\support-and-downloads\download.cfm:72) at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:192) at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:366) at coldfusion.filter.CfincludeFilter.invoke(CfincludeFilter.java:65) at coldfusion.filter.ApplicationFilter.invoke(ApplicationFilter.java:279) at coldfusion.filter.RequestMonitorFilter.invoke(RequestMonitorFilter.java:48) at coldfusion.filter.MonitoringFilter.invoke(MonitoringFilter.java:40) at coldfusion.filter.PathFilter.invoke(PathFilter.java:86) at coldfusion.filter.ExceptionFilter.invoke(ExceptionFilter.java:70) at coldfusion.filter.ClientScopePersistenceFilter.invoke(ClientScopePersistenceFilter.java:28) at coldfusion.filter.BrowserFilter.invoke(BrowserFilter.java:38) at coldfusion.filter.NoCacheFilter.invoke(NoCacheFilter.java:46) at coldfusion.filter.GlobalsFilter.invoke(GlobalsFilter.java:38) at coldfusion.filter.DatasourceFilter.invoke(DatasourceFilter.java:22) at coldfusion.CfmServlet.service(CfmServlet.java:175) at coldfusion.bootstrap.BootstrapServlet.service(BootstrapServlet.java:89) at jrun.servlet.FilterChain.doFilter(FilterChain.java:86) at coldfusion.monitor.event.MonitoringServletFilter.doFilter(MonitoringServletFilter.java:42) at coldfusion.bootstrap.BootstrapFilter.doFilter(BootstrapFilter.java:46) at jrun.servlet.FilterChain.doFilter(FilterChain.java:94) at com.seefusion.Filter.doFilter(Filter.java:49) at com.seefusion.SeeFusion.doFilter(SeeFusion.java:1500) at jrun.servlet.FilterChain.doFilter(FilterChain.java:94) at jrun.servlet.FilterChain.service(FilterChain.java:101) at jrun.servlet.ServletInvoker.invoke(ServletInvoker.java:106) at jrun.servlet.JRunInvokerChain.invokeNext(JRunInvokerChain.java:42) at jrun.servlet.JRunRequestDispatcher.invoke(JRunRequestDispatcher.java:284) at jrun.servlet.ServletEngineService.dispatch(ServletEngineService.java:543) at jrun.servlet.jrpp.JRunProxyService.invokeRunnable(JRunProxyService.java:203) at jrunx.scheduler.ThreadPool$DownstreamMetrics.invokeRunnable(ThreadPool.java:320) at jrunx.scheduler.ThreadPool$ThreadThrottle.invokeRunnable(ThreadPool.java:428) at jrunx.scheduler.ThreadPool$UpstreamMetrics.invokeRunnable(ThreadPool.java:266) at jrunx.scheduler.WorkerThread.run(WorkerThread.java:66)
What I already know:
Though a lack of memory space is the most likely culprit, I know that our server has plenty of memory, and, so far as SeeFusion tells me, we have plenty of memory left in the JVM. And yes, I've asked Paperthin about this issue, and they've said they have no idea and it must be something in our server configuration. But it always occurs when their code is trying to place a named lock, that's for sure.
So if you have any thoughts, we'd love to hear them-- contact me at tmollerus @t pingidentity.com. We're also willing to pay an expert consultant who can resolve the problem. Let me know if you have any thoughts!
Comments (4)
November 19, 2010
12:01AM | #
Hi,
I'm no ColdFusion expert, but it seems to me that indeed, the problem is related with your server "configuration" (I mean behavior). It's not about memory, but the ability to lock a file for exclusive read/write operations. I can deduct from this that the operating system (your Windows 2003 Server) sometimes doesn't respond to the request of exclusive operation on that file.
In conclusion, my advice to you is to look deeply into services that "guard" file activity on your server - eventually temporary remove them to see if the bug replicates again.
Good luck!
November 19, 2010
8:33AM | #
I don't think this is a file lock, this is from a cflock with a name attribute correct.
CF does not really lock variables it locks code, which access variables. So some other request seems to have an exclusive write lock on the same line.
Does this happen more under load?
cfcached2dpage2drender2ecfm1332875835.runPage(D:\Inetpub\wwwroot\commonspot\utilities\cached-page-render.cfm:158
What is happening on 158? cflock - right. Is it exclusive or read level.
A simple solution is to make the name more granular to what is being accessed. IF you are locking all cache access with the same name you are creating an unneeded bottleneck. Make sure the name correlates to the variables being accessed. Make the lock name dynamic perhaps and maybe set it to a string that represents the variable being accessed.
Another note is that later versions of CF take care of 99% of shared scope locking for you. You MAY not even need locking around cached content.
March 25, 2011
3:50PM | #
A little late and probably not of much help, but I've been doing some load tests today and noticed a similar issue cropping up with an exclusive lock.
Basically in my load tests I'm absolutely hammering my server on a very simple page to test locking.
What I've noticed is that under extreme load in CF8, that occasionally sometimes threads seem to end getting processed with a lower priority. So even though new threads are coming in and completing in milliseconds, occasional a thread will end up waiting forever to get it's own exclusive lock on the object.
I think what is actually happening is that instead of their being a FIFO queue for locks, the code keeps checking to see if the lock has been released, so occasionally a particular thread just happens to keep checking when another thread always has control of the lock.
In my mind I'm picturing Chevy Chase in European Vacation when he gets stuck driving in circles... "Look kids! Big Ben! Parliament!"
March 25, 2011
4:58PM | #
It's interesting to note that I have *not* seen this problem when testing load under CF9.