DatabaseBusyException: how to analyze and overcome?

[rpoehlmann]

Dear all,

seems like we are running in database connection pool issues:
recently, we started to receive several errors from user activities with omero::DatabaseBusyException:

Code: Select all

Internal Server Error: /webclient/
Traceback (most recent call last):
  File "/home/omeronas/omeroweb/lib/python2.7/site-packages/django/core/handlers/base.py", line 132, in get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/home/omeronas/OMERO.server/lib/python/omeroweb/decorators.py", line 474, in wrapped
    retval = f(request, *args, **kwargs)
  File "/home/omeronas/OMERO.server/lib/python/omeroweb/decorators.py", line 524, in wrapper
    context = f(request, *args, **kwargs)
  File "/home/omeronas/OMERO.server/lib/python/omeroweb/webclient/views.py", line 463, in load_template
    url=url, **kwargs)
  File "/home/omeronas/OMERO.server/lib/python/omeroweb/webclient/views.py", line 388, in _load_template
    conn.getEventContext().groupId)
  File "/home/omeronas/OMERO.server/lib/python/omero/gateway/__init__.py", line 2208, in getEventContext
    self._ctx = self._proxies['admin'].getEventContext()
  File "/home/omeronas/OMERO.server/lib/python/omero/gateway/__init__.py", line 4528, in __call__
    return self.handle_exception(e, *args, **kwargs)
  File "/home/omeronas/OMERO.server/lib/python/omeroweb/webclient/webclient_gateway.py", line 2025, in handle_exception
    e, *args, **kwargs)
  File "/home/omeronas/OMERO.server/lib/python/omero/gateway/__init__.py", line 4525, in __call__
    return self.f(*args, **kwargs)
  File "/home/omeronas/OMERO.server/lib/python/omero_api_IAdmin_ice.py", line 2354, in getEventContext
    return _M_omero.api.IAdmin._op_getEventContext.invoke(self, ((), _ctx))
DatabaseBusyException: exception ::omero::DatabaseBusyException
{
    serverStackTrace = ome.conditions.DatabaseBusyException: Cannot acquire connection
   at ome.services.db.SelfCorrectingDataSource.callWithRetries(SelfCorrectingDataSource.java:113)
   at ome.services.db.SelfCorrectingDataSource.getConnection(SelfCorrectingDataSource.java:60)
   at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:203)
   at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)
   at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:354)
   at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:103)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:249)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:121)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
   at com.sun.proxy.$Proxy81.getEventContext(Unknown Source)
   at sun.reflect.GeneratedMethodAccessor452.invoke(Unknown Source)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   at java.lang.reflect.Method.invoke(Method.java:498)
   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
   at ome.security.basic.BasicSecurityWiring.invoke(BasicSecurityWiring.java:93)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at ome.services.blitz.fire.AopContextInitializer.invoke(AopContextInitializer.java:43)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
   at com.sun.proxy.$Proxy81.getEventContext(Unknown Source)
   at sun.reflect.GeneratedMethodAccessor715.invoke(Unknown Source)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   at java.lang.reflect.Method.invoke(Method.java:498)
   at ome.services.blitz.util.IceMethodInvoker.invoke(IceMethodInvoker.java:172)
   at ome.services.throttling.Callback.run(Callback.java:56)
   at ome.services.throttling.InThreadThrottlingStrategy.callInvokerOnRawArgs(InThreadThrottlingStrategy.java:56)
   at ome.services.blitz.impl.AbstractAmdServant.callInvokerOnRawArgs(AbstractAmdServant.java:140)
   at ome.services.blitz.impl.AdminI.getEventContext_async(AdminI.java:217)
   at sun.reflect.GeneratedMethodAccessor714.invoke(Unknown Source)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   at java.lang.reflect.Method.invoke(Method.java:498)
   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
   at omero.cmd.CallContext.invoke(CallContext.java:78)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
   at com.sun.proxy.$Proxy82.getEventContext_async(Unknown Source)
   at omero.api._IAdminTie.getEventContext_async(_IAdminTie.java:192)
   at omero.api._IAdminDisp.___getEventContext(_IAdminDisp.java:1881)
   at omero.api._IAdminDisp.__dispatch(_IAdminDisp.java:2041)
   at IceInternal.Incoming.invoke(Incoming.java:221)
   at Ice.ConnectionI.invokeAll(ConnectionI.java:2536)
   at Ice.ConnectionI.dispatch(ConnectionI.java:1145)
   at Ice.ConnectionI.message(ConnectionI.java:1056)
   at IceInternal.ThreadPool.run(ThreadPool.java:395)
   at IceInternal.ThreadPool.access$300(ThreadPool.java:12)
   at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832)
   at java.lang.Thread.run(Thread.java:748)

    serverExceptionClass = ome.conditions.DatabaseBusyException
    message = Cannot acquire connection
    backOff = 0


The OMERO config has a "omero.db.poolsize=80" defined. Postgres is still on the default value of 100 connections.

Any ideas how I could further analyze/debug this issue including hints how to overcome?
Any additional info/output needed?

Thanks a lot in advance, best,
-Rainer

P.S.: by the way, talking about OMERO.server-5.3.4-ice36-b69 and psql (PostgreSQL) 9.4.17 on CentOS 7.4.1708

[mtbc]

Dear Rainer,

Thank you, good to know that you are on CentOS 7. I think that you would normally expect rather high limits in places like /etc/security/limits.conf and /proc/sys/fs/file-max but maybe it's worth quickly checking while we are trying to figure this problem out. I am afraid that we are a bit short-handed this week.

The Monitoring and Metrics parts of https://docs.openmicroscopy.org/omero/5 ... mance.html may be helpful for you in keeping an eye on how many files are being held open. After an OMERO.server restart or an OMERO.web restart with luck you will see them start off low and perhaps there is some clue in the pattern of their growth and then you can also get warning that it might be time to restart the server. There's also the question of which server: Are both OMERO.server and OMERO.web running on the same system, as the same user? Could OMERO.web sessions (Django or OMERO) being held open exhaust file handles for OMERO.server's connections to PostgreSQL?

Over recent months we have worked on reducing leakage of file handles. Some of the issues were exacerbated by configuring a public user for OMERO.web: do you have one enabled? Other issues were NumPy-related, I think: which version of that do you have installed? OMERO 5.4.6 should include another round of such leakage fixes but there were earlier ones too so you may already find 5.4.5 an improvement and when we release 5.4.6 that may certainly be worth your consideration.

Sorry to have more questions than answers at this point! I appreciate that restarts can be very disruptive for your user community.

Cheers,
Mark

[mtbc]

(A small housekeeping note: QA 20629 thru 20632 are client-side views of this trouble.)

[rpoehlmann]

Dear Mark,

thanks a lot for your reply.

regarding open file limits, there seems to be one: /etc/security/limits.conf

Code: Select all

omeronas  soft  nofile  10000
omeronas  hard  nofile  12000


and

Code: Select all

[omeronas@omero02 ~]$ cat  /proc/sys/fs/file-max
26212486


Mmmh, maybe I need to increase?

I installed VisualVM, and I also could start JConsole. In terms of making sense out of those info I feel slightly overwhelmed since I am not really deeply familiar with JVM monitoring details.

jconsole_threading_attributes.png (58.15 KiB) Viewed 1938 times

E.g. is this ThreadCount the actual no. of threads issued by Blitz? So far, I could observe numbers between 50-<80.

VisualVM_Blitz_Screen.png (32.76 KiB) Viewed 1938 times

The upgrade to OMERO 5.4.5 is planned, I will asap rehearse it on our TEST system before we will also upgrade the PROD system afterwards. Therefore it is good to hear that this might improve the situation as well.

Please do not hesitate to request additional info if needed.

Thanks a lot, best,
-Rainer

[rpoehlmann]

Addendum:
Interestingly, the no. of open files is reported as defined in "/etc/security/limits.conf"

Code: Select all

[omeronas@omero02 systemd]$ prlimit -n
RESOURCE DESCRIPTION               SOFT  HARD UNITS
NOFILE   max number of open files 10000 12000


However, when I take a closer look at the main Blitz process, this one seems to have different restrictions:

Code: Select all

[omeronas@omero02 systemd]$ prlimit -p 9699 -n
RESOURCE DESCRIPTION              SOFT HARD UNITS
NOFILE   max number of open files 4096 4096


Code: Select all

[omeronas@omero02 systemd]$ ps -ewf | grep 9699
omeronas  9699  2775  5 Apr23 ?        02:15:52 java -Xmx96000m -XX:MaxPermSize=1g -XX:+IgnoreUnrecognizedVMOptions -Djava.awt.headless=true -Dlogback.configurationFile=etc/logback.xml -Domero.logfile=var/log/${omero.name}.log -Domero.logbase=/OMERO/ManagedRepository/ -Domero.name=Blitz-0 ome.services.blitz.Entry --Ice.Config=/home/omeronas/OMERO.server-5.3.4-ice36-b69/var/master/servers/Blitz-0/config/config
omeronas 24595 12805  0 08:02 pts/0    00:00:00 grep --color=auto 9699


Puzzled ...

[jmoore]

Hi Rainer,

a quick suggestion being one of the those who have left the others short-handed...

when & if your server gets into this state, can you check both what the server is doing as well as what PostgreSQL is doing via:

Code: Select all

jstack $(bin/omero admin ice server pid Blitz-0)


and

Code: Select all

psql omero -c "select * from pg_stat_activity"


Cheers,
~Josh