repeated getPlane in matlab lead to "too many file opened"

[jacques2020]

Dear Omero developper,

I am using omero within home developped matlab code and since upgrade to 5.2 (and still now with 5.2.1) I get an error serverExceptionClass = "ome.conditions.ResourceError" message = "/OMERO/Pixels/Dir-195/195654 (Too many open files)" upon calling getPlane (see full message below). My code call this function repeatedly to go through all planes of long datasets (typiquelly 20 000 frames spread over several Image structured grouped in a dataset. Only one session is opened at the beginning and stored in a global var to be re-used.

ls /proc/19110/fd | wc -l reports ridiculously small number of opened files (535 for matlab and 4 for helper).

I cannot find anything suspicious in the Blitz.log of the server and no error for sure.

Do you have any clue about this issue. Should I close something after using a plane. Is there anything I can do to investigate this issue ?

Many thanks in advance for your help

Jacques

-----------------------
error reported at line 63 of getPlane

Java exception occurred:
omero.ResourceError
serverStackTrace = "ome.conditions.ResourceError: /OMERO/Pixels/Dir-195/195654 (Too many open files)
at ome.services.RawPixelsBean.handleException(RawPixelsBean.java:689)
at ome.services.RawPixelsBean.getPlane(RawPixelsBean.java:388)
at sun.reflect.GeneratedMethodAccessor759.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
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.EventHandler.invoke(EventHandler.java:154)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at ome.tools.hibernate.SessionHandler.doStateful(SessionHandler.java:216)
at ome.tools.hibernate.SessionHandler.invoke(SessionHandler.java:200)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108)
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.$Proxy104.getPlane(Unknown Source)
at sun.reflect.GeneratedMethodAccessor759.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
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.$Proxy104.getPlane(Unknown Source)
at sun.reflect.GeneratedMethodAccessor784.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
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.RawPixelsStoreI.getPlane_async(RawPixelsStoreI.java:102)
at sun.reflect.GeneratedMethodAccessor783.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
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.$Proxy105.getPlane_async(Unknown Source)
at omero.api._RawPixelsStoreTie.getPlane_async(_RawPixelsStoreTie.java:138)
at omero.api._RawPixelsStoreDisp.___getPlane(_RawPixelsStoreDisp.java:1001)
at omero.api._RawPixelsStoreDisp.__dispatch(_RawPixelsStoreDisp.java:1410)
at IceInternal.Incoming.invoke(Incoming.java:222)
at Ice.ConnectionI.invokeAll(ConnectionI.java:2482)
at Ice.ConnectionI.dispatch(ConnectionI.java:1258)
at Ice.ConnectionI.message(ConnectionI.java:1213)
at IceInternal.ThreadPool.run(ThreadPool.java:321)
at IceInternal.ThreadPool.access$300(ThreadPool.java:12)
at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:693)
at java.lang.Thread.run(Thread.java:745)
"
serverExceptionClass = "ome.conditions.ResourceError"
message = "/OMERO/Pixels/Dir-195/195654 (Too many open files)"
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
at java.lang.reflect.Constructor.newInstance(Unknown Source)
at java.lang.Class.newInstance(Unknown Source)
at IceInternal.BasicStream.createUserException(BasicStream.java:2615)
at IceInternal.BasicStream.access$300(BasicStream.java:12)
at IceInternal.BasicStream$EncapsDecoder10.throwException(BasicStream.java:3099)
at IceInternal.BasicStream.throwException(BasicStream.java:2077)
at IceInternal.Outgoing.throwUserException(Outgoing.java:538)
at omero.api._RawPixelsStoreDelM.getPlane(_RawPixelsStoreDelM.java:609)
at omero.api.RawPixelsStorePrxHelper.getPlane(RawPixelsStorePrxHelper.java:2872)
at omero.api.RawPixelsStorePrxHelper.getPlane(RawPixelsStorePrxHelper.java:2836)

[sbesson]

Hi Jacques,

The "Too many open open files" error as you describe it could arise from unclosed active services indeed. First a few questions: since you have access to the server, do you know what the ulimit is set to? Do you know how many raw pixel store services are open at one time? Also is your code closing them when they are no longer used?
If you had a link to a public repository containing your code (or at least the relevant section), it might help troubleshooting the issue.

Best,
Sebastien

[jacques2020]

Hi Sebastien,

thank you for your answer. I looked (although without expertise to ulimit and find nothing). I copy it below. The code is not publicly exposed and is quite big and complex. I have a hard time trying to make a minimal example of the bug, since it apparently involve something else than the sole repetitive call to getPlane. I keep you posted of my progress.

Best,

Jacques



------------------------ ulimit server
cedre-agent@cedre-5a:/var/log/backups$ ulimit -a
core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 288371
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 65536
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) 288371
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited

--------------------------- ulimit client
ulimit -a
core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 289403
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 65536
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) 289403
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited

[jacques2020]

Hi,

Just to help me providing you with a minimal code. When I trigger the exception, do I hit a limit on client side or server side ?

Thank you

Jacques

[jmoore]

The exception is because the server is holding onto too many files at once. And considering your limit is quite high (65K), something seems suspicious.

Cheers,
~Josh.

[jacques2020]

Dear Josh,

I therefore sought something suspicious and found a putative culprit. The server is auto-backuped up using duplicity and the number of opened inodes increased dramatically during the backups. I moved the duplicity cache to a filesystem different from root and after one month, it seems to have solve the issue. This is only speculative but I have not seen the bug any more.

Thank you for your help.

Cheers

Jacques

[jmoore]

Glad to hear it!
~Josh.