[Gusdev-gusdev] plugins speed difference due to dsn string

[Fidel S. <fi...@vb...>]

Hi folks!

This message is mostly with the hope that it may be of benefit
to those experiencing performance issues running plugins.  I also
ask two questions at the end related to implementation of the
plugins, specifically the SubmitRow plugin.

We had been experiencing performance issues when running plugins
and discovered that it was because of the dbiDsn string we were
using in the .gus.properties file.

First, let me describe our environment:
Our oracle is 9i with the server running on a big Sun machine
and the client running on linux, with following:
DBD::Oracle : 1.14
        DBI : 1.38
         OS : linux
       Perl : 5.008

The dbiDsn causing the slow performance follows the same form as
the one found in the gus.properties.sample in the GUS distribution
(in install directory).  In our case, that dbiDsn is:
dbiDsn=dbi:Oracle:host=tuor.bioinformatics.vt.edu;sid=gusdev

Following is the result of profiling the following call:
ga GUS::Common::Plugin::SubmitRow --tablename SRes::ExternalDatabase\
 --attrlist external_database_id,name,lowercase_name\
 --valuelist "200^^^GenBank(main)^^^genbank(main)"
 
Total Elapsed Time = 757.1146 Seconds
  User+System Time = 0.484621 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 12.3   0.060  0.208     11   0.0054 0.0189  GUS::PluginMgr::GusApplication::BEGIN
 8.25   0.040  0.040      4   0.0100 0.0100  DBD::Oracle::db::_login
 6.19   0.030  0.050      3   0.0100 0.0166  GUS::Model::Core::Algorithm_Row::BEGIN
 6.19   0.030  0.021    914   0.0000 0.0000  GUS::ObjRelP::DbiTable::getFullClassName
 6.19   0.030  0.039      5   0.0059 0.0078  GUS::ObjRelP::DbiDbHandle::BEGIN
 4.13   0.020  0.020      3   0.0067 0.0067  DynaLoader::dl_load_file
 4.13   0.020  0.020     37   0.0005 0.0005  DBI::_setup_handle
 4.13   0.020  0.020     28   0.0007 0.0007  DBI::st::execute
 4.13   0.020  0.020      6   0.0033 0.0033  GUS::Model::GusRow::BEGIN
 4.13   0.020  0.078     37   0.0005 0.0021  GUS::ObjRelP::DbiDatabase::getTable
 4.13   0.020  0.042     11   0.0018 0.0038  GUS::ObjRelP::DbiTable::BEGIN
 4.13   0.020  0.238      3   0.0067 0.0793  main::BEGIN
 4.13   0.020  0.069      4   0.0050 0.0173  GUS::ObjRelP::DbiDatabase::BEGIN
 3.71   0.018  0.026      1   0.0183 0.0264  GUS::ObjRelP::DbiDatabase::cacheTableNames
 2.06   0.010  0.008    870   0.0000 0.0000  DBI::st::fetchrow_array

When I change the dbiDsn string to:
dbiDsn=dbi:Oracle:gusdev.bioinformatics.vt.edu
profiling results in:

Total Elapsed Time = 1.104655 Seconds
  User+System Time = 0.534655 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 11.2   0.060  0.055   2470   0.0000 0.0000  GUS::ObjRelP::DbiRow::getTable
 7.48   0.040  0.050      3   0.0133 0.0166  GUS::Model::Core::Algorithm_Row::BEGIN
 7.48   0.040  0.208     11   0.0036 0.0189  GUS::PluginMgr::GusApplication::BEGIN
 5.61   0.030  0.030      4   0.0075 0.0075  DBD::Oracle::db::_login
 5.61   0.030  0.028    870   0.0000 0.0000  DBI::st::fetchrow_array
 5.61   0.030  0.084    951   0.0000 0.0001  GUS::ObjRelP::DbiDatabase::getFullTableClassName
 5.61   0.030  0.109     15   0.0020 0.0073  GUS::PluginMgr::Plugin::BEGIN
 5.61   0.030  0.118     37   0.0008 0.0032  GUS::ObjRelP::DbiDatabase::getTable
 5.61   0.030  0.039      5   0.0059 0.0078  GUS::ObjRelP::DbiDbHandle::BEGIN
 3.74   0.020  0.020      3   0.0067 0.0067  DynaLoader::dl_load_file
 3.74   0.020  0.238      3   0.0067 0.0793  main::BEGIN
 3.37   0.018  0.056      1   0.0183 0.0564  GUS::ObjRelP::DbiDatabase::cacheTableNames
 1.87   0.010  0.010     30   0.0003 0.0003  Exporter::import
 1.87   0.010  0.010     15   0.0007 0.0007  CBIL::Util::PropertySet::getProp
 1.87   0.010  0.010     37   0.0003 0.0003  DBI::st::TIEHASH

As you can see, that's a difference of > 12 minutes vs a little more than 1 second.

Question 1:
Now, looking at the profile results and walking over the code, I see that there are 
several connects made to the database (4 logins shown above) with the same parameters.
An obvious question, is why are several connections made?

Question 2:
Looking at the profiles above, does it make sense for such a simple submit row plugin
to make so many calls to GUS::ObjRelP::DbiRow::getTable, DBI::st::fetchrow_array,
GUS::ObjRelP::DbiDatabase::getFullTableClassName, and others?

Regards

Fidel