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

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 422-6466

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
>>