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

[Steve F. <st...@pc...>]

Folks-

I ran the SubmitRow plugin command mentioned below, with this dsn:

dbiDsn=dbi:Oracle:host=cbilbld.pcbi.upenn.edu;sid=cbilbld

It took less than a second.  So, whatever the problem is on Fidel's site 
is not reproducable here.  I will forward the dsn question to our SA 
folks.  Maybe they'll have a clue.

As far as the surprising profile:  much of it is explained by the call 
to GUS::ObjRelP::DbiDatabase::cacheTableNames which builds a cache of 
table names.  This is a bit of object layer overhead.  There are about 
900 tables in our GUS's TableInfo table. 

The real mystery is why this is in one profile but not in the other:

 11.2   0.060  0.055   2470   0.0000 0.0000  GUS::ObjRelP::DbiRow::getTable


Fidel-  what tool did you use for the profiling?

Steve



Fidel Salas wrote:

>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
>
>
>
>-------------------------------------------------------
>This SF.Net email sponsored by: ApacheCon 2003,
>16-19 November in Las Vegas. Learn firsthand the latest
>developments in Apache, PHP, Perl, XML, Java, MySQL,
>WebDAV, and more! http://www.apachecon.com/
>_______________________________________________
>Gusdev-gusdev mailing list
>Gus...@li...
>https://lists.sourceforge.net/lists/listinfo/gusdev-gusdev
>  
>