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

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

Folks-

I somehow missed the original mail.

Fidel-  thanks for doing this analysis.

Terry-  thanks for reviving the issue.

Will look into.

Steve

Terry Clark wrote:

>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
>>    
>>
>
>
>-------------------------------------------------------
>This SF.net email is sponsored by: SF.net Giveback Program.
>Does SourceForge.net help you be more productive?  Does it
>help you create better code?  SHARE THE LOVE, and help us help
>YOU!  Click Here: http://sourceforge.net/donate/
>_______________________________________________
>Gusdev-gusdev mailing list
>Gus...@li...
>https://lists.sourceforge.net/lists/listinfo/gusdev-gusdev
>  
>