large number of temporay files - is this normal

[stefanm]

Hi Bernie,

thanks for the answer anyway. I still suspect those are basically leftovers from one process/thread not closing a file, that another process/thread has already deleted. I cannot imagine anything that has to do with filesystem mount options, especially because 64bit mount options are the default for xfs on x64 architectures.

Best regards,
Stefan

[stefanm]

Hello again

some final information, that really slipped my attention so far.

At the moment the number of open files in .../data/FullText/ is at 1530, all with the same pattern _???.cfs.
This time all of those are not marked as deleted in lsof. But something that I did not catch before is, that the 1500+ files are actually all pointing to the same 18 distinct files, so that each file in .../data/FullText/ has 85 open file descriptors, and it's varying between 85 and 86 at the moment. Reinspecting my lsof-output from my earlier post shows, that it was already the case there. So already there, there were only 22 distinct files that were marked as "(deleted)", but each had 91 open file descriptors.

[jmoore]

Hi Stefan,

the file handles that are being left over here are not directly under OMERO's control, but rather (our rather old version of) Lucene's. Researching, there seem to be some similar situations around, e.g. https://jira.atlassian.com/browse/JRA-33887.

As a possible workaround that we could test, do you have another filesystem available on this box that you could use? You shouldn't need more than 2GB, especially not initially, and can symlink from /OMERO/FullText to the new location.

Sorry for the trouble.
~Josh.

[stefanm]

Hi Josh,

I hope I did what you meant me to do.
I
- shut down OMERO
- created a FullText dir on a btrfs file system (obviously different from the xfs file system)
- rsync'd the FullText dir over to the one on the btrfs file system
- renamed the original FullText dir
- recreated FullText dir at the original location as a soft link to the btrfs FullText dir
- restarted OMERO

but, alas, no joy. The file handle count right after starting OMERO is up to 90 for each file and after a couple of minutes settles down to 85-86 as reported previously.

Best regards and thanks for your time and help
Stefan

[jmoore]

Would you mind uploading your var/log/Indexer-0.log so we can see if there's anything suspicious? var/log/master.out and master.err may also be useful.

Thanks,
~Josh.

[stefanm]

No problem, I attached both files in a zip file.
Note: I upgraded from 5.0.0 to current on May 2nd, in the process the "scripts directory problem" slipped my attention and therefore a couple of error messages have been generated producing probably quite a bit of noise...

[jmoore]

Hi Stefan,

Unfortunately I'm having trouble following what's going on in Indexer-0.log. The restart times listed are:

Code: Select all

2014-04-30 11:33:00
2014-04-30 13:28:42
2014-04-30 13:31:29
2014-05-05 16:59:37
2014-05-07 11:48:44
2014-05-07 11:51:05
2014-05-07 16:28:18
2014-05-07 17:32:04
2014-05-09 16:13:38
2014-05-09 16:18:13
2014-05-19 09:23:49
2014-05-20 15:52:06


Do those sound plausible for manual restarts by you?

Cheers,
~Josh.

[stefanm]

Hello Josh,

thanks for having a look and sorry for the delay in answering - I have been away for a couple of days. An earlier answer seems to have vanished because of a BB session time out. Here is a short version: Yes all of those restarts have been issued manually for various reasons. The server is not a production server for OMERO, yet. The restarts on May 9th were actually done on your request because I changed the location of the FullText dir. Some of the others are related to the upgrade from 5.0.0 to 5.0.1 and the subsequent fixing of the related script-dir problem (April 30th & May 2nd). At least on one or two occasions I restarted OMERO because either some of its shared libs were security-patched or the postgresql DB-server had to be restarted for the same reason.

In my bash history I found the following:

Code: Select all

2014-04-29 18:15:14 su omero -c "/opt/omero/bin/omero admin start"
2014-04-30 11:10:33 su omero -c "/opt/omero/bin/omero admin stop"
2014-04-30 11:31:22 su omero -c "/opt/omero/bin/omero admin start"
2014-04-30 11:32:34 su omero -c "/opt/omero/bin/omero admin start"
2014-04-30 13:24:21 su omero -c "/opt/omero/bin/omero admin stop"
2014-04-30 13:28:21 su omero -c "/opt/omero/bin/omero admin start"
2014-04-30 13:30:43 su omero -c "/opt/omero/bin/omero admin stop"
2014-04-30 13:31:09 su omero -c "/opt/omero/bin/omero admin start"
2014-05-05 16:59:11 su omero -c "/opt/omero/bin/omero admin start"
2014-05-06 16:49:20 su omero -c "/opt/omero/bin/omero admin stop"
2014-05-07 11:47:40 systemctl stop omero
2014-05-07 11:48:18 systemctl start omero
2014-05-07 11:49:41 systemctl stop omero
2014-05-07 11:50:44 systemctl start omero
2014-05-07 16:06:59 systemctl stop omero
2014-05-07 16:27:56 systemctl start omero
2014-05-07 16:28:53 systemctl stop omero
2014-05-07 17:31:44 systemctl start netatalk smb omero
2014-05-09 16:11:24 systemctl stop omero
2014-05-09 16:13:17 systemctl start omero
2014-05-09 16:16:39 systemctl stop omero
2014-05-09 16:17:54 systemctl start omero
2014-05-19 09:23:14 systemctl restart omero
2014-05-19 17:05:36 systemctl stop omero
2014-05-20 15:51:36 systemctl start omero


which pretty much matches the index-0.log data.

I hope this helps and thanks for your help

Best regards,
Stefan

[jmoore]

Hi Stefan,

glad it all makes sense, but unfortunately doesn't leave me much to work with:

Code: Select all

2014-05-20 15:51:49,876 INFO  [                ome.services.blitz.Entry] (      main) Waiting 10000 ms on startup
2014-05-20 15:51:59,890 INFO  [                ome.services.blitz.Entry] (      main) Creating ome.fulltext. Please wait...
2014-05-20 15:52:06,427 INFO  [           ome.services.util.DBUserCheck] (      main) User root.id = 0
2014-05-20 15:52:06,437 INFO  [           ome.services.util.DBUserCheck] (      main) User guest.id = 1
2014-05-20 15:52:06,437 INFO  [           ome.services.util.DBUserCheck] (      main) Group system.id = 0
2014-05-20 15:52:06,437 INFO  [           ome.services.util.DBUserCheck] (      main) Group user.id = 1
2014-05-20 15:52:06,437 INFO  [           ome.services.util.DBUserCheck] (      main) Group guest.id = 2
2014-05-20 15:52:06,452 INFO  [      ome.services.util.JvmSettingsCheck] (      main) Java version: 1.7.0_51; Linux; amd64; 3.11.6-4-default
2014-05-20 15:52:06,452 INFO  [      ome.services.util.JvmSettingsCheck] (      main) Max Memory (MB):   =    227
2014-05-20 15:52:06,465 INFO  [      ome.services.util.JvmSettingsCheck] (      main) OS Memory (MB):    =   7996
2014-05-20 15:52:06,465 INFO  [      ome.services.util.JvmSettingsCheck] (      main) Processors:        =      2
2014-05-20 15:52:06,649 INFO  [.s.ShutdownSafeEhcacheManagerFactoryBean] (      main) Initializing EHCache CacheManager
2014-05-20 15:52:19,060 INFO  [  ome.services.fulltext.FullTextAnalyzer] (      main) Initialized FullTextAnalyzer
2014-05-20 15:52:33,477 WARN  [        ome.services.fulltext.FileParser] (      main) Indexer maximum file size is set to more than half of total heap size. Excessively large text files may cause search index corruption. Consider decreasing the maximum file size or increasing the Indexer heap size.
2014-05-20 15:52:33,480 WARN  [        ome.services.fulltext.FileParser] (      main) Indexer maximum file size is set to more than half of total heap size. Excessively large text files may cause search index corruption. Consider decreasing the maximum file size or increasing the Indexer heap size.
2014-05-20 15:52:33,597 INFO  [    ome.services.fulltext.FullTextThread] (      main) Initializing Full-Text Indexer
2014-05-20 15:52:34,548 INFO  [        ome.services.db.DatabaseIdentity] (      main) Using LSID format: urn:lsid:export.openmicroscopy.org:%s:7ebc12fd-10c7-4934-b8d8-c94ce6e03dc9_%s%s
2014-05-20 15:52:35,228 INFO  [    ome.tools.hibernate.ExtendedMetadata] (      main) Calculating ExtendedMetadata...
2014-05-20 15:52:36,696 INFO  [      o.s.scheduler.SchedulerFactoryBean] (      main) Starting Quartz Scheduler now
2014-05-20 15:52:37,085 INFO  [                ome.services.blitz.Entry] (      main) ome.fulltext now accepting connections.
2014-05-20 15:52:38,952 INFO  [       ome.security.basic.CurrentDetails] (2-thread-2) Adding log:INSERT,class ome.model.meta.Session,5869


If the Indexer functions, I'm afraid I'd have to say at this point that though it's certainly not normal, this might just be the state of things until we update Lucene. If you have any issues with search, though, don't hesitate to contact us again.

All the best,
~Josh

[stefanm]

Hi Josh
thanks for the answer. At the moment I can see no issue with that one, although I could imagine that it might beome an issue in a production environment. I'll keep an eye on it.

Best regards
Stefan