← Index
NYTProf Performance Profile   « block view • line view • sub view »
For /usr/share/koha/opac/cgi-bin/opac/opac-search.pl
  Run on Tue Oct 15 17:10:45 2013
Reported on Tue Oct 15 17:11:32 2013

Filename/usr/share/perl5/Cache/Memcached/GetParser.pm
StatementsExecuted 1857 statements in 14.7ms
Subroutines
Calls P F Exclusive
Time		 Inclusive
Time		 Subroutine
62116.14ms1.42sCache::Memcached::GetParser::::parse_bufferCache::Memcached::GetParser::parse_buffer
67212.61ms2.61msCache::Memcached::GetParser::::CORE:sysreadCache::Memcached::GetParser::CORE:sysread (opcode)
171211.91ms1.91msCache::Memcached::GetParser::::CORE:matchCache::Memcached::GetParser::CORE:match (opcode)
67111.83ms1.57sCache::Memcached::GetParser::::parse_from_sockCache::Memcached::GetParser::parse_from_sock
1111.56ms2.16msCache::Memcached::GetParser::::BEGIN@8Cache::Memcached::GetParser::BEGIN@8
5711910µs910µsCache::Memcached::GetParser::::newCache::Memcached::GetParser::new
111209µs214µsCache::Memcached::GetParser::::BEGIN@4Cache::Memcached::GetParser::BEGIN@4
11116µs21µsCache::Memcached::GetParser::::BEGIN@2Cache::Memcached::GetParser::BEGIN@2
11115µs96µsCache::Memcached::GetParser::::BEGIN@6Cache::Memcached::GetParser::BEGIN@6
11111µs33µsCache::Memcached::GetParser::::BEGIN@3Cache::Memcached::GetParser::BEGIN@3
11110µs47µsCache::Memcached::GetParser::::BEGIN@9Cache::Memcached::GetParser::BEGIN@9
1119µs39µsCache::Memcached::GetParser::::BEGIN@15Cache::Memcached::GetParser::BEGIN@15
1119µs40µsCache::Memcached::GetParser::::BEGIN@10Cache::Memcached::GetParser::BEGIN@10
1118µs38µsCache::Memcached::GetParser::::BEGIN@13Cache::Memcached::GetParser::BEGIN@13
1118µs38µsCache::Memcached::GetParser::::BEGIN@14Cache::Memcached::GetParser::BEGIN@14
1118µs38µsCache::Memcached::GetParser::::BEGIN@12Cache::Memcached::GetParser::BEGIN@12
1117µs38µsCache::Memcached::GetParser::::BEGIN@11Cache::Memcached::GetParser::BEGIN@11
0000s0sCache::Memcached::GetParser::::current_keyCache::Memcached::GetParser::current_key
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments		 Time
on line		 Calls Time
in subs		 Code
1package Cache::Memcached::GetParser;
2331µs225µs
# spent 21µs (16+4) within Cache::Memcached::GetParser::BEGIN@2 which was called: # once (16µs+4µs) by Cache::Memcached::BEGIN@20 at line 2
use strict;
# spent 21µs making 1 call to Cache::Memcached::GetParser::BEGIN@2 # spent 4µs making 1 call to strict::import
3329µs255µs
# spent 33µs (11+22) within Cache::Memcached::GetParser::BEGIN@3 which was called: # once (11µs+22µs) by Cache::Memcached::BEGIN@20 at line 3
use warnings;
# spent 33µs making 1 call to Cache::Memcached::GetParser::BEGIN@3 # spent 22µs making 1 call to warnings::import
43245µs2221µs
# spent 214µs (209+6) within Cache::Memcached::GetParser::BEGIN@4 which was called: # once (209µs+6µs) by Cache::Memcached::BEGIN@20 at line 4
use integer;
# spent 214µs making 1 call to Cache::Memcached::GetParser::BEGIN@4 # spent 6µs making 1 call to integer::import
5
6356µs2176µs
# spent 96µs (15+80) within Cache::Memcached::GetParser::BEGIN@6 which was called: # once (15µs+80µs) by Cache::Memcached::BEGIN@20 at line 6
use Errno qw( EINPROGRESS EWOULDBLOCK EISCONN );
# spent 96µs making 1 call to Cache::Memcached::GetParser::BEGIN@6 # spent 80µs making 1 call to Exporter::import
7
83205µs22.29ms
# spent 2.16ms (1.56+607µs) within Cache::Memcached::GetParser::BEGIN@8 which was called: # once (1.56ms+607µs) by Cache::Memcached::BEGIN@20 at line 8
use constant DEST => 0; # destination hashref we're writing into
# spent 2.16ms making 1 call to Cache::Memcached::GetParser::BEGIN@8 # spent 129µs making 1 call to constant::import
9334µs285µs
# spent 47µs (10+37) within Cache::Memcached::GetParser::BEGIN@9 which was called: # once (10µs+37µs) by Cache::Memcached::BEGIN@20 at line 9
use constant NSLEN => 1; # length of namespace to ignore on keys
# spent 47µs making 1 call to Cache::Memcached::GetParser::BEGIN@9 # spent 37µs making 1 call to constant::import
10330µs271µs
# spent 40µs (9+31) within Cache::Memcached::GetParser::BEGIN@10 which was called: # once (9µs+31µs) by Cache::Memcached::BEGIN@20 at line 10
use constant ON_ITEM => 2;
# spent 40µs making 1 call to Cache::Memcached::GetParser::BEGIN@10 # spent 31µs making 1 call to constant::import
11329µs269µs
# spent 38µs (7+31) within Cache::Memcached::GetParser::BEGIN@11 which was called: # once (7µs+31µs) by Cache::Memcached::BEGIN@20 at line 11
use constant BUF => 3; # read buffer
# spent 38µs making 1 call to Cache::Memcached::GetParser::BEGIN@11 # spent 31µs making 1 call to constant::import
12331µs268µs
# spent 38µs (8+30) within Cache::Memcached::GetParser::BEGIN@12 which was called: # once (8µs+30µs) by Cache::Memcached::BEGIN@20 at line 12
use constant STATE => 4; # 0 = waiting for a line, N = reading N bytes
# spent 38µs making 1 call to Cache::Memcached::GetParser::BEGIN@12 # spent 30µs making 1 call to constant::import
13329µs269µs
# spent 38µs (8+30) within Cache::Memcached::GetParser::BEGIN@13 which was called: # once (8µs+30µs) by Cache::Memcached::BEGIN@20 at line 13
use constant OFFSET => 5; # offsets to read into buffers
# spent 38µs making 1 call to Cache::Memcached::GetParser::BEGIN@13 # spent 30µs making 1 call to constant::import
14329µs268µs
# spent 38µs (8+30) within Cache::Memcached::GetParser::BEGIN@14 which was called: # once (8µs+30µs) by Cache::Memcached::BEGIN@20 at line 14
use constant FLAGS => 6;
# spent 38µs making 1 call to Cache::Memcached::GetParser::BEGIN@14 # spent 30µs making 1 call to constant::import
153712µs269µs
# spent 39µs (9+30) within Cache::Memcached::GetParser::BEGIN@15 which was called: # once (9µs+30µs) by Cache::Memcached::BEGIN@20 at line 15
use constant KEY => 7; # current key we're parsing (without the namespace prefix)
# spent 39µs making 1 call to Cache::Memcached::GetParser::BEGIN@15 # spent 30µs making 1 call to constant::import
16
17
# spent 910µs within Cache::Memcached::GetParser::new which was called 57 times, avg 16µs/call: # 57 times (910µs+0s) by Cache::Memcached::_load_multi at line 727 of Cache/Memcached.pm, avg 16µs/call
sub new {
18114978µs my ($class, $dest, $nslen, $on_item) = @_;
19 return bless [$dest, $nslen, $on_item, '', 0, 0], $class;
20}
21
22sub current_key {
23 return $_[0][KEY];
24}
25
26# returns 1 on success, -1 on failure, and 0 if still working.
27
# spent 1.57s (1.83ms+1.57) within Cache::Memcached::GetParser::parse_from_sock which was called 67 times, avg 23.5ms/call: # 67 times (1.83ms+1.57s) by Cache::Memcached::__ANON__[/usr/share/perl5/Cache/Memcached.pm:741] at line 733 of Cache/Memcached.pm, avg 23.5ms/call
sub parse_from_sock {
285114.03ms my ($self, $sock) = @_;
29 my $res;
30
31 # where are we reading into?
3235236µs if ($self->[STATE]) { # reading value into $ret
33 my $ret = $self->[DEST];
345130µs $res = sysread($sock, $ret->{$self->[KEY]},
# spent 130µs making 5 calls to Cache::Memcached::GetParser::CORE:sysread, avg 26µs/call
35 $self->[STATE] - $self->[OFFSET],
36 $self->[OFFSET]);
37
38 return 0
39 if !defined($res) and $!==EWOULDBLOCK;
40
41 if ($res == 0) { # catches 0=conn closed or undef=error
42 $self->[ON_ITEM] = undef;
43 return -1;
44 }
45
46 $self->[OFFSET] += $res;
471541µs if ($self->[OFFSET] == $self->[STATE]) { # finished reading
485153ms $self->[ON_ITEM]->($self->[KEY], $self->[FLAGS]);
# spent 153ms making 5 calls to Cache::Memcached::__ANON__[Cache/Memcached.pm:714], avg 30.7ms/call
49 $self->[OFFSET] = 0;
50 $self->[STATE] = 0;
51 # wait for another VALUE line or END...
52 }
53 return 0; # still working, haven't got to end yet
54 }
55
56 # we're reading a single line.
57 # first, read whatever's there, but be satisfied with 2048 bytes
58622.48ms $res = sysread($sock, $self->[BUF],
# spent 2.48ms making 62 calls to Cache::Memcached::GetParser::CORE:sysread, avg 40µs/call
59 128*1024, $self->[OFFSET]);
60 return 0
61 if !defined($res) and $!==EWOULDBLOCK;
62 if ($res == 0) {
63 $self->[ON_ITEM] = undef;
64 return -1;
65 }
66
67 $self->[OFFSET] += $res;
68
69621.42s return $self->parse_buffer;
# spent 1.42s making 62 calls to Cache::Memcached::GetParser::parse_buffer, avg 22.9ms/call
70}
71
72# returns 1 on success, -1 on failure, and 0 if still working.
73
# spent 1.42s (6.14ms+1.41) within Cache::Memcached::GetParser::parse_buffer which was called 62 times, avg 22.9ms/call: # 62 times (6.14ms+1.41s) by Cache::Memcached::GetParser::parse_from_sock at line 69, avg 22.9ms/call
sub parse_buffer {
74191215µs my ($self) = @_;
75 my $ret = $self->[DEST];
76
77 SEARCH:
78 while (1) { # may have to search many times
79
80 # do we have a complete END line?
812853.15ms114673µs if ($self->[BUF] =~ /^END\r\n/) {
# spent 673µs making 114 calls to Cache::Memcached::GetParser::CORE:match, avg 6µs/call
82 $self->[ON_ITEM] = undef;
83 return 1; # we're done successfully, return 1 to finish
84 }
85
86 # do we have a complete VALUE line?
874614.05ms571.23ms if ($self->[BUF] =~ /^VALUE (\S+) (\d+) (\d+)\r\n/) {
# spent 1.23ms making 57 calls to Cache::Memcached::GetParser::CORE:match, avg 22µs/call
88 ($self->[KEY], $self->[FLAGS], $self->[STATE]) =
89 (substr($1, $self->[NSLEN]), int($2), $3+2);
90 # Note: we use $+[0] and not pos($self->[BUF]) because pos()
91 # seems to have problems under perl's taint mode. nobody
92 # on the list discovered why, but this seems a reasonable
93 # work-around:
94 my $p = $+[0];
95 my $len = length($self->[BUF]);
96 my $copy = $len-$p > $self->[STATE] ? $self->[STATE] : $len-$p;
97 $ret->{$self->[KEY]} = substr($self->[BUF], $p, $copy)
98 if $copy;
99 $self->[OFFSET] = $copy;
100 substr($self->[BUF], 0, $p+$copy, ''); # delete the stuff we used
101
102208534µs if ($self->[OFFSET] == $self->[STATE]) { # have it all?
103521.41s $self->[ON_ITEM]->($self->[KEY], $self->[FLAGS]);
# spent 1.41s making 52 calls to Cache::Memcached::__ANON__[Cache/Memcached.pm:714], avg 27.1ms/call
104 $self->[OFFSET] = 0;
105 $self->[STATE] = 0;
106 next SEARCH; # look again
107 }
108
109 last SEARCH; # buffer is empty now
110 }
111
112 # if we're here probably means we only have a partial VALUE
113 # or END line in the buffer. Could happen with multi-get,
114 # though probably very rarely. Exit the loop and let it read
115 # more.
116
117 # but first, make sure subsequent reads don't destroy our
118 # partial VALUE/END line.
119 $self->[OFFSET] = length($self->[BUF]);
120 last SEARCH;
121 }
122 return 0;
123}
124
12515µs1;
 
# spent 1.91ms within Cache::Memcached::GetParser::CORE:match which was called 171 times, avg 11µs/call: # 114 times (673µs+0s) by Cache::Memcached::GetParser::parse_buffer at line 81, avg 6µs/call # 57 times (1.23ms+0s) by Cache::Memcached::GetParser::parse_buffer at line 87, avg 22µs/call
sub Cache::Memcached::GetParser::CORE:match; # opcode
# spent 2.61ms within Cache::Memcached::GetParser::CORE:sysread which was called 67 times, avg 39µs/call: # 62 times (2.48ms+0s) by Cache::Memcached::GetParser::parse_from_sock at line 58, avg 40µs/call # 5 times (130µs+0s) by Cache::Memcached::GetParser::parse_from_sock at line 34, avg 26µs/call
sub Cache::Memcached::GetParser::CORE:sysread; # opcode
Report produced by the NYTProf 4.04 Perl profiler, developed by Tim Bunce and Adam Kaplan.