http://qs321.pair.com?node_id=277617


in reply to Transaction time for LWP::UserAgent GET

You can time the subroutine that does the request, in this case LWP::UserAgent::request (or LWP::UserAgent::simple_request, one level further down) using Hook::LexWrap and Time::HiRes. This can be handy when there are a number of layers between the subroutine/method you call and the one that you want to time (e.g. when you're using some higher level module like WWW::Mechanize to fetch the pages.

Please note that no attempt was made to adjust the time reported to take into account the time spent in the timing code itself.

use strict; use warnings; use Time::HiRes qw(tv_interval gettimeofday); use Hook::LexWrap; use LWP::UserAgent; use Data::Dumper; my $start; my @timer_list; my $timer = {}; wrap LWP::UserAgent::request, pre => \&start_timer, post => \&stop_timer, ; ### Now any LWP calls that use the subroutine ### LWP::UserAgent::request will be timed my $agent = LWP::UserAgent->new(timeout => 30); my $site = 'http://www.perlmonks.org/'; my $response = HTTP::Request->new(GET => $site); my $page = $agent->request($response); $page = $agent->request($response); $page = $agent->request($response); $page = $agent->request($response); $page = $agent->request($response); ### After doing some LWP work, dump the results: print Dumper(\@timer_list); sub start_timer { $start = [gettimeofday]; } sub stop_timer { $timer->{interval} = tv_interval ($start, [gettimeofday]); push @timer_list, $timer; $timer = {}; };
And the output:
$VAR1 = [ { 'interval' => '8.521706' }, { 'interval' => '3.794971' }, { 'interval' => '20.934479' }, { 'interval' => '12.792284' }, { 'interval' => '4.147622' } ];