Lucene Merge Thread - Java memory error

[jmoore]

Hi Damir,

I've managed to reproduce with java version "1.7.0_51" so that can likely be ruled out. Thanks for all your help. We'll keep you posted: https://trac.openmicroscopy.org.uk/ome/ticket/12279

~Josh.

[dsudar]

Thanks Josh, glad it's not just me
Let me know if I can run any tests or so. We're very motivated to have this fixed since we plan to use Tags (based on the webtagging and csvtagging approaches by the partners) to annotate a very large screen that is underway. And without indexing the search function does not work.
- Damir

[dsudar]

Hi Josh,

I was happy to see that you found what was causing the OOMs during Indexing and that the fix was part of the 5.0.2 release today. I immediately installed 5.0.2 on one of my systems and indeed so far no OOMs but I do see quite a few ERRORs in Indexer-0.log.
Here the first section of that log:

omero@quid:~/OMERO.server/var/log$ more Indexer-0.log
2014-05-28 11:02:32,374 INFO [ ome.services.blitz.Entry] ( main) Waiting 10000 ms on startup
2014-05-28 11:02:42,391 INFO [ ome.services.blitz.Entry] ( main) Creating ome.fulltext. Please wait...
2014-05-28 11:02:43,943 INFO [ ome.services.util.DBUserCheck] ( main) User root.id = 0
2014-05-28 11:02:43,945 INFO [ ome.services.util.DBUserCheck] ( main) User guest.id = 1
2014-05-28 11:02:43,945 INFO [ ome.services.util.DBUserCheck] ( main) Group system.id = 0
2014-05-28 11:02:43,945 INFO [ ome.services.util.DBUserCheck] ( main) Group user.id = 1
2014-05-28 11:02:43,945 INFO [ ome.services.util.DBUserCheck] ( main) Group guest.id = 2
2014-05-28 11:02:43,948 INFO [ ome.services.util.JvmSettingsCheck] ( main) Java version: 1.7.0_11; Linux; amd64; 3.2.0-43-generic
2014-05-28 11:02:43,949 INFO [ ome.services.util.JvmSettingsCheck] ( main) Max Memory (MB): = 910
2014-05-28 11:02:43,950 INFO [ ome.services.util.JvmSettingsCheck] ( main) OS Memory (MB): = 60389
2014-05-28 11:02:43,950 INFO [ ome.services.util.JvmSettingsCheck] ( main) Processors: = 16
2014-05-28 11:02:43,985 INFO [.s.ShutdownSafeEhcacheManagerFactoryBean] ( main) Initializing EHCache CacheManager
2014-05-28 11:02:46,393 INFO [ ome.services.fulltext.FullTextAnalyzer] ( main) Initialized FullTextAnalyzer
2014-05-28 11:02:49,449 INFO [ ome.services.fulltext.FullTextThread] ( main) Initializing Full-Text Indexer
2014-05-28 11:02:49,764 INFO [ ome.services.db.DatabaseIdentity] ( main) Using LSID format: urn:lsid:export.openmicroscopy.org:%s
:27822266-e5fc-4003-8b01-2c3f102c2e79_%s%s
2014-05-28 11:02:49,936 INFO [ ome.tools.hibernate.ExtendedMetadata] ( main) Calculating ExtendedMetadata...
2014-05-28 11:02:50,071 INFO [ o.s.scheduler.SchedulerFactoryBean] ( main) Starting Quartz Scheduler now
2014-05-28 11:02:50,147 INFO [ ome.services.blitz.Entry] ( main) ome.fulltext now accepting connections.
2014-05-28 11:02:50,380 INFO [ ome.security.basic.CurrentDetails] (2-thread-2) Adding log:INSERT,class ome.model.meta.Session,9065
2014-05-28 11:03:41,862 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-2) INDEXED 50 objects in 1 batch(es) [51402 ms.]
2014-05-28 11:03:41,865 ERROR [ ome.services.util.ServiceHandler] (2-thread-2) Method interface ome.services.util.Executor$Work.doWork
invocation took 51433
2014-05-28 11:04:32,672 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-3) INDEXED 50 objects in 1 batch(es) [50782 ms.]
2014-05-28 11:04:32,675 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork
invocation took 50793
2014-05-28 11:05:23,285 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-4) INDEXED 50 objects in 1 batch(es) [50578 ms.]
2014-05-28 11:05:23,287 ERROR [ ome.services.util.ServiceHandler] (2-thread-4) Method interface ome.services.util.Executor$Work.doWork
invocation took 50592
2014-05-28 11:06:13,813 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-1) INDEXED 50 objects in 1 batch(es) [50498 ms.]
2014-05-28 11:06:13,816 ERROR [ ome.services.util.ServiceHandler] (2-thread-1) Method interface ome.services.util.Executor$Work.doWork
invocation took 50509
2014-05-28 11:07:04,310 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-2) INDEXED 50 objects in 1 batch(es) [50472 ms.]
2014-05-28 11:07:04,313 ERROR [ ome.services.util.ServiceHandler] (2-thread-2) Method interface ome.services.util.Executor$Work.doWork
invocation took 50481
2014-05-28 11:07:54,828 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-5) INDEXED 50 objects in 1 batch(es) [50495 ms.]
2014-05-28 11:07:54,830 ERROR [ ome.services.util.ServiceHandler] (2-thread-5) Method interface ome.services.util.Executor$Work.doWork
invocation took 50501
2014-05-28 11:08:45,314 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-4) INDEXED 50 objects in 1 batch(es) [50458 ms.]
2014-05-28 11:08:45,316 ERROR [ ome.services.util.ServiceHandler] (2-thread-4) Method interface ome.services.util.Executor$Work.doWork
invocation took 50466
2014-05-28 11:09:35,791 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-1) INDEXED 50 objects in 1 batch(es) [50452 ms.]
2014-05-28 11:09:35,794 ERROR [ ome.services.util.ServiceHandler] (2-thread-1) Method interface ome.services.util.Executor$Work.doWork
invocation took 50461
2014-05-28 11:10:26,293 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-2) INDEXED 50 objects in 1 batch(es) [50474 ms.]
2014-05-28 11:10:26,295 ERROR [ ome.services.util.ServiceHandler] (2-thread-2) Method interface ome.services.util.Executor$Work.doWork
invocation took 50480
2014-05-28 11:11:16,744 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-5) INDEXED 50 objects in 1 batch(es) [50428 ms.]
2014-05-28 11:11:16,746 ERROR [ ome.services.util.ServiceHandler] (2-thread-5) Method interface ome.services.util.Executor$Work.doWork
invocation took 50434
2014-05-28 11:12:07,184 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-3) INDEXED 50 objects in 1 batch(es) [50415 ms.]
2014-05-28 11:12:07,186 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork
invocation took 50420
2014-05-28 11:12:57,632 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-1) INDEXED 50 objects in 1 batch(es) [50425 ms.]
2014-05-28 11:12:57,634 ERROR [ ome.services.util.ServiceHandler] (2-thread-1) Method interface ome.services.util.Executor$Work.doWork
invocation took 50430
2014-05-28 11:13:48,057 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-4) INDEXED 50 objects in 1 batch(es) [50403 ms.]
2014-05-28 11:13:48,060 ERROR [ ome.services.util.ServiceHandler] (2-thread-4) Method interface ome.services.util.Executor$Work.doWork
invocation took 50411
2014-05-28 11:14:38,481 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-5) INDEXED 50 objects in 1 batch(es) [50398 ms.]
2014-05-28 11:14:38,483 ERROR [ ome.services.util.ServiceHandler] (2-thread-5) Method interface ome.services.util.Executor$Work.doWork
invocation took 50403
2014-05-28 11:15:28,900 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-3) INDEXED 50 objects in 1 batch(es) [50393 ms.]
2014-05-28 11:15:28,903 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork
invocation took 50400
2014-05-28 11:16:19,334 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-1) INDEXED 50 objects in 1 batch(es) [50410 ms.]
2014-05-28 11:16:19,336 ERROR [ ome.services.util.ServiceHandler] (2-thread-1) Method interface ome.services.util.Executor$Work.doWork
invocation took 50415
2014-05-28 11:17:09,759 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-4) INDEXED 50 objects in 1 batch(es) [50397 ms.]
2014-05-28 11:17:09,761 ERROR [ ome.services.util.ServiceHandler] (2-thread-4) Method interface ome.services.util.Executor$Work.doWork
invocation took 50403
2014-05-28 11:18:00,168 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-2) INDEXED 50 objects in 1 batch(es) [50391 ms.]
2014-05-28 11:18:00,170 ERROR [ ome.services.util.ServiceHandler] (2-thread-2) Method interface ome.services.util.Executor$Work.doWork
invocation took 50397
2014-05-28 11:18:50,602 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-3) INDEXED 50 objects in 1 batch(es) [50411 ms.]
2014-05-28 11:18:50,604 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork
invocation took 50417
... and so on and on ....

Is this worrisome? The time taken does not seem to trend upwards as it did before.

Thanks,
- Damir

[jmoore]

Hi Damir,

Is this worrisome?

Not necessarily.

The time taken does not seem to trend upwards as it did before.

If the times are stable, then I'd give it a chance to catch its breath. The previous OutOfMemory exceptions likely led to quite a backlog. Keep an eye on it and do let us know whether it successfully catches up or not. Thanks for the quick testing!

~Josh

[dsudar]

Thanks Josh. Indeed, time taken is stable at just over 50000ms and chugging along. Most searches still give no results but I'll give it a day or so to catch up.
- Damir

[dsudar]

Hi Josh,

It has now been running since Wednesday and the Indexer-0.log still shows those >50000ms ERRORS every minute. Here are the last few:

2014-06-01 13:15:42,615 ERROR [ ome.services.util.ServiceHandler] (2-thread-2) Method interface ome.services.util.Executor$Work.doWork invocation took 50460
2014-06-01 13:16:33,208 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-5) INDEXED 50 objects in 1 batch(es) [50576 ms.]
2014-06-01 13:16:33,210 ERROR [ ome.services.util.ServiceHandler] (2-thread-5) Method interface ome.services.util.Executor$Work.doWork invocation took 50580
2014-06-01 13:17:23,750 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-3) INDEXED 50 objects in 1 batch(es) [50519 ms.]
2014-06-01 13:17:23,751 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork invocation took 50523

I wouldn't be too worried about the above except that my searches still give mixed or no results. Maybe I am misunderstanding how searches should work so let me explain what I'm trying to do. We're trying to use tagging to annotate a large screen experiment where each image (actually all images in a well) is tagged with the gene that is being expressed and/or the drug that was applied to that well. When I look in the Tags panel on the left in Insight, all my tags are there and for each tag I select I get the images tagged with that tag. However, when I do a search on a tag name, I get nothing. My goal is to use this functionality to do searches on multiple tags e.g. give me all images tagged with drug "tagA", expressing gene "tagX", and showing proliferation stain "tagStainZ".

Thanks,
- Damir

[jmoore]

Hi Josh,

Hi Damir,

It has now been running since Wednesday and the Indexer-0.log still shows those >50000ms ERRORS every minute. Here are the last few...

We ran into the same situation on one of our servers which had been OOM'ing. Running the following SQL should tell you how caught up the indexer is:

Code: Select all

psql omero -c "select 'At ' || current_timestamp(0) || ', Percent indexed: ' || trunc(((select count(*) from eventlog el, configuration c where el.id < cast(c.value as int) and (c.name like 'PersistentEventLogLoader%')) * 1.0) / (select count(*) from eventlog) * 100, 3) || '%';"


For us:

Code: Select all

                      ?column?                       
-----------------------------------------------------
At 2014-06-02 10:10:24+01, Percent indexed: 16.222%
(1 row)


I wouldn't be too worried about the above except that my searches still give mixed or no results...

Without knowing in which order things were done (and possibly even then), figuring out what will be returned when the indexer is so far behind is incredibly difficult. If you'd prefer to do an offline, bulk reindex, you can follow these instructions. But it will also take some time.

Cheers,
~Josh

[dsudar]

Hi Josh,
Thanks for being so patient with me.

The sql query returned:

?column?
-----------------------------------------------------
At 2014-06-02 12:38:52-07, Percent indexed: 99.836%
(1 row)

So that looked very promising. Alas, pretty much any of my searches still return nothing.

And looking at Indexer-0.log, at around 4:30am this morning, besides the >50000ms errors every minute, a new event popped up in the log:

2014-06-02 04:24:43,123 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-3) INDEXED 50 objects in 1 batch(es) [50505 ms.]
2014-06-02 04:24:43,125 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork invocation took 50510
2014-06-02 04:25:33,756 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-4) INDEXED 50 objects in 1 batch(es) [50611 ms.]
2014-06-02 04:25:33,758 ERROR [ ome.services.util.ServiceHandler] (2-thread-4) Method interface ome.services.util.Executor$Work.doWork invocation took 50616
2014-06-02 04:26:13,198 WARN [ ome.services.fulltext.FullTextIndexer] (2-thread-5) Null returned! Purging since cannot index ome.model.core.Image:Id_5 for ome.model.meta.EventLog:Id_1478104
2014-06-02 04:26:14,200 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-5) Purged: class ome.model.core.Image:Id_5
2014-06-02 04:26:14,215 WARN [ ome.services.fulltext.FullTextIndexer] (2-thread-5) Null returned! Purging since cannot index ome.model.core.Image:Id_7 for ome.model.meta.EventLog:Id_1478105
2014-06-02 04:26:15,216 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-5) Purged: class ome.model.core.Image:Id_7
2014-06-02 04:26:15,232 WARN [ ome.services.fulltext.FullTextIndexer] (2-thread-5) Null returned! Purging since cannot index ome.model.core.Image:Id_8 for ome.model.meta.EventLog:Id_1478106
2014-06-02 04:26:16,232 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-5) Purged: class ome.model.core.Image:Id_8
2014-06-02 04:26:16,243 WARN [ ome.services.fulltext.FullTextIndexer] (2-thread-5) Null returned! Purging since cannot index ome.model.core.Image:Id_17 for ome.model.meta.EventLog:Id_1478107
2014-06-02 04:26:17,244 INFO [ ome.services.fulltext.FullTextIndexer] (2-thread-5) Purged: class ome.model.core.Image:Id_17

and so on for every "class ome.model.<etc>:Id_*"
And also tons of other "Purged" INFOs, and "Already in backlog" INFOs,

I haven't tried doing the whole offline reindex option. Is all the above maybe an indication that the index is quite messed up and that reindexing would indeed be the best thing to do?

Thanks,
- Damir

[jmoore]

The PURGED items means you are getting to deleted items, which is fine. Having items in the backlog is also ok. However, if your index really is within a couple percent of being finished, then most likely you are going to need to perform a full re-index, deleting all of /OMERO/FullText.

And thanks for your patience as well!
~Josh.