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

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

Fidel-

Thanks for the profiler info. 

About the multiple connections.  I agree that ideally it should be one 
connection.  But, there are some non-obvious issues around this, such as 
keeping independent transactions alive, that i don't fully understand.  
Two of the connections seem to be caused by ga and the rest by the 
object layer.   When we renovate the object layer i will pay attention 
to this.  But for now, besides the fact that it is suspicious and 
wasteful, is there any particular performance problem it is causing?

steve

Fidel Salas wrote:

>Steve,
>
>The profiler I used is Devel::DProf.  It is run like this:
>
>$ perl -d:DProf ga GUS::Common::Plugin::SubmitRow --tablename SRes::ExternalDatabase --attrlist external_database_id,name,lowercase_name --valuelist "200^^^GenBank(main)^^^genbank(main)"
>
>The profile output is written to a file called 'tmon.out.'  This file is interpreted
>by the program 'dprofpp.'
>
>>From your sample output below, it seems like it is the same profiler you used.
>
>There were two main points to my original post:
>
>1.  The dbiDsn issue.  I do not know what your oracle setup is at CBIL or what it is at
>other places where people are using GUS.  As I pointed out before, we connect to oracle
>from a client machine, that is, the oracle server and client are on different machines.
>Oracle has multiple ways of making connections (using environment variables or tnsname.ora)
>and I am not sure whether the server/client configuration impacts what the dsn must be in 
>order for things to work properly.
>
>2.  Connecting to the database (by SubmitRow) multiple times.  The reason I spoke to you
>(Steve) about how slow things were running has to do with the multiple connections to
>the database.  I probably would have ignored the issue (due to my limited time at VBI)
>if SubmitRow had been taking 3 minutes to run, but since it was taking 12 min. or more,
>it became a concern.  There is no reason for SubmitRow or any other plugin to have to 
>connect to the database more than once per invocation.  In the course of debugging the
>problem, I placed a few print statements in various places.  Here is the output after
>one invocation:
>
>	gus@tyler-lab:/home/apps/gus/debug$   ga GUS::Common::Plugin::SubmitRow --tablename SRes::ExternalDatabase --attrlist external_database_id,name,lowercase_name --valuelist "200^^^GenBank(main)^^^genbank(main)"
>	
>	Creating GusApplication Object
>	Reading properties from /home/apps/gus/gushome/config/GUS-PluginMgr.prop
>	
>	Created GusApplication object
>	
>	Entering GA parseAndRun
>	
>	Entering doMajorMode
>	
>	Entering doMajorMode_Run
>	
>	I am in GusApplication module.  Entering connect_to_database method
>	
>	PlugIn is:GUS::PluginMgr::GusApplication=HASH(0x813361c)
>	Reading properties from /home/apps/gus/.gus.properties
>	
>	My login is:GUSrw       core is:Core    dbiDsn is:dbi:Oracle:host=tuor.bioinformatics.vt.edu;sid=gusdev oraDfltRbs is:none
>	
>	Creating DbiDatabase
>	
>	Created DbiDatabase
>	
>	*************I am in DbiDbHandle and about to connect to database with following parameters:
>	        class: GUS::ObjRelP::DbiDbHandle        dsn: dbi:Oracle:host=tuor.bioinformatics.vt.edu;sid=gusdev
>	user: GUSrw     autoCommit:     *****************
>	
>	I am in GusApplication module.  Entering connect_to_database method
>	
>	PlugIn is:GUS::Common::Plugin::SubmitRow=HASH(0x8143fb4)
>	
>	My login is:GUSrw       core is:Core    dbiDsn is:dbi:Oracle:host=tuor.bioinformatics.vt.edu;sid=gusdev oraDfltRbs is:none
>	
>	Creating DbiDatabase
>	
>	Created DbiDatabase
>	
>	*************I am in DbiDbHandle and about to connect to database with following parameters:
>	        class: GUS::ObjRelP::DbiDbHandle        dsn: dbi:Oracle:host=tuor.bioinformatics.vt.edu;sid=gusdev
>	user: GUSrw     autoCommit:     *****************
>	
>	*************I am in DbiDbHandle and about to connect to database with following parameters:
>	        class: GUS::ObjRelP::DbiDbHandle        dsn: dbi:Oracle:host=tuor.bioinformatics.vt.edu;sid=gusdev
>	user: GUSrw     autoCommit: 1   *****************
>	
>	Creating DbiTable object
>	
>	Created DbiTable object
>	
>	*************I am in DbiDbHandle and about to connect to database with following parameters:
>	        class: GUS::ObjRelP::DbiDbHandle        dsn: dbi:Oracle:host=tuor.bioinformatics.vt.edu;sid=gusdev
>	user: GUSrw     autoCommit:     *****************
>	
>	Creating DbiTable object
>	
>	Created DbiTable object
>	
>	Entering openInvocation
>	
>	PlugIn is: GUS::Common::Plugin::SubmitRow=HASH(0x8143fb4)
>	
>	Creating DbiTable object
>	
>	Created DbiTable object
>	
>	Creating DbiTable object
>	
>	Created DbiTable object
>	
>	Creating DbiTable object
>	
>	Created DbiTable object
>	
>	Creating DbiTable object
>	
>	Created DbiTable object
>	Mon Nov 10 10:44:14 2003        ALGINVID        10
>	Mon Nov 10 10:44:14 2003        COMMIT  commit off
>	
>	Creating DbiTable object
>	
>	Created DbiTable object
>	Mon Nov 10 10:44:14 2003        Row updated
>	Mon Nov 10 10:44:14 2003        RESULT  Updated one row
>	gus@tyler-lab:/home/apps/gus/debug$
>
>Connecting to the database is expensive and it is, obviously, desirable to minimize
>the number of connections made.
>
>Fidel
>
>
>Steve Fischer <st...@pc...> writes:
>
>     > 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
>>>
>>>      
>>>
>
>
>
>-------------------------------------------------------
>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
>  
>