ODB pool full: Webinterface not reachable while crawler is still working

[Slarti Bartfass]

Seams like OrientDB is again having issues - guess a restart would help. But I want Picapport to scan all 250k images with the PAI plugin. This is not done anymore, after I restart picapport.

Guess this happened while I used the webinterface to filter for newly "PAI:" tagged images while Picapport was still in the middle of scanning.

How can I fix this?
How can I give OrientDB more ressources the next time (100 locks seams not enough)?

Thanks

==== debug log========

DEBUG@ 12:06:31.420 Photo.saveToDocument: OrientDB-Workaround PHOTO_FUZZY_SEARCH: T$blume$ CP$156$ T$blüte$ CP$152$ CP$1264$ CP$24$ CP$8$ CP$3537$ CP$328$ CP$014$ CP$62$ T$pflanzen$ CP$135686$ CP$86$

DEBUG@ 12:06:31.423 DbWrapper.updatePhoto: /...DSC_6073.JPG

DEBUG@ 12:06:31.424 DbWrapper.reorgKeywordTreeAfterRemoval:keywords nothing to do.

DEBUG@ 12:06:31.424 DbWrapper.reorgKeywordTreeAfterRemoval:persons nothing to do.

DEBUG@ 12:06:31.424 PhotoSelectionProcessor.processFile: Proc=PaProcRunGroovy file=/...DSC_6074.JPG data={"proc":"PaProcRunGroovy","pars":{"addonId":"pagpPicApportAITagger

-PicApportAITagger","processAll":true,"id":"f1","mode":"0","tagPrefix":"$PicApportAI","pathToJava":"","javaOptions":"","updateDefaults":false,"analyseResult":false}}

DEBUG@ 12:06:31.424 PaProcRunGroovy.processPhoto[-1]: uid=SysPicApport jpg=/...DSC_6074.JPG

DEBUG@ 12:06:31.425 FileSystemMonitor.reorgIgnoredFiles: removed 1 entrys.

DEBUG@ 12:06:31.425 Groovy-pagpPicApportAITagger-PicApportAITagger:INFO de.contecon.dl4j.ModelEvaluator.Main - loading image /...DSC_6074.JPG

EXCEP@ ============================================================

EXCEP@ Exception at: 2021-11-15 12:06:31

EXCEP@          Msg:

EXCEP@ null

EXCEP@ ------------------------------------------------------------

EXCEP@ java.lang.reflect.InvocationTargetException

EXCEP@     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

EXCEP@     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

EXCEP@     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

EXCEP@     at java.lang.reflect.Method.invoke(Method.java:498)

EXCEP@     at de.contecon.picapport.server.servlet.PicApportJsonServlet.doGet(Unknown Source)

EXCEP@     at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)

EXCEP@     at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)

EXCEP@     at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799)

EXCEP@     at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:550)

EXCEP@     at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)

EXCEP@     at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)

EXCEP@     at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)

EXCEP@     at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434)

EXCEP@     at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)

EXCEP@     at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501)

EXCEP@     at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)

EXCEP@     at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)

EXCEP@     at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349)

EXCEP@     at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)

EXCEP@     at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)

EXCEP@     at org.eclipse.jetty.server.Server.handle(Server.java:516)

EXCEP@     at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388)

EXCEP@     at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633)

EXCEP@     at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380)

EXCEP@     at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)

EXCEP@     at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)

EXCEP@     at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)

EXCEP@     at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)

EXCEP@     at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)

EXCEP@     at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)

EXCEP@     at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)

EXCEP@     at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)

EXCEP@     at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:386)

EXCEP@     at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)

EXCEP@     at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)

EXCEP@     at java.lang.Thread.run(Thread.java:748)

EXCEP@ Caused by: com.orientechnologies.common.concur.lock.OLockException: No more resources available in pool (max=100). Requested resource: null

EXCEP@     at com.orientechnologies.common.concur.resource.OResourcePool.getResource(OResourcePool.java:74)

EXCEP@     at com.orientechnologies.orient.core.db.ODatabasePoolImpl.acquire(ODatabasePoolImpl.java:69)

EXCEP@     at com.orientechnologies.orient.core.db.ODatabasePool.acquire(ODatabasePool.java:132)

EXCEP@     at de.contecon.picapport.db.PicApportDBService.getPooledDbInstance(Unknown Source)

EXCEP@     at de.contecon.picapport.db.PicApportDBService.getDbWrapper(Unknown Source)

EXCEP@     at de.contecon.picapport.PicApportStatus.toJSON(Unknown Source)

EXCEP@     at de.contecon.picapport.server.servlet.PicApportJsonServlet.doCmdGetStatus(Unknown Source)

EXCEP@     ... 36 more

DEBUG@ 12:06:32.760 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 21 von 100

DEBUG@ 12:06:34.260 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 21 von 100

^^^^^^ Crawler and Plugins still working.

[PicApport]

...for 250000 photos we may need to check your java (version and type 32/64 Bit) and memory configuration. (It's in the beginning of each logfile after server start)

Does this also happen if you wait until the initial crawl has been terminated?

Does this also happen if you use a smaller amount of pictures for the call to the plugin?

How many users are concurrently using the server?

[Slarti Bartfass]

This is one page discussing the pool issue:

https://github.com/orientechnologies/orientdb/issues/7716

[Slarti Bartfass]

Forgot to mention: 1 user only. For me it seems like the initial crawling phase is most unstable. Version 9 of Picapport crashed a lot in the beginning till I managed to find a memory setting with the forums help which allowed it to scan all 250k images without crashing and destroying the OrientDB. Now with version PAP Ver 10 I wanted to use the PAI and OSM reverse coding plugin on all 250k images. So I configured PAP to start on an initial folder with only 10 images then I moved the folders containing all 250k images to the PAP folder. Then both add-ons

DEBUG@ 15:02:04.518 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 16 von 100

DEBUG@ 15:02:06.018 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 17 von 100

DEBUG@ 15:02:07.519 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 17 von 100

DEBUG@ 15:02:09.019 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 18 von 100

DEBUG@ 15:02:10.520 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 18 von 100

DEBUG@ 15:02:12.021 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 19 von 100

DEBUG@ 15:02:13.522 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 20 von 100

DEBUG@ 15:02:15.022 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 20 von 100

DEBUG@ 15:02:16.523 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 21 von 100

DEBUG@ 15:02:18.026 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 21 von 100

DEBUG@ 15:02:19.527 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 22 von 100

DEBUG@ 15:02:21.028 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 22 von 100

DEBUG@ 15:02:22.528 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 23 von 100

DEBUG@ 15:02:24.028 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 23 von 100

DEBUG@ 15:02:25.529 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 24 von 100

DEBUG@ 15:02:27.029 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 24 von 100

DEBUG@ 15:02:28.530 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 25 von 100

DEBUG@ 15:02:30.032 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 26 von 100

DEBUG@ 15:02:31.532 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 26 von 100

DEBUG@ 15:02:33.033 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 27 von 100

DEBUG@ 15:02:34.534 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 27 von 100

DEBUG@ 15:02:36.034 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 27 von 100

DEBUG@ 15:02:37.535 AddonAutoExecutionManager.NewPhotoConsumer.runAddon pagpPicApportAITagger-PicApportAITagger running: 28 von 100

 

[Slarti Bartfass]

Unfortunately the logfiles seam to not show the initial start anymore due to log rotation.

This is the StartPicapport.sh:

#!/bin/bash

ulimit -n 500000 &&  java -Xms512m -Xmx2G  -XX:ActiveProcessorCount=2 -DTRACE=DEBUG -Dstorage.diskCache.bufferSize=1024 -Duser.home=/opt/picapport -Duser.language=de -jar /opt/picapport/picapport-headless.jar

# -DTRACE=WARNING

# -DTRACE=DEBUG

# java -version

java version "1.8.0_261"

Java(TM) SE Runtime Environment (build 1.8.0_261-b12)

Java HotSpot(TM) 64-Bit Server VM (build 25.261-b12, mixed mode)

Any chance to temporary fixing this by logging into the Picapport console?

Thanks

[Slarti Bartfass]

I just lost faith and restarted Picapport with the same mechanism to trigger automated image tagging by the OSM and PAI add-ons: renamed the photo folder, created a new empty folder with the same name, moved some images to the new location, started Picapport, moved all images back to the new location with the old name.

Now its scanning and crawling.

I added a JAVA command line option which might increase OrientDBs Locking-Pool from 100 to 500: -Dclient.channel.maxPool=500

Despite Some random web pages discussing this topic say that this seems to be a result of a application error - a connection to the database is not always closed cleanly...

Lets see how it goes...

This is the log:

******************************************************************************

/opt/picapport/.picapport/logfiles/picapport.003 created at 2021-11-15 21:38:40

allowOutputOnSystemOut=true

******************************************************************************

Copyright (c) 1997-2021 Contecon Software GmbH. All rights reserved.

2021-11-15 21:38:40

Tracelevel: DEBUG

VER  @ 21:38:40.973 PicApport Version 10.2 from 15.10.2021 loaded.

VER  @ 21:38:40.974 de.contecon.picapport.PicApport.Version=V10.2.0 15.10.2021

VER  @ 21:38:40.975 java.runtime.version: 1.8.0_261-b12

VER  @ 21:38:40.975 java.version: 1.8.0_261

VER  @ 21:38:40.975 java.vm.version: 25.261-b12

VER  @ 21:38:40.976 java.vm.vendor: Oracle Corporation

VER  @ 21:38:40.976 java.vm.name: Java HotSpot(TM) 64-Bit Server VM

VER  @ 21:38:40.976 java.specification.version: 1.8

VER  @ 21:38:40.976 java.vm.specification.version: 1.8

VER  @ 21:38:40.977 java.class.path: /opt/picapport/picapport-headless.jar

VER  @ 21:38:40.977 os.name: Linux

VER  @ 21:38:40.978 os.version: 3.13.0-147-generic

VER  @ 21:38:40.978 os.arch: amd64

VER  @ 21:38:40.978 file.separator: /

VER  @ 21:38:40.979 path.separator: :

VER  @ 21:38:40.979 user.dir: /

VER  @ 21:38:40.980 user.home: /opt/picapport

VER  @ 21:38:40.980 user.name: root

MSG  @ 21:38:40.980 SystemProperty: log.console.level not set. PicApport sets default to:WARNING (OrientDB configuration)

MSG  @ 21:38:40.981 SystemProperty: storage.diskCache.bufferSize has been set with -Doption to:512 (OrientDB configuration)

MSG  @ 21:38:40.981 SystemProperty: com.sun.xml.bind.v2.bytecode.ClassTailor.noOptimize not set. PicApport sets default to:true (JAXB Java 17 Support)

MSG  @ 21:38:40.982 java.runtime totalMemory=514mb maxMemory=1908mb freeMemory=506mb processors=2

MSG  @ 21:38:40.993 java.runtime.argument: -Xms512m

MSG  @ 21:38:40.994 java.runtime.argument: -Xmx2G

MSG  @ 21:38:40.994 java.runtime.argument: -XX:ActiveProcessorCount=2

MSG  @ 21:38:40.995 java.runtime.argument: -DTRACE=DEBUG

MSG  @ 21:38:40.995 java.runtime.argument: -Dstorage.diskCache.bufferSize=1024

MSG  @ 21:38:40.995 java.runtime.argument: -Dclient.channel.maxPool=500

MSG  @ 21:38:40.996 java.runtime.argument: -Duser.home=/opt/picapport

MSG  @ 21:38:40.996 java.runtime.argument: -Duser.language=de

MSG  @ 21:38:40.996 PicApport home=/opt/picapport/.picapport

MSG  @ 21:38:40.997 PicApport logging to /opt/picapport/.picapport/logfiles

MSG  @ 21:38:40.997 Loading config File: /opt/picapport/.picapport/picapport.properties

INFO @ 21:38:41.025 PicApportProperties.mergeParameter: gui.enabled=false

DEBUG@ 21:38:41.026 GenProperties.getProperty: Key=server.port value=8080

DEBUG@ 21:38:41.026 GenProperties.getProperty: Key=server.contextpath value=null

INFO @ 21:38:41.057 PicApportServlet.initServletPathWithContext:/picapport

DEBUG@ 21:38:41.057 GenProperties.getProperty: Key=server.domain.name value=null

DEBUG@ 21:38:41.058 GenProperties.getProperty: Key=server.letsencrypt.challenge.port value=null

DEBUG@ 21:38:41.058 GenProperties.getProperty: Key=server.ssl value=false

DEBUG@ 21:38:41.059 GenProperties.getProperty: Key=server.ssl.provider value=null

[Slarti Bartfass]

Yesterday and today I restarted Picapport with Java 40 times, different config, more memory for the VM, not touched the web-interface during the initial scan etc.. Always the same problems - crash sooner or later. Then I noticed that the JVM gets the parameter "use 2 cores". Deactivated - since then no more crashes... So it looks very much like that some race conditions crash the system under stress.

[E. Schreiner]

... good to know. Thanks for the information. I'm afraid it's a problem of the orientdb. I'll have an eye on it for the next versions.

[Jobenvil]

Thanks as well from my side!

Just to be clear, do you men your flag  " -XX:ActiveProcessorCount=2" ? If yes, how many cores do you have? Just to be sure if you have two or more cpus and evaluate properly the context.

[Slarti Bartfass]

Yes,   " -XX:ActiveProcessorCount=1" did resolve the issue for about 2 days. After that and a lot of PAI scanning I still got a OrientDB corruption. But this was 48h of scan and runtime instead of 2h. Smeels like race conditions between the groovy java process and the core java process. In the end most often the lock-pool of 100 locks is exhausted.

[Slarti Bartfass]

BTW: now I have counted nearly 400k media files...

[Slarti Bartfass]

Yes, I changed it to -XX:ActiveProcessorCount=1 and no crash ever since. And further good news: Now its suddenly fast both in the web interface and in the Andorid App to be used on a day to day base.

Processor-wise: 2 Cores, 4 Multi-Threading cores:

Intel® Core™ i3-2310M Processor - Intel® Product ...

https://ark.intel.com › ark › products

CPU Specifications. Total Cores 2; Total Threads 4; Processor Base Frequency 2.10 GHz; Cache 3 MB Intel® Smart Cache; Bus Speed 5 GT/s

cat /proc/cpuinfo

processor       : 0

vendor_id       : GenuineIntel

cpu family      : 6

model           : 42

model name      : Intel(R) Core(TM) i3-2310M CPU @ 2.10GHz

stepping        : 7

microcode       : 0x23

cpu MHz         : 800.000

cache size      : 3072 KB

physical id     : 0

siblings        : 4

core id         : 0

cpu cores       : 2

apicid          : 0

initial apicid  : 0

fpu             : yes

fpu_exception   : yes

cpuid level     : 13

wp              : yes

flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer xsave avx lahf_lm arat epb xsaveopt pln pts dtherm retpoline tpr_shadow vnmi flexpriority ept vpid

bogomips        : 4190.76

clflush size    : 64

cache_alignment : 64

address sizes   : 36 bits physical, 48 bits virtual

power management:

processor       : 1

vendor_id       : GenuineIntel

cpu family      : 6

model           : 42

model name      : Intel(R) Core(TM) i3-2310M CPU @ 2.10GHz

stepping        : 7

microcode       : 0x23

cpu MHz         : 1700.000

cache size      : 3072 KB

physical id     : 0

siblings        : 4

core id         : 0

cpu cores       : 2

apicid          : 1

initial apicid  : 1

fpu             : yes

fpu_exception   : yes

cpuid level     : 13

wp              : yes

flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer xsave avx lahf_lm arat epb xsaveopt pln pts dtherm retpoline tpr_shadow vnmi flexpriority ept vpid

bogomips        : 4190.76

clflush size    : 64

cache_alignment : 64

address sizes   : 36 bits physical, 48 bits virtual

power management:

[Slarti Bartfass]

Not sure, if its only OrientDB. If it helps I can donate some log files. Lots of data and lots of exceptions in some Java components. On a short look a lot of exceptions from OrientDB but from PAI groovy plugin as well. Tings got worse pretty fast when I used the web interface at the same time when the crawler was doing the initial scan and PAI and OSM work on each image.

With the setting " -XX:ActiveProcessorCount=1" Picaport is way more responsive and there is no crash since 24 hours+ while its scanning images through PAI all the time.

this is my config:

ulimit -n 500000 &&  java -Xms512m -Xmx4G  -XX:ActiveProcessorCount=1 -DTRACE=DEBUG -Dstorage.diskCache.bufferSize=1024 -Dclient.channel.maxPool=500 -Duser.home=/opt/picapport -Duser.language=de -jar /opt/picapport/picapport-headless.jar

 

Guess, I can reduce -Xmx4G back to 2G.

You might wonder why I was reducing " -XX:ActiveProcessorCount=2" to " -XX:ActiveProcessorCount=1" . Gut feeling and experence of seeing concurrent software implementations fail due to race conditions since 20 years now.