Author: timbo
Date: Tue Dec 13 08:05:21 2005
New Revision: 2308
Modified:
dbi/trunk/Changes
dbi/trunk/DBI.xs
dbi/trunk/lib/DBI/Profile.pm
dbi/trunk/lib/DBI/ProfileData.pm
dbi/trunk/t/40profile.t
Log:
Changed dbi_profile_merge() to be able to recurse and merge
sub-trees of profile data.
Added documentation for dbi_profile_merge(), including how to
measure the time spent inside the DBI for an http request.
Modified: dbi/trunk/Changes
==============================================================================
--- dbi/trunk/Changes (original)
+++ dbi/trunk/Changes Tue Dec 13 08:05:21 2005
@@ -9,6 +9,12 @@ DBI::Changes - List of significant chang
Fixed Makefile.PL options for gcc bug introduced in 1.49.
Fixed handle magic order to keep DBD::Oracle happy.
+ Changed dbi_profile_merge() to be able to recurse and merge
+ sub-trees of profile data.
+
+ Added documentation for dbi_profile_merge(), including how to
+ measure the time spent inside the DBI for an http request.
+
=head2 Changes in DBI 1.49 (svn rev 2287), 29th November 2005
Fixed assorted attribute handling bugs in DBD::Proxy.
Modified: dbi/trunk/DBI.xs
==============================================================================
--- dbi/trunk/DBI.xs (original)
+++ dbi/trunk/DBI.xs Tue Dec 13 08:05:21 2005
@@ -2315,11 +2315,10 @@ dbi_profile_merge(SV *dest, SV *incremen
AV *d_av, *i_av;
SV *tmp;
double i_nv;
- if (!SvROK(dest) || SvTYPE(SvRV(dest)) != SVt_PVAV
- || !SvROK(increment) || SvTYPE(SvRV(increment)) != SVt_PVAV)
- croak("dbi_profile_merge(%s, %s) requires array refs",
- neatsvpv(dest,0), neatsvpv(dest,0));
- i_av = (AV*)SvRV(increment);
+ int i_is_earlier;
+
+ if (!SvROK(dest) || SvTYPE(SvRV(dest)) != SVt_PVAV)
+ croak("dbi_profile_merge(%s, ...) requires array ref",
neatsvpv(dest,0));
d_av = (AV*)SvRV(dest);
if (av_len(d_av) < DBIprof_max_index) {
@@ -2327,11 +2326,29 @@ dbi_profile_merge(SV *dest, SV *incremen
av_extend(d_av, DBIprof_max_index);
for(idx=0; idx<=DBIprof_max_index; ++idx) {
tmp = *av_fetch(d_av, idx, 1);
- if (!SvOK(tmp))
- sv_setiv(tmp, 0);
+ if (!SvOK(tmp) && idx != DBIprof_MIN_TIME && idx !=
DBIprof_FIRST_CALLED)
+ sv_setnv(tmp, 0.0); /* leave 'min' values as undef */
}
}
+ if (!SvOK(increment))
+ return;
+
+ if (SvROK(increment) && SvTYPE(SvRV(increment)) == SVt_PVHV) {
+ HV *hv = (HV*)SvRV(increment);
+ char *key;
+ I32 keylen = 0;
+ hv_iterinit(hv);
+ while ( (tmp = hv_iternextsv(hv, &key, &keylen)) != NULL ) {
+ dbi_profile_merge(dest, tmp);
+ };
+ return;
+ }
+
+ if (!SvROK(increment) || SvTYPE(SvRV(increment)) != SVt_PVAV)
+ croak("dbi_profile_merge: increment not an array or hash ref");
+ i_av = (AV*)SvRV(increment);
+
tmp = *av_fetch(d_av, DBIprof_COUNT, 1);
sv_setiv( tmp, SvIV(tmp) + SvIV( *av_fetch(i_av, DBIprof_COUNT, 1)) );
@@ -2340,7 +2357,7 @@ dbi_profile_merge(SV *dest, SV *incremen
i_nv = SvNV(*av_fetch(i_av, DBIprof_MIN_TIME, 1));
tmp = *av_fetch(d_av, DBIprof_MIN_TIME, 1);
- if (i_nv < SvNV(tmp)) sv_setnv(tmp, i_nv);
+ if (!SvOK(tmp) || i_nv < SvNV(tmp)) sv_setnv(tmp, i_nv);
i_nv = SvNV(*av_fetch(i_av, DBIprof_MAX_TIME, 1));
tmp = *av_fetch(d_av, DBIprof_MAX_TIME, 1);
@@ -2348,11 +2365,16 @@ dbi_profile_merge(SV *dest, SV *incremen
i_nv = SvNV(*av_fetch(i_av, DBIprof_FIRST_CALLED, 1));
tmp = *av_fetch(d_av, DBIprof_FIRST_CALLED, 1);
- if (i_nv < SvNV(tmp)) {
+ i_is_earlier = (!SvOK(tmp) || i_nv < SvNV(tmp));
+ if (i_is_earlier)
sv_setnv(tmp, i_nv);
+
+ i_nv = SvNV(*av_fetch(i_av, DBIprof_FIRST_TIME, 1));
+ tmp = *av_fetch(d_av, DBIprof_FIRST_TIME, 1);
+ if (i_is_earlier || !SvOK(tmp)) {
/* If the increment has an earlier DBIprof_FIRST_CALLED
- then we use the DBIprof_FIRST_TIME from the increment */
- sv_setnv( tmp, SvNV( *av_fetch(i_av, DBIprof_FIRST_TIME, 1)) );
+ then we set the DBIprof_FIRST_TIME from the increment */
+ sv_setnv(tmp, i_nv);
}
i_nv = SvNV(*av_fetch(i_av, DBIprof_LAST_CALLED, 1));
@@ -3788,15 +3810,20 @@ dbi_profile_merge(dest, ...)
SV * dest
CODE:
{
- (void)cv;
if (!SvROK(dest) || SvTYPE(SvRV(dest)) != SVt_PVAV)
croak("dbi_profile_merge(%s,...) not an array reference",
neatsvpv(dest,0));
- /* items==2 for dest + 1 arg, ST(0) is dest, ST(1) is first arg */
- while (--items >= 1) {
- SV *thingy = ST(items); /* currently has to be an array ref */
- dbi_profile_merge(dest, thingy);
+ if (items <= 1) {
+ (void)cv;
+ RETVAL = 0;
+ }
+ else {
+ /* items==2 for dest + 1 arg, ST(0) is dest, ST(1) is first arg */
+ while (--items >= 1) {
+ SV *thingy = ST(items);
+ dbi_profile_merge(dest, thingy);
+ }
+ RETVAL = newSVsv(*av_fetch((AV*)SvRV(dest), DBIprof_TOTAL_TIME, 1));
}
- RETVAL = newSVsv(*av_fetch((AV*)SvRV(dest), DBIprof_TOTAL_TIME, 1));
}
OUTPUT:
RETVAL
Modified: dbi/trunk/lib/DBI/Profile.pm
==============================================================================
--- dbi/trunk/lib/DBI/Profile.pm (original)
+++ dbi/trunk/lib/DBI/Profile.pm Tue Dec 13 08:05:21 2005
@@ -381,6 +381,52 @@ then by default the statement handles cr
to the same merged profile data tree.
+=head1 CUSTOM DATA MANIPULATION
+
+Recall that C<$h->{Profile}->{Data}> is a reference to the collected data.
+Either to a 'leaf' array (when the Path is empty, i.e., DBI_PROFILE env var is
1),
+or a reference to hash containing values that are either further hash
+references or leaf array references.
+
+Sometimes it's useful to be able to summarise some or all of the collected
data.
+The dbi_profile_merge() function can be used to merge leaf node values.
+
+=head2 dbi_profile_merge
+
+ use DBI qw(dbi_profile_merge);
+
+ $time_in_dbi = dbi_profile_merge(my $totals=[], @$leaves);
+
+Merges profile data node. Given a reference to a destination array, and zero or
+more references to profile data, merges the profile data into the destination
array.
+For example:
+
+ $time_in_dbi = dbi_profile_merge(
+ my $totals=[],
+ [ 10, 0.51, 0.11, 0.01, 0.22, 1023110000, 1023110010 ],
+ [ 15, 0.42, 0.12, 0.02, 0.23, 1023110005, 1023110009 ],
+ );
+
+$totals will then contain
+
+ [ 25, 0.93, 0.11, 0.01, 0.23, 1023110000, 1023110010 ]
+
+and $time_in_dbi will be 0.93;
+
+For example, to get the time spent 'inside' the DBI during an http request,
+your logging code run at the end of the request (i.e. mod_perl LogHandler)
+could use:
+
+ my $time_in_dbi = 0;
+ if (my $Profile = $dbh->{Profile}) { # if DBI profiling is enabled
+ $time_in_dbi = dbi_profile_merge(my $total=[], $Profile->{Data});
+ $Profile->{Data} = {}; # reset the profile data
+ }
+
+If profiling has been enabled then $time_in_dbi will hold the time spent inside
+the DBI for that handle (and any other handles that share the same profile
data)
+since the last request.
+
=head1 CUSTOM DATA COLLECTION
=head2 Using The Path Attribute
Modified: dbi/trunk/lib/DBI/ProfileData.pm
==============================================================================
--- dbi/trunk/lib/DBI/ProfileData.pm (original)
+++ dbi/trunk/lib/DBI/ProfileData.pm Tue Dec 13 08:05:21 2005
@@ -261,30 +261,6 @@ sub _read_body {
}
}
-# takes an existing node and merges in new data points
-sub _merge_data { # XXX use dbi_profile_merge instead
- my ($self, $node, $data) = @_;
-
- # add counts and total duration
- $node->[COUNT] += $data->[COUNT];
- $node->[TOTAL] += $data->[TOTAL];
-
- # first duration untouched
-
- # take new shortest duration if shorter
- $node->[SHORTEST] = $data->[SHORTEST]
- if $data->[SHORTEST] < $node->[SHORTEST];
-
- # take new longest duration if longer
- $node->[LONGEST] = $data->[LONGEST]
- if $data->[LONGEST] > $node->[LONGEST];
-
- # time of first event untouched
-
- # take time of last event
- $node->[LAST_AT] = $data->[LAST_AT];
-}
-
=item $copy = $prof->clone();
Modified: dbi/trunk/t/40profile.t
==============================================================================
--- dbi/trunk/t/40profile.t (original)
+++ dbi/trunk/t/40profile.t Tue Dec 13 08:05:21 2005
@@ -26,7 +26,7 @@ BEGIN {
}
use Test;
-BEGIN { plan tests => 60; }
+BEGIN { plan tests => 64; }
use Data::Dumper;
$Data::Dumper::Indent = 1;
@@ -194,6 +194,23 @@ my $t1 = DBI::dbi_time;
dbi_profile($dbh, "Hi, mom", "fetchhash_bang", $t1, $t1 + 1);
ok(exists $data->{foo}{"Hi, mom"});
+my $total_time = dbi_profile_merge(
+ my $totals=[],
+ [ 10, 0.51, 0.11, 0.01, 0.22, 1023110000, 1023110010 ],
+ [ 15, 0.42, 0.12, 0.02, 0.23, 1023110005, 1023110009 ],
+);
+ok("@$totals", "25 0.93 0.11 0.01 0.23 1023110000 1023110010");
+ok($total_time, 0.93);
+
+$total_time = dbi_profile_merge(
+ $totals=[], {
+ foo => [ 10, 1.51, 0.11, 0.01, 0.22, 1023110000, 1023110010 ],
+ bar => [ 17, 1.42, 0.12, 0.02, 0.23, 1023110005, 1023110009 ],
+ }
+);
+ok("@$totals", "27 2.93 0.11 0.01 0.23 1023110000 1023110010");
+ok($total_time, 2.93);
+
# check that output went into the log file
DBI->trace(0, "STDOUT"); # close current log to flush it
ok(-s $LOG_FILE);
