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

[Terry C. <tw...@cs...>]

Greetings, 
I was watching with interest (and mulling over)
this performance report (posted 11-10-2003), 
but didn't see anything come through gusdev. 
Were there further findings?

Terry



On  0, Fidel Salas <fi...@vb...> 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