[CDBI] Make name_lc go fast. Benchmarks

Brad Bowman list at bereft.net
Tue Apr 10 03:29:17 BST 2007


Michael G Schwern wrote:
> FWIW name_lc() often pops up high in my profiles.  Its called as part of the
> column stringification override which is called very, very often.  So yes, it
> would be nice to optimize it away.
> 
> There's probably no harm in simply changing the stringification sub to be simply:
> 
>     sub { lc shift->name };
> 
> That would remove a layer of method calls.
> 
> I can't think of why anyone would want to override the method which lower
> cases the name.

I used the Rose DB benchmark script to see if this change actually makes a
difference.  It seems to make a small one.

cd /home/bsb/Rose-DB-Object-0.763/t/benchmarks

repeated runs, editing /usr/share/perl5/Class/DBI/Column.pm:

./bench.pl --no-rdbo --database mysql --time --cmp Class::DBI \
   --skip-intro --no-readline

It seemed difficult to use the bench.pl --compare option with two
versions of Class::DBI, that would have been preferable.  Instead
I collected the time output and looked at the output of
compare_bench.pl (attached) output shown below.

This compares vanilla cdbi with the sub { lc shift->name } suggestion
above.  The numbers shown are the number of operations per second,
for example, the first is the number of "Simple insert 1"s per second.
(cdbi.vanilla attached shows sample bench.pl output)

The percentage differences are relative to the previous in the
list, not all that useful in this setup.

===========
./compare_bench.pl cdbi.vanilla cdbi.vanilla2 cdbi.hacked.lc_shift 
cdbi.hacked.lc_shift2

Simple: insert 1
925.93, 884.96 (-4.6%), 1000.00 (+12%), 909.09 (-10%)
sorted vanilla2 884.96, lc_shift2 909.09, vanilla 925.93, lc_shift 1000.00

Complex: insert 1
869.57, 943.40 (+7.8%), 980.39 (+3.8%), 892.86 (-9.8%)
sorted vanilla 869.57, lc_shift2 892.86, vanilla2 943.40, lc_shift 980.39

Simple: insert 2
518.13, 515.46 (-0.52%), 540.54 (+4.6%), 526.32 (-2.7%)
sorted vanilla2 515.46, vanilla 518.13, lc_shift2 526.32, lc_shift 540.54

Complex: insert 2
571.43, 568.18 (-0.57%), 584.80 (+2.8%), 598.80 (+2.3%)
sorted vanilla2 568.18, vanilla 571.43, lc_shift 584.80, lc_shift2 598.80

Simple: accessor 1
1.41, 1.41 (+0%), 1.52 (+7.2%), 1.52 (+0%)
sorted vanilla 1.41, vanilla2 1.41, lc_shift 1.52, lc_shift2 1.52

Complex: accessor 1
1.41, 1.43 (+1.4%), 1.50 (+4.7%), 1.50 (+0%)
sorted vanilla 1.41, vanilla2 1.43, lc_shift 1.50, lc_shift2 1.50

Simple: accessor 2
0.32, 0.33 (+3%), 0.34 (+2.9%), 0.34 (+0%)
sorted vanilla 0.32, vanilla2 0.33, lc_shift 0.34, lc_shift2 0.34

Complex: accessor 2
0.32, 0.32 (+0%), 0.34 (+5.9%), 0.35 (+2.9%)
sorted vanilla 0.32, vanilla2 0.32, lc_shift 0.34, lc_shift2 0.35

Simple: load 1
925.93, 934.58 (+0.93%), 1063.83 (+12%), 1030.93 (-3.2%)
sorted vanilla 925.93, vanilla2 934.58, lc_shift2 1030.93, lc_shift 1063.83

Simple: load 2
609.76, 632.91 (+3.7%), 645.16 (+1.9%), 680.27 (+5.2%)
sorted vanilla 609.76, vanilla2 632.91, lc_shift 645.16, lc_shift2 680.27

Complex: load 2
436.68, 442.48 (+1.3%), 460.83 (+4%), 467.29 (+1.4%)
sorted vanilla 436.68, vanilla2 442.48, lc_shift 460.83, lc_shift2 467.29

Simple: load 3
452.49, 427.35 (-5.9%), 467.29 (+8.5%), 448.43 (-4.2%)
sorted vanilla2 427.35, lc_shift2 448.43, vanilla 452.49, lc_shift 467.29

Complex: load 3
343.64, 342.47 (-0.34%), 344.83 (+0.68%), 348.43 (+1%)
sorted vanilla2 342.47, vanilla 343.64, lc_shift 344.83, lc_shift2 348.43

Simple: update 1
483.09, 462.96 (-4.3%), 478.47 (+3.2%), 467.29 (-2.4%)
sorted vanilla2 462.96, lc_shift2 467.29, lc_shift 478.47, vanilla 483.09

Simple: update 2
381.68, 366.30 (-4.2%), 377.36 (+2.9%), 400.00 (+5.7%)
sorted vanilla2 366.30, lc_shift 377.36, vanilla 381.68, lc_shift2 400.00

Complex: update 2
228.31, 230.41 (+0.91%), 239.81 (+3.9%), 233.64 (-2.6%)
sorted vanilla 228.31, vanilla2 230.41, lc_shift2 233.64, lc_shift 239.81

Simple: search 1
82.08, 81.01 (-1.3%), 81.46 (+0.55%), 82.82 (+1.6%)
sorted vanilla2 81.01, lc_shift 81.46, vanilla 82.08, lc_shift2 82.82

Simple: search 2
29.48, 29.70 (+0.74%), 29.80 (+0.34%), 30.74 (+3.1%)
sorted vanilla 29.48, vanilla2 29.70, lc_shift 29.80, lc_shift2 30.74

Complex: search 2
5.28, 5.41 (+2.4%), 5.48 (+1.3%), 5.56 (+1.4%)
sorted vanilla 5.28, vanilla2 5.41, lc_shift 5.48, lc_shift2 5.56

Simple: search with 1-to-1 sub-objects
23.40, 23.38 (-0.086%), 24.11 (+3%), 23.93 (-0.75%)
sorted vanilla2 23.38, vanilla 23.40, lc_shift2 23.93, lc_shift 24.11

Complex: search with 1-to-1 sub-objects
5.12, 5.12 (+0%), 5.23 (+2.1%), 5.13 (-1.9%)
sorted vanilla 5.12, vanilla2 5.12, lc_shift2 5.13, lc_shift 5.23

Simple: search with 1-to-1 and 1-to-n sub-objects
1.12, 1.13 (+0.88%), 1.13 (+0%), 1.12 (-0.89%)
sorted vanilla 1.12, lc_shift2 1.12, vanilla2 1.13, lc_shift 1.13

Complex: search with 1-to-1 and 1-to-n sub-objects
0.77, 0.78 (+1.3%), 0.77 (-1.3%), 0.78 (+1.3%)
sorted vanilla 0.77, lc_shift 0.77, vanilla2 0.78, lc_shift2 0.78

Simple: iterate 1
61.95, 61.02 (-1.5%), 61.12 (+0.16%), 62.41 (+2.1%)
sorted vanilla2 61.02, lc_shift 61.12, vanilla 61.95, lc_shift2 62.41

Complex: iterate 1
60.20, 61.00 (+1.3%), 58.87 (-3.6%), 61.86 (+4.8%)
sorted lc_shift 58.87, vanilla 60.20, vanilla2 61.00, lc_shift2 61.86

Simple: iterate 2
25.58, 25.63 (+0.2%), 25.63 (+0%), 25.76 (+0.5%)
sorted vanilla 25.58, vanilla2 25.63, lc_shift 25.63, lc_shift2 25.76

Complex: iterate 2
5.21, 5.20 (-0.19%), 5.27 (+1.3%), 5.14 (-2.5%)
sorted lc_shift2 5.14, vanilla2 5.20, vanilla 5.21, lc_shift 5.27

Simple: iterate 3
7.63, 7.81 (+2.3%), 7.77 (-0.51%), 8.18 (+5%)
sorted vanilla 7.63, lc_shift 7.77, vanilla2 7.81, lc_shift2 8.18

Complex: iterate 3
3.41, 3.43 (+0.58%), 3.43 (+0%), 3.51 (+2.3%)
sorted vanilla 3.41, vanilla2 3.43, lc_shift 3.43, lc_shift2 3.51

Simple: delete
515.46, 529.10 (+2.6%), 540.54 (+2.1%), 523.56 (-3.2%)
sorted vanilla 515.46, lc_shift2 523.56, vanilla2 529.10, lc_shift 540.54

Complex: delete
299.40, 301.20 (+0.6%), 292.40 (-3%), 297.62 (+1.8%)
sorted lc_shift 292.40, lc_shift2 297.62, vanilla 299.40, vanilla2 301.20

Simple: insert or update
478.47, 465.12 (-2.9%), 478.47 (+2.8%), 483.09 (+0.96%)
sorted vanilla2 465.12, vanilla 478.47, lc_shift 478.47, lc_shift2 483.09
===============

It looks like there is a small improvement on some things and just noise
in others.  I tried a few other variations, using $_[0] and even not doing
the lc but found it hard to discern an improvement relative to Schwern's.

I wonder if it's worth making this change just to stop the profiling
output from looking so weird with name_lc featuring so prominently.
In the non-overloaded version, it's probably still high up there
but bundled into a less troubling __ANON__

Even if this isn't changed it's nice to have tools to benchmark,

Brad

-- 
  When one's own attitude on courage is fixed in his heart, and when his
  resolution is devoid of doubt, then when the time comes he will of
  necessity be able to choose the right move. -- Hagakure
-------------- next part --------------
A non-text attachment was scrubbed...
Name: compare_bench.pl
Type: application/x-perl
Size: 1031 bytes
Desc: not available
Url : http://lists.digitalcraftsmen.net/pipermail/classdbi/attachments/20070410/835565a0/compare_bench.bin
-------------- next part --------------
./compare_bench.pl cdbi.vanilla cdbi.vanilla2 cdbi.hacked.lc_shift cdbi.hacked.lc_shift2

Simple: insert 1
925.93, 884.96 (-4.6%), 1000.00 (+12%), 909.09 (-10%)
sorted vanilla2 884.96, lc_shift2 909.09, vanilla 925.93, lc_shift 1000.00

Complex: insert 1
869.57, 943.40 (+7.8%), 980.39 (+3.8%), 892.86 (-9.8%)
sorted vanilla 869.57, lc_shift2 892.86, vanilla2 943.40, lc_shift 980.39

Simple: insert 2
518.13, 515.46 (-0.52%), 540.54 (+4.6%), 526.32 (-2.7%)
sorted vanilla2 515.46, vanilla 518.13, lc_shift2 526.32, lc_shift 540.54

Complex: insert 2
571.43, 568.18 (-0.57%), 584.80 (+2.8%), 598.80 (+2.3%)
sorted vanilla2 568.18, vanilla 571.43, lc_shift 584.80, lc_shift2 598.80

Simple: accessor 1
1.41, 1.41 (+0%), 1.52 (+7.2%), 1.52 (+0%)
sorted vanilla 1.41, vanilla2 1.41, lc_shift 1.52, lc_shift2 1.52

Complex: accessor 1
1.41, 1.43 (+1.4%), 1.50 (+4.7%), 1.50 (+0%)
sorted vanilla 1.41, vanilla2 1.43, lc_shift 1.50, lc_shift2 1.50

Simple: accessor 2
0.32, 0.33 (+3%), 0.34 (+2.9%), 0.34 (+0%)
sorted vanilla 0.32, vanilla2 0.33, lc_shift 0.34, lc_shift2 0.34

Complex: accessor 2
0.32, 0.32 (+0%), 0.34 (+5.9%), 0.35 (+2.9%)
sorted vanilla 0.32, vanilla2 0.32, lc_shift 0.34, lc_shift2 0.35

Simple: load 1
925.93, 934.58 (+0.93%), 1063.83 (+12%), 1030.93 (-3.2%)
sorted vanilla 925.93, vanilla2 934.58, lc_shift2 1030.93, lc_shift 1063.83

Simple: load 2
609.76, 632.91 (+3.7%), 645.16 (+1.9%), 680.27 (+5.2%)
sorted vanilla 609.76, vanilla2 632.91, lc_shift 645.16, lc_shift2 680.27

Complex: load 2
436.68, 442.48 (+1.3%), 460.83 (+4%), 467.29 (+1.4%)
sorted vanilla 436.68, vanilla2 442.48, lc_shift 460.83, lc_shift2 467.29

Simple: load 3
452.49, 427.35 (-5.9%), 467.29 (+8.5%), 448.43 (-4.2%)
sorted vanilla2 427.35, lc_shift2 448.43, vanilla 452.49, lc_shift 467.29

Complex: load 3
343.64, 342.47 (-0.34%), 344.83 (+0.68%), 348.43 (+1%)
sorted vanilla2 342.47, vanilla 343.64, lc_shift 344.83, lc_shift2 348.43

Simple: update 1
483.09, 462.96 (-4.3%), 478.47 (+3.2%), 467.29 (-2.4%)
sorted vanilla2 462.96, lc_shift2 467.29, lc_shift 478.47, vanilla 483.09

Simple: update 2
381.68, 366.30 (-4.2%), 377.36 (+2.9%), 400.00 (+5.7%)
sorted vanilla2 366.30, lc_shift 377.36, vanilla 381.68, lc_shift2 400.00

Complex: update 2
228.31, 230.41 (+0.91%), 239.81 (+3.9%), 233.64 (-2.6%)
sorted vanilla 228.31, vanilla2 230.41, lc_shift2 233.64, lc_shift 239.81

Simple: search 1
82.08, 81.01 (-1.3%), 81.46 (+0.55%), 82.82 (+1.6%)
sorted vanilla2 81.01, lc_shift 81.46, vanilla 82.08, lc_shift2 82.82

Simple: search 2
29.48, 29.70 (+0.74%), 29.80 (+0.34%), 30.74 (+3.1%)
sorted vanilla 29.48, vanilla2 29.70, lc_shift 29.80, lc_shift2 30.74

Complex: search 2
5.28, 5.41 (+2.4%), 5.48 (+1.3%), 5.56 (+1.4%)
sorted vanilla 5.28, vanilla2 5.41, lc_shift 5.48, lc_shift2 5.56

Simple: search with 1-to-1 sub-objects
23.40, 23.38 (-0.086%), 24.11 (+3%), 23.93 (-0.75%)
sorted vanilla2 23.38, vanilla 23.40, lc_shift2 23.93, lc_shift 24.11

Complex: search with 1-to-1 sub-objects
5.12, 5.12 (+0%), 5.23 (+2.1%), 5.13 (-1.9%)
sorted vanilla 5.12, vanilla2 5.12, lc_shift2 5.13, lc_shift 5.23

Simple: search with 1-to-1 and 1-to-n sub-objects
1.12, 1.13 (+0.88%), 1.13 (+0%), 1.12 (-0.89%)
sorted vanilla 1.12, lc_shift2 1.12, vanilla2 1.13, lc_shift 1.13

Complex: search with 1-to-1 and 1-to-n sub-objects
0.77, 0.78 (+1.3%), 0.77 (-1.3%), 0.78 (+1.3%)
sorted vanilla 0.77, lc_shift 0.77, vanilla2 0.78, lc_shift2 0.78

Simple: iterate 1
61.95, 61.02 (-1.5%), 61.12 (+0.16%), 62.41 (+2.1%)
sorted vanilla2 61.02, lc_shift 61.12, vanilla 61.95, lc_shift2 62.41

Complex: iterate 1
60.20, 61.00 (+1.3%), 58.87 (-3.6%), 61.86 (+4.8%)
sorted lc_shift 58.87, vanilla 60.20, vanilla2 61.00, lc_shift2 61.86

Simple: iterate 2
25.58, 25.63 (+0.2%), 25.63 (+0%), 25.76 (+0.5%)
sorted vanilla 25.58, vanilla2 25.63, lc_shift 25.63, lc_shift2 25.76

Complex: iterate 2
5.21, 5.20 (-0.19%), 5.27 (+1.3%), 5.14 (-2.5%)
sorted lc_shift2 5.14, vanilla2 5.20, vanilla 5.21, lc_shift 5.27

Simple: iterate 3
7.63, 7.81 (+2.3%), 7.77 (-0.51%), 8.18 (+5%)
sorted vanilla 7.63, lc_shift 7.77, vanilla2 7.81, lc_shift2 8.18

Complex: iterate 3
3.41, 3.43 (+0.58%), 3.43 (+0%), 3.51 (+2.3%)
sorted vanilla 3.41, vanilla2 3.43, lc_shift 3.43, lc_shift2 3.51

Simple: delete
515.46, 529.10 (+2.6%), 540.54 (+2.1%), 523.56 (-3.2%)
sorted vanilla 515.46, lc_shift2 523.56, vanilla2 529.10, lc_shift 540.54

Complex: delete
299.40, 301.20 (+0.6%), 292.40 (-3%), 297.62 (+1.8%)
sorted lc_shift 292.40, lc_shift2 297.62, vanilla 299.40, vanilla2 301.20

Simple: insert or update
478.47, 465.12 (-2.9%), 478.47 (+2.8%), 483.09 (+0.96%)
sorted vanilla2 465.12, vanilla 478.47, lc_shift 478.47, lc_shift2 483.09
-------------- next part --------------

##
## Benchmark against Class::DBI using MySQL
##

Module      Version
----------  -------
Class::DBI  v3.0.14

# Simple: insert 1
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  2 wallclock secs ( 1.04 usr +  0.04 sys =  1.08 CPU) @ 925.93/s (n=1000)

# Complex: insert 1
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  1 wallclock secs ( 1.10 usr +  0.05 sys =  1.15 CPU) @ 869.57/s (n=1000)

# Simple: insert 2
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  2 wallclock secs ( 1.87 usr +  0.06 sys =  1.93 CPU) @ 518.13/s (n=1000)

# Complex: insert 2
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  2 wallclock secs ( 1.71 usr +  0.04 sys =  1.75 CPU) @ 571.43/s (n=1000)

# Simple: accessor 1
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  6 wallclock secs ( 5.67 usr +  0.00 sys =  5.67 CPU) @  1.41/s (n=8)

# Complex: accessor 1
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  6 wallclock secs ( 5.66 usr +  0.00 sys =  5.66 CPU) @  1.41/s (n=8)

# Simple: accessor 2
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  6 wallclock secs ( 6.24 usr +  0.00 sys =  6.24 CPU) @  0.32/s (n=2)

# Complex: accessor 2
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  6 wallclock secs ( 6.20 usr +  0.00 sys =  6.20 CPU) @  0.32/s (n=2)

# Simple: load 1
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  1 wallclock secs ( 1.03 usr +  0.05 sys =  1.08 CPU) @ 925.93/s (n=1000)

# Simple: load 2
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  2 wallclock secs ( 1.52 usr +  0.12 sys =  1.64 CPU) @ 609.76/s (n=1000)

# Complex: load 2
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  3 wallclock secs ( 2.19 usr +  0.10 sys =  2.29 CPU) @ 436.68/s (n=1000)

# Simple: load 3
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  2 wallclock secs ( 2.11 usr +  0.10 sys =  2.21 CPU) @ 452.49/s (n=1000)

# Complex: load 3
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  3 wallclock secs ( 2.79 usr +  0.12 sys =  2.91 CPU) @ 343.64/s (n=1000)

# Simple: update 1
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  3 wallclock secs ( 1.95 usr +  0.12 sys =  2.07 CPU) @ 483.09/s (n=1000)

# Simple: update 2
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  4 wallclock secs ( 2.53 usr +  0.09 sys =  2.62 CPU) @ 381.68/s (n=1000)

# Complex: update 2
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  5 wallclock secs ( 4.14 usr +  0.24 sys =  4.38 CPU) @ 228.31/s (n=1000)

# Simple: search 1
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  5 wallclock secs ( 5.15 usr +  0.15 sys =  5.30 CPU) @ 82.08/s (n=435)

# Simple: search 2
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  5 wallclock secs ( 5.30 usr +  0.06 sys =  5.36 CPU) @ 29.48/s (n=158)

# Complex: search 2
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  5 wallclock secs ( 5.10 usr +  0.01 sys =  5.11 CPU) @  5.28/s (n=27)

# Making indexes...

# Simple: search with 1-to-1 sub-objects
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  5 wallclock secs ( 5.12 usr +  0.05 sys =  5.17 CPU) @ 23.40/s (n=121)

# Complex: search with 1-to-1 sub-objects
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  6 wallclock secs ( 5.07 usr +  0.01 sys =  5.08 CPU) @  5.12/s (n=26)

# Inserting 1-to-n records....

# Simple: search with 1-to-1 and 1-to-n sub-objects
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  6 wallclock secs ( 5.24 usr +  0.14 sys =  5.38 CPU) @  1.12/s (n=6)

# Complex: search with 1-to-1 and 1-to-n sub-objects
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  6 wallclock secs ( 5.09 usr +  0.09 sys =  5.18 CPU) @  0.77/s (n=4)

# Simple: iterate 1
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  6 wallclock secs ( 5.14 usr +  0.09 sys =  5.23 CPU) @ 61.95/s (n=324)

# Complex: iterate 1
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  5 wallclock secs ( 5.02 usr +  0.08 sys =  5.10 CPU) @ 60.20/s (n=307)

# Simple: iterate 2
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  6 wallclock secs ( 5.17 usr +  0.03 sys =  5.20 CPU) @ 25.58/s (n=133)

# Complex: iterate 2
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  5 wallclock secs ( 5.17 usr +  0.01 sys =  5.18 CPU) @  5.21/s (n=27)

# Simple: iterate 3
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  6 wallclock secs ( 4.90 usr +  0.34 sys =  5.24 CPU) @  7.63/s (n=40)

# Complex: iterate 3
Benchmark: running CDBI for at least 5 CPU seconds...
      CDBI:  6 wallclock secs ( 5.14 usr +  0.14 sys =  5.28 CPU) @  3.41/s (n=18)

# Dropping indexes...

# Simple: delete
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  3 wallclock secs ( 1.84 usr +  0.10 sys =  1.94 CPU) @ 515.46/s (n=1000)

# Complex: delete
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  4 wallclock secs ( 3.25 usr +  0.09 sys =  3.34 CPU) @ 299.40/s (n=1000)

# Simple: insert or update
Benchmark: timing 1000 iterations of CDBI...
      CDBI:  2 wallclock secs ( 2.02 usr +  0.07 sys =  2.09 CPU) @ 478.47/s (n=1000)

-------------- next part --------------
dprofpp -r tmon.out.vanilla
Total Elapsed Time = 70.55154 Seconds
         Real Time = 70.55154 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 15.8   11.21 11.210  39971   0.0003 0.0003  DBI::st::execute
 12.4   8.776  8.776 325656   0.0000 0.0000  Class::Accessor::Fast::__ANON__
 9.53   6.725 14.603 298581   0.0000 0.0000  Class::DBI::Column::name_lc
 6.30   4.446 19.049 298571   0.0000 0.0000  Class::DBI::Column::__ANON__
 5.98   4.216  4.729 196228   0.0000 0.0000  Class::DBI::_attribute_store
 5.70   4.022 28.704 533286   0.0000 0.0001  Class::DBI::get
 5.67   3.997  3.997 136622   0.0000 0.0000  Class::Data::Inheritable::__ANON__
 4.65   3.280  7.771 698840   0.0000 0.0000  Class::DBI::_attrs
 4.23   2.985  6.892 631200   0.0000 0.0000  Class::DBI::ColumnGrouper::find_co
                                             lumn
 3.80   2.678  6.944 139166   0.0000 0.0000  Class::DBI::_live_object_key
 3.68   2.599 25.887 151350   0.0000 0.0002  Class::DBI::Relationship::HasA::__
                                             ANON__
 3.39   2.392  2.392  28851   0.0001 0.0001  DBI::db::ping
 3.35   2.360  6.152 589818   0.0000 0.0000  Class::DBI::_attribute_exists
 3.23   2.282  7.887  23645   0.0001 0.0003  DateTime::new
 3.12   2.200  9.420 533286   0.0000 0.0000  Class::DBI::_find_columns

dprofpp -r tmon.out.lc_shift
Total Elapsed Time = 97.68773 Seconds
         Real Time = 97.68773 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 12.8   12.50 12.500  39938   0.0003 0.0003  DBI::st::execute
 11.3   11.12 21.160 302625   0.0000 0.0000  Class::DBI::Column::__ANON__
 11.2   11.00 11.001 330551   0.0000 0.0000  Class::Accessor::Fast::__ANON__
 5.40   5.271 34.301 534898   0.0000 0.0001  Class::DBI::get
 4.94   4.822  4.822 139175   0.0000 0.0000  Class::Data::Inheritable::__ANON__
 4.40   4.296  4.933 204054   0.0000 0.0000  Class::DBI::_attribute_store
 4.20   4.099  9.007 706756   0.0000 0.0000  Class::DBI::_attrs
 3.65   3.566  7.743 632812   0.0000 0.0000  Class::DBI::ColumnGrouper::find_co
                                             lumn
 3.12   3.045  6.804 591442   0.0000 0.0000  Class::DBI::_attribute_exists
 3.03   2.962 29.276 156962   0.0000 0.0002  Class::DBI::Relationship::HasA::__
                                             ANON__
 2.94   2.872  6.918 116301   0.0000 0.0001  Class::DBI::_fresh_init
 2.91   2.838 11.090 534898   0.0000 0.0000  Class::DBI::_find_columns
 2.82   2.750  9.060 145378   0.0000 0.0001  Class::DBI::_live_object_key
 2.55   2.488  8.759  24545   0.0001 0.0004  DateTime::new
 2.45   2.397  2.397  28896   0.0001 0.0001  DBI::db::ping



More information about the ClassDBI mailing list