Re: DBD::Pg, DBD::Oracle and others are slow with threads due to DBIS

On 15/03/12 21:18, Tim Bunce wrote:
> On Thu, Mar 15, 2012 at 10:33:43AM +0000, Martin J. Evans wrote:
>>
>> Argh, DBD::Oracle tracing is a mess wrt to this discussion:
>>
>> ocitrace.h:
>>
>> #define DBD_OCI_TRACEON	(DBIS->debug>= 6 || dbd_verbose>=6)
>> #define DBD_OCI_TRACEFP	(DBILOGFP)
>>
>> #define OCIServerRelease_log_stat(sc,errhp,b,bl,ht,ver,stat)\
>> 	stat =OCIServerRelease(sc,errhp,b,bl,ht,ver);\
>> 	(DBD_OCI_TRACEON) \
>> 			? PerlIO_printf(DBD_OCI_TRACEFP,\
>> 				 "%sOCIServerRelease(%p)=%s\n",\
>> 				 OciTp, sc,oci_status_name(stat)),stat \
>> 	: stat
>>
>> Every single OCI call uses DBD_OCI_TRACEON which in turn uses
>> DBIS->debug and non have a imp_xxx handle so this is a very large
>> change. Ensuring the code at each point an OCI call is made has an
>> imp_xxh and getting the right one is going to be an awful job
>> especially when a load of funcs in oci8.c don't even have a handle. I
>> don't see an easy way to automate this change so I'm not sure I've got
>> the stomach for this. If I do this will I really "see" some speed up
>> as it is a lot of work.
>
> Maybe just do the OCI* function calls that are used in the main fetch
> code path, i.e., dbd_st_fetch. Add an imp parameter
>
> -#define OCIServerRelease_log_stat(sc,errhp,b,bl,ht,ver,stat)
> +#define OCIServerRelease_log_stat(imp,sc,errhp,b,bl,ht,ver,stat)
>
>    	stat =OCIServerRelease(sc,errhp,b,bl,ht,ver);\
> ! 	(DBIc_TRACE(imp,...)) \
> ! 			? PerlIO_printf(DBIc_LOGPIO(imp),\
>    				 "%sOCIServerRelease(%p)=%s\n",\
>    				 OciTp, sc,oci_status_name(stat)),stat \
>    	: stat
>
> Tim.

Last night I finished changing DBD::Oracle to eradicate all DBIS usage. I ran into quite a few problems along the way but all DBIS usage is gone except for a few calls in functions passed to Oracle. I've not moved to DBIc_TRACE yet but when I get time I will do that and add the new DBD trace flag as well (hopefully to replace ora_verbose which seems pointless to me simply adding yet another test when no-one really uses it other than as on/off).

As a side note there is a phenomenal amount of tracing in DBD::Oracle which it would be nice to noop the whole lot out for people who don't want the code continually testing whether tracing is on - me.

A quick benchmark:

use DBI;
use strict;
use warnings;
use Benchmark;

my $h = DBI->connect("dbi:Oracle:host=xxx.easysoft.local;sid=test",
                      "xxx", "xxx", {RaiseError => 1});
if (@ARGV) {
     eval {
         $h->do(q/drop table dbis/);
     };
     setup($h);
}

timethese(10, {
     'read' => sub {readit($h)},
     'readperrow' => sub {readitperrow($h)}});

#readit($h);

sub setup {
     $h->do(q/create table dbis (a int, b varchar(100))/);
     $h->begin_work;
     my $s = $h->prepare(q/insert into dbis values(?,?)/);
     foreach (1..1000000) {
         $s->execute($_, "the quick brown fox jumps over the lazy dog");
     }
     $h->commit;
     print "Table populated\n";
}

sub readit {
     my $h = shift;
     my $s = $h->prepare(q/select * from dbis/);
     $s->execute;
     my $d = $s->fetchall_arrayref;
     print "Read ", scalar(@$d), " rows\n";
}
sub readitperrow {
     my $h = shift;
     my $s = $h->prepare(q/select * from dbis/);
     $s->execute;
     my $rows = 0;
     while(my $d = $s->fetchrow_arrayref) {
         $rows++;
     }
     print "Read $rows rows\n";
}

perl 5.14.2

Perl without threads:
  1.42:
   read: 83 wallclock secs (37.55 usr +  5.77 sys = 43.32 CPU) @  0.23/s (n=10)
   readperrow 85 wallclock secs (39.53 usr +  4.98 sys = 44.51 CPU) @  0.22/s (n=10)

  subversion trunk:
   read: 85 wallclock secs (40.23 usr +  6.22 sys = 46.45 CPU) @  0.22/s (n=10)
   readperrow: 85 wallclock secs (40.06 usr +  5.32 sys = 45.38 CPU) @  0.22/s (n=10)

Perl with threads:
  1.42
   read: 128 wallclock secs (86.11 usr +  5.41 sys = 91.52 CPU) @  0.11/s (n=10)
   readperrow: 137 wallclock secs (95.33 usr +  4.86 sys = 100.19 CPU) @  0.10/s (n=10)

subversion trunk:
   read: 94 wallclock secs (52.55 usr +  5.68 sys = 58.23 CPU) @  0.17/s (n=10)
   readperrow: 104 wallclock secs (62.74 usr +  5.06 sys = 67.80 CPU) @  0.15/s (n=10)

which only goes to remind me why I don't use a Perl with threads but if you do, DBD::Oracle should be a fair bit faster now.

BTW, this change is literally thousands of lines of code so if you depend on DBD::Oracle I'd get a copy of the subversion trunk and try it.

Martin
-- 
Martin J. Evans
Easysoft Limited
http://www.easysoft.com