| Subject: | [patch] Measure query running time |
Attached is a patch to have AnyEvent::Pg measure the running time of each query and pass this as extra argument to the on_result and on_done callbacks. This functionality is useful for logging and throttling on SQL time (for which I use it).
| Subject: | AEPg-timing-0.14.patch |
diff -ur AnyEvent-Pg-0.14/lib/AnyEvent/Pg/Pool.pm AnyEvent-Pg-mod/lib/AnyEvent/Pg/Pool.pm
--- AnyEvent-Pg-0.14/lib/AnyEvent/Pg/Pool.pm 2014-05-06 16:33:49.000000000 +0200
+++ AnyEvent-Pg-mod/lib/AnyEvent/Pg/Pool.pm 2014-10-22 08:46:24.451960357 +0200
@@ -351,7 +351,7 @@
my %error_severiry_fatal = map { $_ => 1 } qw(FATAL PANIC);
sub _on_query_result {
- my ($pool, $seq, $conn, $result) = @_;
+ my ($pool, $seq, $conn, $result, $time) = @_;
my $query = $pool->{current}{$seq};
if ($debug and $debug & 8) {
$pool->_debug("query result $result received for query $query on connection $conn, seq: $seq");
@@ -375,7 +375,7 @@
}
}
$query->{max_retries} = 0;
- $pool->_maybe_callback($query, 'on_result', $conn, $result);
+ $pool->_maybe_callback($query, 'on_result', $conn, $result, $time);
}
}
@@ -386,7 +386,7 @@
}
sub _on_query_done {
- my ($pool, $seq, $conn) = @_;
+ my ($pool, $seq, $conn, $time) = @_;
my $query = delete $pool->{current}{$seq};
if (delete $query->{retry}) {
$debug and $debug & 8 and $pool->_debug("unshifting failed query into queue");
@@ -394,7 +394,7 @@
$pool->_requeue_query($query);
}
else {
- $pool->_maybe_callback($query, 'on_done', $conn);
+ $pool->_maybe_callback($query, 'on_done', $conn, $time);
}
}
@@ -770,15 +770,16 @@
The callbacks for the C<push_query> method receive as arguments the
pool object, the underlying L<AnyEvent::Pg> object actually handling
-the query and the result object when applicable. For instance:
+the query, the result object when applicable and the running time.
+For instance:
sub on_result_cb {
- my ($pool, $conn, $result) = @_;
+ my ($pool, $conn, $result, $time) = @_;
...
}
sub on_done_cb {
- my ($pool, $conn) = @_;
+ my ($pool, $conn, $time) = @_;
}
my $watcher = $pool->push_query("select * from foo",
diff -ur AnyEvent-Pg-0.14/lib/AnyEvent/Pg.pm AnyEvent-Pg-mod/lib/AnyEvent/Pg.pm
--- AnyEvent-Pg-0.14/lib/AnyEvent/Pg.pm 2014-05-06 16:33:41.000000000 +0200
+++ AnyEvent-Pg-mod/lib/AnyEvent/Pg.pm 2014-10-22 08:45:09.221249466 +0200
@@ -331,6 +331,7 @@
my $args = "'" . join("', '", @{$query->{args}}) . "'";
$self->_debug("calling $method($args)");
}
+ $self->{query_time} = AE::now();
if ($dbc->$method(@{$query->{args}})) {
$self->{current_query} = $query;
$self->_on_push_query_flushable;
@@ -412,11 +413,11 @@
my $sqlstate = $result->errorField('sqlstate') // '<undef>';
$self->_debug("calling on_result status: $status, sqlstate: $sqlstate, conn status: $conn_status, cmdRows: $cmdRows, columns: $cols, rows: $rows");
}
- $self->_maybe_callback($cq, 'on_result', $result);
+ $self->_maybe_callback($cq, 'on_result', $result, AE::now()-$self->{query_time});
}
else {
$debug and $debug & 2 and $self->_debug("calling on_done");
- $self->_maybe_callback($cq, 'on_done');
+ $self->_maybe_callback($cq, 'on_done', AE::now()-$self->{query_time});
undef $self->{current_query};
$self->_on_push_query;
return;
@@ -584,13 +585,15 @@
You should expect one result object for every SQL statement on the
query.
-The callback will receive as its arguments the AnyEvent::Pg and the
-L<Pg::PQ::Result> object.
+The callback will receive as its arguments the AnyEvent::Pg, the
+L<Pg::PQ::Result> object, and the time elapsed since the query has been sent to
+the PostgreSQL server.
=item on_done => sub { ... }
-This callback will be run after the last result from the query is
-processed. The AnyEvent::Pg object is passed as an argument.
+This callback will be run after the last result from the query is processed.
+The AnyEvent::Pg object and the time elapsed since the query has been sent to
+the PostreSQL server are passed as arguments.
=back