Mantis - Resin
Viewing Issue Advanced Details
ID: Category: Severity: Reproducibility: Date Submitted: Last Update:
5599 major random 12-03-13 06:25 11-05-14 16:17
Reporter: Mathias Lagerwall Platform:  
Assigned To: ferg OS:  
Priority: normal OS Version:  
Status: closed Product Version: 4.0.36  
Product Build: Resolution: fixed  
Projection: none      
ETA: none Fixed in Version: 4.0.42  
Summary: 0005599: Sometimes Resin takes really long time to save the session.
Description: It can take several minutes for Resin to save the session. The server is quite idle when this happens.

I get a lot of these in stderr. (once every 30 seconds or so)
OFFER_FAILED: Block[Table[data:6],3ec006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],330006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],3ea006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],3f2006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],14006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],350006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],3fa006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],34006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],3f8006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],370006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],3f6006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],390006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],3f4006,copy=false,load=false,dirty=true]
OFFER_FAILED: Block[Table[data:6],2f2006,copy=false,load=false,dirty=true]

The stacktrace for the thread that is taking a lot of time:
Thread 94: (state = BLOCKED)
 - java.lang.Object.wait(long) @bci=0 (Interpreted frame)
 - com.caucho.util.RingBlockerBasic.offerWait(long, java.util.concurrent.atomic.AtomicLong, int, long, java.util.concurrent.TimeUnit) @bci=98, line=81 (Interpreted frame)
 - com.caucho.util.RingValueQueue.offer(java.lang.Object, long, java.util.concurrent.TimeUnit, int) @bci=79, line=174 (Compiled frame)
 - com.caucho.util.RingValueQueue.offer(java.lang.Object, long, java.util.concurrent.TimeUnit) @bci=6, line=151 (Compiled frame)
 - com.caucho.db.block.BlockWriter.addDirtyBlockNoWake(com.caucho.db.block.Block) @bci=25, line=103 (Interpreted frame)
 - com.caucho.db.block.BlockWriter.addDirtyBlock(com.caucho.db.block.Block) @bci=2, line=67 (Compiled frame)
 - com.caucho.db.block.Block.save() @bci=31, line=446 (Compiled frame)
 - com.caucho.db.block.Block.commit() @bci=8, line=353 (Compiled frame)
 - com.caucho.db.xa.DbTransaction.writeData() @bci=56, line=453 (Compiled frame)
 - com.caucho.db.sql.QueryContext.unlock() @bci=143, line=641 (Compiled frame)
 - com.caucho.db.table.Table.insertRow(com.caucho.db.sql.QueryContext, com.caucho.db.xa.DbTransaction, java.util.ArrayList, java.util.ArrayList, com.caucho.db.block.Block, int) @bci=483, line=1095 (Compiled frame)
 - com.caucho.db.table.Table.insert(com.caucho.db.sql.QueryContext, com.caucho.db.xa.DbTransaction, java.util.ArrayList, java.util.ArrayList) @bci=100, line=977 (Interpreted frame)
 - com.caucho.db.sql.InsertQuery.execute(com.caucho.db.sql.QueryContext, com.caucho.db.xa.DbTransaction) @bci=39, line=116 (Interpreted frame)
 - com.caucho.db.jdbc.PreparedStatementImpl.execute() @bci=126, line=367 (Interpreted frame)
 - com.caucho.db.jdbc.PreparedStatementImpl.executeUpdate() @bci=1, line=337 (Interpreted frame)
 - com.caucho.server.distcache.DataStore.insert(java.io.InputStream, int) @bci=37, line=443 (Interpreted frame)
 - com.caucho.server.distcache.DataStore.save(java.io.InputStream, int) @bci=3, line=419 (Interpreted frame)
 - com.caucho.server.distcache.CacheDataBackingImpl.saveData(java.io.InputStream, int) @bci=6, line=282 (Interpreted frame)
 - com.caucho.server.distcache.LocalDataManager.writeData(java.io.InputStream) @bci=17, line=404 (Interpreted frame)
 - com.caucho.server.distcache.DistCacheEntry.putStream(java.io.InputStream, long, long, int, long, long, long, boolean) @bci=10, line=418 (Interpreted frame)
 - com.caucho.server.distcache.DistCacheEntry.put(java.io.InputStream, long, long, long, long) @bci=12, line=351 (Interpreted frame)
 - com.caucho.server.distcache.CacheImpl.put(java.lang.Object, java.io.InputStream, long, long, long, long) @bci=17, line=488 (Interpreted frame)
 - com.caucho.server.session.SessionImpl.save() @bci=124, line=908 (Interpreted frame)
 - com.caucho.server.http.AbstractCauchoRequest.saveSession() @bci=10, line=739 (Interpreted frame)
 - com.caucho.server.http.HttpServletResponseImpl.sendRedirect(java.lang.String) @bci=166, line=1012 (Interpreted frame)
 - se.netset.m4.NodeHttp.doPost() @bci=563, line=241 (Compiled frame)
 - se.netset.m4.NodeHttp.<init>(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=143, line=62 (Interpreted frame)
 - se.netset.m4.M4Comp.service(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=14, line=209 (Interpreted frame)
 - se.netset.m4.ServletAPIAdapter.doGet(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=86, line=176 (Interpreted frame)
 - se.netset.m4.ServletAPIAdapter.doPost(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=3, line=192 (Interpreted frame)
 - javax.servlet.http.HttpServlet.service(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=267, line=159 (Interpreted frame)
 - javax.servlet.http.HttpServlet.service(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=15, line=97 (Interpreted frame)
 - com.caucho.server.dispatch.ServletFilterChain.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=47, line=109 (Interpreted frame)
 - com.caucho.server.httpcache.ProxyCacheFilterChain.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=13, line=156 (Interpreted frame)
 - com.caucho.server.webapp.WebAppFilterChain.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=93, line=156 (Interpreted frame)
 - com.caucho.server.webapp.AccessLogFilterChain.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=6, line=95 (Interpreted frame)
 - com.caucho.server.dispatch.ServletInvocation.service(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=61, line=289 (Interpreted frame)
 - com.caucho.server.http.HttpRequest.handleRequest() @bci=380, line=838 (Interpreted frame)
 - com.caucho.network.listen.TcpSocketLink.dispatchRequest() @bci=98, line=1345 (Interpreted frame)
 - com.caucho.network.listen.TcpSocketLink.handleRequest() @bci=1, line=1301 (Compiled frame)
 - com.caucho.network.listen.TcpSocketLink.handleRequestsImpl(boolean) @bci=48, line=1285 (Compiled frame)
 - com.caucho.network.listen.TcpSocketLink.handleRequests(boolean) @bci=11, line=1193 (Interpreted frame)
 - com.caucho.network.listen.TcpSocketLink.handleAcceptTaskImpl() @bci=180, line=992 (Interpreted frame)
 - com.caucho.network.listen.ConnectionTask.runThread() @bci=54, line=117 (Interpreted frame)
 - com.caucho.network.listen.ConnectionTask.run() @bci=19, line=93 (Interpreted frame)
 - com.caucho.network.listen.SocketLinkThreadLauncher.handleTasks(boolean) @bci=108, line=169 (Interpreted frame)
 - com.caucho.network.listen.TcpSocketAcceptThread.run() @bci=61, line=61 (Interpreted frame)
 - com.caucho.env.thread2.ResinThread2.runTasks() @bci=158, line=173 (Interpreted frame)
 - com.caucho.env.thread2.ResinThread2.run() @bci=15, line=118 (Interpreted frame)


Resin-Pro-4.0.36
Windows
Win Server 2008 R2 Enterprise
java version "1.7.0_09"
Java(TM) SE Runtime Environment (build 1.7.0_09-b05)
Java HotSpot(TM) 64-Bit Server VM (build 23.5-b02, mixed mode)

Do you need any extra information to track this problem down?
Steps To Reproduce:
Additional Information:
Relationships
Attached Files:

Notes
(0006363)
ferg   
12-06-13 10:10   
Is there another thread that's doing the writing that also slow?

That code has two processes connected by message passing. The one above is the sending thread. There's also a consuming thread that takes the block and writes it to disk. The consumer is spawned on demand.

Depending on the thread dump there are two main possible issues:
  1) the writer is stuck somehow (you'd see a thread with another stuck thread)
  2) the messaging system has failed in the notification/spawning (you wouldn't see any other threads, and the system would never write more data.)

In either case, restarting would work around the issue, because it's a memory-based synchronization issue, not a file/data issue.
(0006552)
ferg   
11-05-14 16:17   
Added queue wake() before blocking in this situation to avoid case where queue is fill but worker has not been woken.

Because of the complexities of timing in this area of code, this may be a different issue than observed in the bug report.