Given this code:
my $dbh = DBI->connect("dbi:ExampleP:", '', '', {
Profile => 1 # <=== NEW
});
my $sth = $dbh->prepare("select mode,size,name from ?");
$sth->execute(".");
while ( my $hash = $sth->fetchrow_hashref ) {
}
exit 0;
The DBI now produces:
'STATEMENT' =>
'select mode,size,name from ?' =>
'fetchrow_hashref' =>
0.031764s / 101 = 0.000314s avg (first 0.001671s, min 0.000214s, max
0.001671s)
'execute' =>
0.000413s / 1 = 0.000413s avg (first 0.000413s, min 0.000413s, max
0.000413s)
'FETCH' =>
0.000081s / 1 = 0.000081s avg (first 0.000081s, min 0.000081s, max
0.000081s)
'disconnect' =>
0.000078s / 1 = 0.000078s avg (first 0.000078s, min 0.000078s, max
0.000078s)
'prepare' =>
0.000711s / 1 = 0.000711s avg (first 0.000711s, min 0.000711s, max
0.000711s)
The Profile attribute enables data collection. Profile => 1 is
shorthand for Profile => {}, which is shorthand for:
Profile => do { require DBI::Profile; bless {}=>DBI::Profile },
The hash is used to collect the data and the DESTROY method in
DBI::Profile formats the data as shown above (currently unsorted).
The data in the hash is structured like this:
STATEMENT => {
'select mode,size,name from ?' => { <-- the current Statement
fetchrow_hashref => [ <-- the method
101, <-- count of calls
'0.0356581211090088', <-- total time spent in those calls
'0.00502204895019531', <-- time spent on first call
'0.000294923782348633', <-- min time spent on a call
'0.00502204895019531', <-- max time spent on a call
'1022532565.05001', <-- time of first call
'1022532565.08818' <-- time of last call
],
}
}
(The code is written to enable alternative ways of structuring
the hash in future.)
By default the Profile attribute is inherited by $sth from $dbh.
You can always set the Profile attribute on a single $sth and have
the Profile stats generated when that $sth is destroyed.
You could also do $dbh->{Driver}->{Profile} = {} and have
multiple database handles share the same stats hash.
Obviously applications that generate vast numbers of different
sql statements, like insert statements without placeholders,
will need to prune the stats hash from time-to-time. In future
it'll be possible for a code ref to edit the statement text
that's used for the stats hash key.
I anticipate people writing modules which slice-n-dice the data in
more interesting ways. The obvious ones:
- Time spent per query (sum together all the calls for that query)
- Time spent per method (sum together all the calls across queries)
will probably be added to DBI::Profile. The DBI will have a function
that merges together multiple data arrays in the right way.
There are some, er, wrinkles, in the choice of default keys for the
stats hash. The main one is that stats for method calls on a
database handle get associated with the $dbh->{Statement} text.
That works fine for $dbh->do(), $dbh->selectrow_arrayref() etc
because $dbh->{Statement} is updated before the method returns.
But calls like $dbh->quote(), when building a new query, will be
associated with the _previous_ query prepared or executed on $dbh.
I don't see that as a big issue right now.
Currently the profile will only gather information for DBI calls
from an application. It'll ignore 'recursive calls' back into the
DBI from DBI and driver methods. That'll be configurable later.
Meanwhile the time recorded does accurately reflect the time from
entry to exit of the top level method call.
The performance cost of adding this feature is one bit flag test
and one 'is a value non-zero' test per DBI method call dispatch.
That's probably just about unmeasurable.
Any questions/comments?
Tim.
