lock awaited for FileDescriptorCache, production issue

[ruchi]

Hi,
We are using zimbra for yahoo calendar. In production, we are facing locking issues. Folowing is the stack trace :

btpool0-441 runnable
Waiting for: 0x0000002a9fee7488 - UNKNOWN
btpool0-372 is waiting on this thread
btpool0-375 is waiting on this thread
btpool0-380 is waiting on this thread
btpool0-386 is waiting on this thread
btpool0-389 is waiting on this thread
btpool0-394 is waiting on this thread
btpool0-396 is waiting on this thread
btpool0-402 is waiting on this thread
btpool0-403 is waiting on this thread
btpool0-404 is waiting on this thread
btpool0-405 is waiting on this thread
btpool0-417 is waiting on this thread
btpool0-419 is waiting on this thread
btpool0-422 is waiting on this thread
btpool0-423 is waiting on this thread
btpool0-427 is waiting on this thread
btpool0-428 is waiting on this thread
btpool0-429 is waiting on this thread
btpool0-430 is waiting on this thread
btpool0-432 is waiting on this thread
btpool0-433 is waiting on this thread
btpool0-435 is waiting on this thread
btpool0-436 is waiting on this thread
btpool0-437 is waiting on this thread
btpool0-438 is waiting on this thread
btpool0-444 is waiting on this thread
btpool0-445 is waiting on this thread
btpool0-448 is waiting on this thread
btpool0-449 is waiting on this thread
btpool0-454 is waiting on this thread
"btpool0-441" prio=1 tid=0x0000002bb8686160 nid=0x32bd runnable [0x00000000488b4000..0x00000000488b6c30]
at com.zimbra.cs.store.FileDescriptorCache.getSharedF ile(FileDescriptorCache.java:119)
- waiting to lock <0x0000002a9fee7488> (a com.zimbra.cs.store.FileDescriptorCache)
at com.zimbra.cs.store.FileDescriptorCache.read(FileD escriptorCache.java:88)
at com.zimbra.cs.store.BlobInputStream.read(BlobInput Stream.java:205)
at com.sun.mail.util.LineInputStream.readLine(LineInp utStream.java:84)
at javax.mail.internet.InternetHeaders.load(InternetH eaders.java:338)
at javax.mail.internet.InternetHeaders.<init>(Interne tHeaders.java:310)
at javax.mail.internet.MimeMessage.createInternetHead ers(MimeMessage.java:2107)
at javax.mail.internet.MimeMessage.parse(MimeMessage. java:328)
at javax.mail.internet.MimeMessage.<init>(MimeMessage .java:205)
at com.sun.mail.handlers.message_rfc822.getContent(me ssage_rfc822.java:98)
at javax.activation.DataSourceDataContentHandler.getC ontent(DataHandler.java:803)
at javax.activation.DataHandler.getContent(DataHandle r.java:550)
at javax.mail.internet.MimeBodyPart.getContent(MimeBo dyPart.java:630)
at com.zimbra.cs.mime.Mime.getMessageContent(Mime.jav a:410)
at com.zimbra.cs.mailbox.CalendarItem.getSubpartMessa ge(CalendarItem.java:2775)
at com.zimbra.cs.mailbox.calendar.Invite.loadDescFrom Blob(Invite.java:819)
- locked <0x0000002b557b6810> (a com.zimbra.cs.mailbox.calendar.Invite)
at com.zimbra.cs.mailbox.calendar.Invite.getDescripti on(Invite.java:808)
- locked <0x0000002b557b6810> (a com.zimbra.cs.mailbox.calendar.Invite)
at com.zimbra.cs.mailbox.calendar.Invite.newToVCompon ent(Invite.java:2135)
at com.zimbra.cs.mailbox.calendar.Invite.toVComponent s(Invite.java:2317)
at com.zimbra.cs.mailbox.Mailbox.writeICalendarForCal endarItems(Mailbox.java:3285)
- locked <0x0000002ab6882498> (a com.yahoo.calendar.cs.mailbox.YCalMailbox)
at com.zimbra.cs.service.formatter.IcsFormatter.forma tCallback(IcsFormatter.java:107)



As you can see, the lock is awaited for FileDescriptorCache. Does this require enabling or optimizing any cache parameter ?

Appreciate your response , since this is happening in production and leading to server hang.

Regards,
Ruchi

[uxbod]

Welcome to the forums

Is ZCS installed on physical hardware or is it a virtual machine ? Please update your profile with the following as it provides more information

su - zimbra
zmcontrol -v

[veronica]

I hope you have sufficient number of file descriptors defined.

[ruchi]

Hi,
Thanks for the reply. Checked file
descriptors on production , /etc/security/limits.conf says :
zimbra soft nofile 524288
zimbra hard nofile 524288

which is correct as per Performance Tuning Guidelines for Large Deployments - Zimbra :: Wiki



We have hit the same issue again :
The GC logs analysis looks something like this :
btpool0-2446 waiting for monitor entry
Waiting for: 0x0000002a9f858800 - UNKNOWN
btpool0-2401 is waiting on this thread
btpool0-2406 is waiting on this thread
btpool0-2407 is waiting on this thread
btpool0-2412 is waiting on this thread
btpool0-2413 is waiting on this thread
btpool0-2416 is waiting on this thread
btpool0-2426 is waiting on this thread
btpool0-2434 is waiting on this thread
btpool0-2435 is waiting on this thread
btpool0-2436 is waiting on this thread
btpool0-2438 is waiting on this thread
btpool0-2440 is waiting on this thread
btpool0-2455 is waiting on this thread
"btpool0-2446" prio=1 tid=0x0000002bacc2ec50 nid=0x3eaf waiting for monitor entry
[0x0000000041844000..0x0000000041846ab0]
at com.zimbra.cs.store.FileDescriptorCache.closeIfPru ned(FileDescriptorCache.java:107)
- waiting to lock <0x0000002a9f858800> (a com.zimbra.cs.store.FileDescriptorCache)
at com.zimbra.cs.store.FileDescriptorCache.read(FileD escriptorCache.java:90)
at com.zimbra.cs.store.BlobInputStream.read(BlobInput Stream.java:205)
at com.sun.mail.util.LineInputStream.readLine(LineInp utStream.java:84)
at javax.mail.internet.InternetHeaders.load(InternetH eaders.java:338)
at javax.mail.internet.InternetHeaders.<init>(Interne tHeaders.java:310)
at javax.mail.internet.MimeMessage.createInternetHead ers(MimeMessage.java:2107)
at javax.mail.internet.MimeMessage.parse(MimeMessage. java:328)
at javax.mail.internet.MimeMessage.<init>(MimeMessage .java:205)
at com.sun.mail.handlers.message_rfc822.getContent(me ssage_rfc822.java:98)
at javax.activation.DataSourceDataContentHandler.getC ontent(DataHandler.java:803)
at javax.activation.DataHandler.getContent(DataHandle r.java:550)
at javax.mail.internet.MimeBodyPart.getContent(MimeBo dyPart.java:630)
at com.zimbra.cs.mime.Mime.getMessageContent(Mime.jav a:410)
at com.zimbra.cs.mailbox.CalendarItem.getSubpartMessa ge(CalendarItem.java:2775)
at com.zimbra.cs.mailbox.calendar.Invite.loadDescFrom Blob(Invite.java:819)
- locked <0x0000002ac492a510> (a com.zimbra.cs.mailbox.calendar.Invite)
at com.zimbra.cs.mailbox.calendar.Invite.getDescripti on(Invite.java:808)
- locked <0x0000002ac492a510> (a com.zimbra.cs.mailbox.calendar.Invite)
at com.zimbra.cs.mailbox.calendar.Invite.newToVCompon ent(Invite.java:2135)
at com.zimbra.cs.mailbox.calendar.Invite.toVComponent s(Invite.java:2317)
at com.zimbra.cs.mailbox.Mailbox.writeICalendarForCal endarItems(Mailbox.java:3285)
- locked <0x0000002b625ee468> (a com.yahoo.calendar.cs.mailbox.YCalMailbox)
at com.zimbra.cs.service.formatter.IcsFormatter.forma tCallback(IcsFormatter.java:107)
at com.zimbra.cs.service.formatter.Formatter.format(F ormatter.java:85)
at com.zimbra.cs.service.UserServlet.doAuthGet(UserSe rvlet.java:520)
at com.zimbra.cs.service.UserServlet.doGet(UserServle t.java:423)
at javax.servlet.http.HttpServlet.service(HttpServlet .java:707)
at com.zimbra.cs.servlet.ZimbraServlet.service(Zimbra Servlet.java:181)
at javax.servlet.http.HttpServlet.service(HttpServlet .java:820)
at org.mortbay.jetty.servlet.ServletHolder.handle(Ser vletHolder.java:511)
at org.mortbay.jetty.servlet.ServletHandler.handle(Se rvletHandler.java:390)
at org.mortbay.jetty.security.SecurityHandler.handle( SecurityHandler.java:216)
at org.mortbay.jetty.servlet.SessionHandler.handle(Se ssionHandler.java:182)
at org.mortbay.jetty.handler.ContextHandler.handle(Co ntextHandler.java:765)
at org.mortbay.jetty.webapp.WebAppContext.handle(WebA ppContext.java:418)
at org.mortbay.jetty.servlet.Dispatcher.forward(Dispa tcher.java:327)
at org.mortbay.jetty.servlet.Dispatcher.forward(Dispa tcher.java:126)



From the logs, we can make out that this thread is waiting to get lock on filedescriptor cache while all other threads
are waiting on this thread. The method for which this thread is waiting checks if cache does not have the file entry ,
it tries to close the file. It appears , a thread is not able to close the file and therefore holding the lock on
filedescriptor cache , and all other threads are waiting to get lock on filedescriptor cache.


Is there a way to set a timeout for file close operation.

Help/pointers appreciated.

thanks,
Ruchi