import speed

[cxallan]

Certainly a couple things we could do Juergen would be to start increasing the batch sizes with the new importer (details in the other thread) and make sure the longevity of those processes is correct and that we're not leaking memory on that size.

Regarding the indexer, what does bin/omero admin diagnostics have to say about it? Anything odd in var/log/Indexer-0.log?

[jmoore]

Hi Juergen,

Ok. That does look like your Indexer wasn't running, though I know I don't know why that might be. Could you attached var/log/Indexer-0.log and I'll take a look?

So, if I understand correctly indexer isn't running and you're now re-using sessions, correct? Has the contention on ome_nextval('session') gone away? What queries are you seeing logged during the heavy CPU usage?

On the subject of 5 calls on one session failing, do you have an error message you could give us?

Cheers,
~Josh

[helmerj]

Certainly a couple things we could do Juergen would be to start increasing the batch sizes with the new importer (details in the other thread) and make sure the longevity of those processes is correct and that we're not leaking memory on that size.

Regarding the indexer, what does bin/omero admin diagnostics have to say about it? Anything odd in var/log/Indexer-0.log?

I have tried a batch size of 250 using 4 workers and import time increases from 22 to 29 minutes with the DB server still at 100% CPU usage.

This the the retuns of the diagnostics call:

Code: Select all

helmerj@dhcppc2:~/bin/omero$ bin/omero admin diagnostics

================================================================================
OMERO Diagnostics 4.3.0-DEV
================================================================================
       
Commands:   java -version                  1.6.0     (/usr/bin/java)
Commands:   python -V                      2.6.6     (/usr/bin/python)
Commands:   icegridnode --version          3.3.1     (/usr/bin/icegridnode)
Commands:   icegridadmin --version         3.3.1     (/usr/bin/icegridadmin)
Commands:   psql --version                 9.0.2     (/opt/PostgreSQL/9.0/bin/psql)

Server:     icegridnode                    running
Server:     Blitz-0                        active (pid = 23994, enabled)
Server:     DropBox                        active (pid = 24006, enabled)
Server:     FileServer                     active (pid = 24010, enabled)
Server:     Indexer-0                      active (pid = 24016, enabled)
Server:     MonitorServer                  active (pid = 24008, enabled)
Server:     OMERO.Glacier2                 active (pid = 24019, enabled)
Server:     OMERO.IceStorm                 active (pid = 24014, enabled)
Server:     Processor-0                    active (pid = 24012, enabled)
Server:     Repository-1                   error: node `repo' couldn't be reached:
the node is not active
Server:     Tables-0                       inactive (disabled)
Server:     TestDropBox                    inactive (enabled)

Log dir:    /home/helmerj/bin/omero/var/log exists

Log files:  Blitz-0.log                    31.0 MB       errors=1    warnings=21 
Log files:  DropBox.log                    3.0 KB        errors=0    warnings=1   
Log files:  FileServer.log                 0.0 KB       
Log files:  Indexer-0.log                  1.0 MB        errors=21   warnings=74 
Log files:  MonitorServer.log              2.0 KB       
Log files:  OMEROweb.log                   4.0 KB        errors=10   warnings=0   
Log files:  Processor-0.log                2.0 KB       
Log files:  Tables-0.log                   n/a
Log files:  TestDropBox.log                n/a
Log files:  master.err                     11.0 KB     
Log files:  master.out                     0.0 KB       
Log files:  Total size                     33.14 MB

Parsing Blitz-0.log:[line:140] => Server restarted <=
Parsing Blitz-0.log:[line:683] => Server restarted <=

Environment:OMERO_HOME=(unset)             
Environment:OMERO_NODE=(unset)             
Environment:OMERO_MASTER=(unset)           
Environment:PATH=/home/helmerj/.rvm/gems/ruby-1.9.2-p136/bin:/home/helmerj/.rvm/gems/ruby-1.9.2-p136@global/bin:/home/helmerj/.rvm/rubies/ruby-1.9.2-p136/bin:/home/helmerj/.rvm/bin:/home/helmerj/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/home/helmerj/rails/metaxpress/bftools:/opt/PostgreSQL/9.0/bin
Environment:ICE_HOME=(unset)               
Environment:LD_LIBRARY_PATH=(unset)       
Environment:DYLD_LIBRARY_PATH=(unset)     

OMERO data dir: '/OMERO'   Exists? True   Is writable? True
OMERO.web status... DEVELOPMENT: You will have to check status by hand!



The log fiel lloks a lot like this, Error and Warning I cannot find:

Code: Select all

2011-02-03 19:05:01,382 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.setCurrentEventLog([6726,
PersistentEventLogLoader.v2.current_id])
2011-02-03 19:05:01,489 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.selectCurrentEventLog([Per
sistentEventLogLoader.v2.current_id])
2011-02-03 19:05:01,508 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.setCurrentEventLog([6727,
PersistentEventLogLoader.v2.current_id])
2011-02-03 19:05:01,624 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.selectCurrentEventLog([Per
sistentEventLogLoader.v2.current_id])
2011-02-03 19:05:01,643 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.setCurrentEventLog([6728,
PersistentEventLogLoader.v2.current_id])
2011-02-03 19:05:01,733 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.selectCurrentEventLog([Per
sistentEventLogLoader.v2.current_id])
2011-02-03 19:05:01,751 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.setCurrentEventLog([6729,
PersistentEventLogLoader.v2.current_id])
2011-02-03 19:05:01,850 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.selectCurrentEventLog([Per
sistentEventLogLoader.v2.current_id])
2011-02-03 19:05:01,869 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.setCurrentEventLog([6730,
PersistentEventLogLoader.v2.current_id])
2011-02-03 19:05:01,872 INFO  [      ome.services.fulltext.EventBacklog] (3-thread-5) Added to backlog:ome.model.core.Image:Id_285
2011-02-03 19:05:01,959 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.selectCurrentEventLog([Per
sistentEventLogLoader.v2.current_id])
2011-02-03 19:05:01,978 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.setCurrentEventLog([6732,
PersistentEventLogLoader.v2.current_id])
2011-02-03 19:05:02,085 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.selectCurrentEventLog([Per
sistentEventLogLoader.v2.current_id])
2011-02-03 19:05:02,104 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.setCurrentEventLog([6733,
PersistentEventLogLoader.v2.current_id])
2011-02-03 19:05:02,202 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.selectCurrentEventLog([Per
sistentEventLogLoader.v2.current_id])
2011-02-03 19:05:02,222 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.setCurrentEventLog([6734,
PersistentEventLogLoader.v2.current_id])
2011-02-03 19:05:02,312 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.selectCurrentEventLog([Per
sistentEventLogLoader.v2.current_id])
2011-02-03 19:05:02,331 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.setCurrentEventLog([6737,
PersistentEventLogLoader.v2.current_id])
2011-02-03 19:05:02,455 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.selectCurrentEventLog([Per
sistentEventLogLoader.v2.current_id])
2011-02-03 19:05:02,475 INFO  [                      ome.util.SqlAction] (3-thread-5) ome.util.actions.PostgresSqlAction@35087359.setCurrentEventLog([6738,
PersistentEventLogLoader.v2.current_id])
2011-02-03 19:05:02,580 INFO  [   ome.services.fulltext.FullTextIndexer] (3-thread-5) INDEXED 50 objects in 1 batch(es) [6560 ms.]
2011-02-03 19:05:02,594 WARN  [        ome.services.util.ServiceHandler] (3-thread-5) Method interface ome.services.util.Executor$Work.doWork invocation too
k 6575
2011-02-03 19:05:04,018 INFO  [                      ome.util.SqlAction] (3-thread-1) ome.util.actions.PostgresSqlAction@35087359.deferConstraints([])



Cheers Juergen

[helmerj]

Hi Juergen,

Ok. That does look like your Indexer wasn't running, though I know I don't know why that might be. Could you attached var/log/Indexer-0.log and I'll take a look?

So, if I understand correctly indexer isn't running and you're now re-using sessions, correct? Has the contention on ome_nextval('session') gone away? What queries are you seeing logged during the heavy CPU usage?

On the subject of 5 calls on one session failing, do you have an error message you could give us?

Cheers,
~Josh

Hi Josh.

Please find the Omero log file attached to this post. I have not been reusing sessions on my last import these log file have been generated with due to the fact that it was even slower than my initial approach starting each import session individually. It was not much slower but it definitely didn't speed things up. as I had to keep the session alive using omero session keepalive -f 500 it did complicate my system as that session would be alive indefinitely unless I killed it. So I abandoned that approach. I have it checked into a separate branch of my project so if you think you will be needing that feedback on this particular type of import, let me know and I can generate it for you.

I have created the postgres log using the auto_explain setting of my earlier post. Everything above 3ms is logged. Generated from a complete import of 1404 image files in 6 parallel import sessions.

too large to attach, please download it from here:

http://home.arcor.de/helmerj/postgresql ... 19.tar.bz2

Cheers Juergen

[jmoore]

Hi Juergen,

your Indexer-0 log looks healthy. Is it possible that you ran the above commands multiple times to have it already be shutdown? If not, this may be another mystery to look into, but for the moment it seems to be inactive. You can verify this, as Chris said, via "bin/omero admin diagnostics".

Please find the Omero log file attached to this post

Looking into it. Thanks.

I have not been reusing sessions on my last import these log file have been generated with due to the fact that it was even slower than my initial approach starting each import session individually. It was not much slower but it definitely didn't speed things up. as I had to keep the session alive using omero session keepalive -f 500 it did complicate my system as that session would be alive indefinitely unless I killed it. So I abandoned that approach. I have it checked into a separate branch of my project so if you think you will be needing that feedback on this particular type of import, let me know and I can generate it for you.

Hmmm,...you shouldn't need to use keepalive manually, since the importer itself will call that. If there is nothing to import (not that that's a problem at the moment), then the session will time out and clean itself up. I was just trying to come up with a short shell snippet to do what you needed but ran into ticket:4224. It may be necessary to provide you a short snippet of Python to do what you want. Roughly:

Code: Select all

  uuid = get_stored_uuid();
  try:
      check_uuid(uuid)
  else:
      uuid = get_new_uuid()
      store_uuid(uuid)
  return uuid     


There's a short window in there, where you could be using two sessions, but that shouldn't be problematic. Except for the fact that you couldn't use more than 4 sessions. Do you have any information about that?

I have created the postgres log using the auto_explain setting of my earlier post. Everything above 3ms is logged. Generated from a complete import of 1404 image files in 6 parallel import sessions.

I've attached some initial parsing of your logs. There doesn't seem to be too terribly much ome_nextval contention, so perhaps that's a red herring. The values seem evenly distributed across the rest of the application, i.e. inserts and selects, so perhaps we can try adding the attached indexes and compare the results.

As far as possible, we should try to isolate the tests:
* no OMERO indexer
* clean database
* run 1404 image in 6 parallel import sessions test
* save logs
* clean database
* add indexes
* run 1404 image in 6 parallel import sessions test
* save logs

Then we can compare the results. (Was the database clean before this run?)

One final question: do you have any logs from a single session'ed import? That might also be worthwhile to examine.

Thanks,
~J.

[jmoore]

I lied: more questions (maybe answered elsewhere):
* what version of PostgreSQL?
* what OS & version?
* and what specific OMERO download/checkout?

Cheers,
~Josh.

[helmerj]

Hi Juergen,

your Indexer-0 log looks healthy. Is it possible that you ran the above commands multiple times to have it already be shutdown? If not, this may be another mystery to look into, but for the moment it seems to be inactive. You can verify this, as Chris said, via "bin/omero admin diagnostics".

Please find the Omero log file attached to this post

Looking into it. Thanks.

I have not been reusing sessions on my last import these log file have been generated with due to the fact that it was even slower than my initial approach starting each import session individually. It was not much slower but it definitely didn't speed things up. as I had to keep the session alive using omero session keepalive -f 500 it did complicate my system as that session would be alive indefinitely unless I killed it. So I abandoned that approach. I have it checked into a separate branch of my project so if you think you will be needing that feedback on this particular type of import, let me know and I can generate it for you.

Hmmm,...you shouldn't need to use keepalive manually, since the importer itself will call that. If there is nothing to import (not that that's a problem at the moment), then the session will time out and clean itself up. I was just trying to come up with a short shell snippet to do what you needed but ran into ticket:4224. It may be necessary to provide you a short snippet of Python to do what you want. Roughly:

Code: Select all

  uuid = get_stored_uuid();
  try:
      check_uuid(uuid)
  else:
      uuid = get_new_uuid()
      store_uuid(uuid)
  return uuid     


There's a short window in there, where you could be using two sessions, but that shouldn't be problematic. Except for the fact that you couldn't use more than 4 sessions. Do you have any information about that?

I have created the postgres log using the auto_explain setting of my earlier post. Everything above 3ms is logged. Generated from a complete import of 1404 image files in 6 parallel import sessions.

I've attached some initial parsing of your logs. There doesn't seem to be too terribly much ome_nextval contention, so perhaps that's a red herring. The values seem evenly distributed across the rest of the application, i.e. inserts and selects, so perhaps we can try adding the attached indexes and compare the results.

As far as possible, we should try to isolate the tests:
* no OMERO indexer
* clean database
* run 1404 image in 6 parallel import sessions test
* save logs
* clean database
* add indexes
* run 1404 image in 6 parallel import sessions test
* save logs

Then we can compare the results. (Was the database clean before this run?)

One final question: do you have any logs from a single session'ed import? That might also be worthwhile to examine.

Thanks,
~J.

Hi!

the mystery of only being able to run 4 session in parallel was due to the fact that my postgres server had run out of hard disk space as I had forgotten to turn off the excessive logging using auto_explain. I had generated several GB of log files... So that is unrelated to omero itself.

First thing tomorrow I will generate a log file from a single import session which as I am using trunk should be possible now as well as doing the import using 6 workers with and without index.

BTW I have a script that will shut down Omero, clean out /OMERO, drop the database, create the DB and restore from a sql backup file start the server again. So I always have the same environment for my import tests. Doesn't mean of course that I can rule out that I once in a while forget to run that script...

I will post my results tomorrow.

Cheers and thanks for everyones help with this one. I really appreciate it.

Juergen

[helmerj]

I lied: more questions (maybe answered elsewhere):
* what version of PostgreSQL?
* what OS & version?
* and what specific OMERO download/checkout?

Cheers,
~Josh.

DB: Postgres is on version 9.0.2-1
OS: Ubuntu 64bit 10.10
Omero: trunk from yesterday afternoon (server and importer script do match)

Cheers Juergen

[helmerj]

Hi!

Ok, so I have run the import test using a non indexed and an indexed version of the Omero postgresql database. I have updated the postgresql server version to the latest 9.0.3.1.

This is what I have done for testing:

# WITHOUT Indexes

* restore Omero database
* shutdown postgres server
* enable auto_explain logging > 3ms
* delete old postgres log files
* start postgres server

* start job server
* start web interface for job server
* start 6 workers

* delete old omero log files
* start omero server (server 1024MB)

* start import (importer 512M)
duration: 18 minutes
postgres server at 20-96% CPU usage
* stop omero server
* get all log files


# WITH Indexes

* restore Omero database
* stop postgres server
* delete old log files
* start postgres server
* import create index sql file:
psql -U omero -W omero < create-indexes-1.sql

* delete old omero log files
* start omero server (server 1024MB)

* start import (importer 512M)
duration: 18:37 minutes
postgres server at 20-97% CPU usage
* stop omero server
* get all log files


The import using the indexed version of the database is within error margins as slow as the import into a database lacking the indexes.

Due to the size of log files (947Mb uncompressed), I have created another tar.bz2 archive (16Mb) which you guys can download here:

http://home.arcor.de/helmerj/omero_import_tests.tar.bz2

Cheers Juergen

[cxallan]

Hi Juergen,

That's sort of telling then. I'd like to make sure we're not barking up completely the wrong tree here. So, it would be good to have a look at the importer logs. PostgreSQL CPU usage is sort of expected, the INSERT volume is reasonable and a lot of that is going to be I/O wait rather than actual processing overhead. Looking at the server logs for the INSERTs they're consistently, in this rather high load test < 100ms per image. That's less than 2 of your 18+ minutes for the entire 1402 images.

Adding --debug to importer-cli or --debug=ALL to bin/omero import and then piping that to a file for each worker would be perfect.

-Chris