| File | /project/perl/lib/LWP/Protocol/http.pm |
| Statements Executed | 57294 |
| Statement Execution Time | 92.9s |
| Calls | P | F | Exclusive Time |
Inclusive Time |
Subroutine |
|---|---|---|---|---|---|
| 468 | 1 | 2 | 92.0s | 92.0s | LWP::Protocol::http::SocketMethods::CORE:sselect (opcode) |
| 461 | 1 | 1 | 576ms | 146s | LWP::Protocol::http::request |
| 461 | 1 | 1 | 65.3ms | 49.6s | LWP::Protocol::http::_new_socket |
| 922 | 1 | 1 | 42.0ms | 50.9ms | LWP::Protocol::http::__ANON__[:166] |
| 461 | 1 | 1 | 34.4ms | 138ms | LWP::Protocol::http::_fixup_header |
| 468 | 1 | 1 | 32.4ms | 92.0s | LWP::Protocol::http::SocketMethods::can_read |
| 468 | 2 | 1 | 32.0ms | 91.0ms | LWP::Protocol::http::__ANON__[:352] |
| 468 | 2 | 1 | 31.2ms | 92.1s | LWP::Protocol::http::SocketMethods::sysread |
| 461 | 1 | 1 | 29.8ms | 292ms | LWP::Protocol::http::_get_sock_info |
| 468 | 1 | 2 | 18.1ms | 18.1ms | LWP::Protocol::http::SocketMethods::CORE:sysread (opcode) |
| 2305 | 3 | 2 | 11.8ms | 11.8ms | LWP::Protocol::http::CORE:subst (opcode) |
| 461 | 1 | 1 | 9.49ms | 9.49ms | LWP::Protocol::http::SocketMethods::increment_response_count |
| 1383 | 3 | 2 | 9.34ms | 9.34ms | LWP::Protocol::http::CORE:match (opcode) |
| 461 | 1 | 1 | 8.73ms | 8.73ms | LWP::Protocol::http::socket_class |
| 461 | 1 | 1 | 5.20ms | 5.20ms | LWP::Protocol::http::_check_sock |
| 461 | 1 | 1 | 5.09ms | 5.09ms | LWP::Protocol::http::_extra_sock_opts |
| 0 | 0 | 0 | 0s | 0s | LWP::Protocol::http::BEGIN |
| 0 | 0 | 0 | 0s | 0s | LWP::Protocol::http::Socket::BEGIN |
| 0 | 0 | 0 | 0s | 0s | LWP::Protocol::http::SocketMethods::ping |
| 0 | 0 | 0 | 0s | 0s | LWP::Protocol::http::hlist_remove |
| Line | State ments |
Time on line |
Calls | Time in subs |
Code |
|---|---|---|---|---|---|
| 1 | # $Id: http.pm,v 1.70 2005/12/08 10:28:01 gisle Exp $ | ||||
| 2 | # | ||||
| 3 | |||||
| 4 | package LWP::Protocol::http; | ||||
| 5 | |||||
| 6 | 3 | 152µs | 1 | 25µs | use strict; # spent 25µs making 1 call to strict::import |
| 7 | |||||
| 8 | 1 | 6µs | require LWP::Debug; | ||
| 9 | 1 | 4µs | require HTTP::Response; | ||
| 10 | 1 | 5µs | require HTTP::Status; | ||
| 11 | 1 | 245µs | require Net::HTTP; | ||
| 12 | |||||
| 13 | 3 | 4.25ms | 1 | 219µs | use vars qw(@ISA @EXTRA_SOCK_OPTS); # spent 219µs making 1 call to vars::import |
| 14 | |||||
| 15 | 1 | 7µs | require LWP::Protocol; | ||
| 16 | 1 | 6µs | @ISA = qw(LWP::Protocol); | ||
| 17 | |||||
| 18 | 1 | 4µs | my $CRLF = "\015\012"; | ||
| 19 | |||||
| 20 | sub _new_socket | ||||
| 21 | # spent 49.6s (65.3ms+49.5) within LWP::Protocol::http::_new_socket which was called 461 times, avg 108ms/call:
# 461 times (65.3ms+49.5s) by LWP::Protocol::http::request at line 154, avg 108ms/call | ||||
| 22 | 461 | 3.25ms | my($self, $host, $port, $timeout) = @_; | ||
| 23 | 461 | 3.25ms | my $conn_cache = $self->{ua}{conn_cache}; | ||
| 24 | 461 | 2.12ms | if ($conn_cache) { | ||
| 25 | if (my $sock = $conn_cache->withdraw("http", "$host:$port")) { | ||||
| 26 | return $sock if $sock && !$sock->can_read(0); | ||||
| 27 | # if the socket is readable, then either the peer has closed the | ||||
| 28 | # connection or there are some garbage bytes on it. In either | ||||
| 29 | # case we abandon it. | ||||
| 30 | $sock->close; | ||||
| 31 | } | ||||
| 32 | } | ||||
| 33 | |||||
| 34 | 461 | 4.45ms | local($^W) = 0; # IO::Socket::INET can be noisy | ||
| 35 | 461 | 27.3ms | 1383 | 49.5s | my $sock = $self->socket_class->new(PeerAddr => $host, # spent 49.5s making 461 calls to IO::Socket::INET::new, avg 107ms/call
# spent 8.73ms making 461 calls to LWP::Protocol::http::socket_class, avg 19µs/call
# spent 5.09ms making 461 calls to LWP::Protocol::http::_extra_sock_opts, avg 11µs/call |
| 36 | PeerPort => $port, | ||||
| 37 | Proto => 'tcp', | ||||
| 38 | Timeout => $timeout, | ||||
| 39 | KeepAlive => !!$conn_cache, | ||||
| 40 | SendTE => 1, | ||||
| 41 | $self->_extra_sock_opts($host, $port), | ||||
| 42 | ); | ||||
| 43 | |||||
| 44 | 461 | 2.21ms | unless ($sock) { | ||
| 45 | # IO::Socket::INET leaves additional error messages in $@ | ||||
| 46 | $@ =~ s/^.*?: //; | ||||
| 47 | die "Can't connect to $host:$port ($@)"; | ||||
| 48 | } | ||||
| 49 | |||||
| 50 | # perl 5.005's IO::Socket does not have the blocking method. | ||||
| 51 | 922 | 17.3ms | 461 | 5.46ms | eval { $sock->blocking(0); }; # spent 5.46ms making 461 calls to IO::Handle::blocking, avg 12µs/call |
| 52 | |||||
| 53 | 461 | 9.13ms | $sock; | ||
| 54 | } | ||||
| 55 | |||||
| 56 | sub socket_class | ||||
| 57 | # spent 8.73ms within LWP::Protocol::http::socket_class which was called 461 times, avg 19µs/call:
# 461 times (8.73ms+0s) by LWP::Protocol::http::_new_socket at line 35, avg 19µs/call | ||||
| 58 | 461 | 2.21ms | my $self = shift; | ||
| 59 | 461 | 8.38ms | (ref($self) || $self) . "::Socket"; | ||
| 60 | } | ||||
| 61 | |||||
| 62 | sub _extra_sock_opts # to be overridden by subclass | ||||
| 63 | # spent 5.09ms within LWP::Protocol::http::_extra_sock_opts which was called 461 times, avg 11µs/call:
# 461 times (5.09ms+0s) by LWP::Protocol::http::_new_socket at line 35, avg 11µs/call | ||||
| 64 | 461 | 6.11ms | return @EXTRA_SOCK_OPTS; | ||
| 65 | } | ||||
| 66 | |||||
| 67 | sub _check_sock | ||||
| 68 | 461 | 5.75ms | # spent 5.20ms within LWP::Protocol::http::_check_sock which was called 461 times, avg 11µs/call:
# 461 times (5.20ms+0s) by LWP::Protocol::http::request at line 155, avg 11µs/call | ||
| 69 | #my($self, $req, $sock) = @_; | ||||
| 70 | } | ||||
| 71 | |||||
| 72 | sub _get_sock_info | ||||
| 73 | # spent 292ms (29.8+262) within LWP::Protocol::http::_get_sock_info which was called 461 times, avg 633µs/call:
# 461 times (29.8ms+262ms) by LWP::Protocol::http::request at line 328, avg 633µs/call | ||||
| 74 | 461 | 2.52ms | my($self, $res, $sock) = @_; | ||
| 75 | 461 | 25.9ms | 1383 | 262ms | if (defined(my $peerhost = $sock->peerhost)) { # spent 109ms making 460 calls to HTTP::Message::__ANON__[(eval 0)[HTTP/Message.pm:371]:1], avg 236µs/call
# spent 93.5ms making 461 calls to IO::Socket::INET::peerhost, avg 203µs/call
# spent 59.1ms making 461 calls to IO::Socket::INET::peerport, avg 128µs/call
# spent 197µs making 1 call to HTTP::Message::AUTOLOAD |
| 76 | $res->header("Client-Peer" => "$peerhost:" . $sock->peerport); | ||||
| 77 | } | ||||
| 78 | } | ||||
| 79 | |||||
| 80 | sub _fixup_header | ||||
| 81 | # spent 138ms (34.4+104) within LWP::Protocol::http::_fixup_header which was called 461 times, avg 300µs/call:
# 461 times (34.4ms+104ms) by LWP::Protocol::http::request at line 159, avg 300µs/call | ||||
| 82 | 461 | 2.98ms | my($self, $h, $url, $proxy) = @_; | ||
| 83 | |||||
| 84 | # Extract 'Host' header | ||||
| 85 | 461 | 9.14ms | 461 | 30.7ms | my $hhost = $url->authority; # spent 30.7ms making 461 calls to URI::_generic::authority, avg 67µs/call |
| 86 | 461 | 9.02ms | 461 | 2.89ms | if ($hhost =~ s/^([^\@]*)\@//) { # get rid of potential "user:pass@" # spent 2.89ms making 461 calls to LWP::Protocol::http::CORE:subst, avg 6µs/call |
| 87 | # add authorization header if we need them. HTTP URLs do | ||||
| 88 | # not really support specification of user and password, but | ||||
| 89 | # we allow it. | ||||
| 90 | if (defined($1) && not $h->header('Authorization')) { | ||||
| 91 | require URI::Escape; | ||||
| 92 | $h->authorization_basic(map URI::Escape::uri_unescape($_), | ||||
| 93 | split(":", $1, 2)); | ||||
| 94 | } | ||||
| 95 | } | ||||
| 96 | 461 | 8.41ms | 461 | 70.2ms | $h->init_header('Host' => $hhost); # spent 70.2ms making 461 calls to HTTP::Headers::init_header, avg 152µs/call |
| 97 | |||||
| 98 | 461 | 6.27ms | if ($proxy) { | ||
| 99 | # Check the proxy URI's userinfo() for proxy credentials | ||||
| 100 | # export http_proxy="http://proxyuser:proxypass@proxyhost:port" | ||||
| 101 | my $p_auth = $proxy->userinfo(); | ||||
| 102 | if(defined $p_auth) { | ||||
| 103 | require URI::Escape; | ||||
| 104 | $h->proxy_authorization_basic(map URI::Escape::uri_unescape($_), | ||||
| 105 | split(":", $p_auth, 2)) | ||||
| 106 | } | ||||
| 107 | } | ||||
| 108 | } | ||||
| 109 | |||||
| 110 | sub hlist_remove { | ||||
| 111 | my($hlist, $k) = @_; | ||||
| 112 | $k = lc $k; | ||||
| 113 | for (my $i = @$hlist - 2; $i >= 0; $i -= 2) { | ||||
| 114 | next unless lc($hlist->[$i]) eq $k; | ||||
| 115 | splice(@$hlist, $i, 2); | ||||
| 116 | } | ||||
| 117 | } | ||||
| 118 | |||||
| 119 | sub request | ||||
| 120 | # spent 146s (576ms+146) within LWP::Protocol::http::request which was called 461 times, avg 318ms/call:
# 461 times (576ms+146s) by LWP::UserAgent::send_request at line 215 of LWP/UserAgent.pm, avg 318ms/call | ||||
| 121 | 461 | 2.94ms | my($self, $request, $proxy, $arg, $size, $timeout) = @_; | ||
| 122 | 461 | 6.85ms | 461 | 5.17ms | LWP::Debug::trace('()'); # spent 5.17ms making 461 calls to LWP::Debug::trace, avg 11µs/call |
| 123 | |||||
| 124 | 461 | 2.27ms | $size ||= 4096; | ||
| 125 | |||||
| 126 | # check method | ||||
| 127 | 461 | 8.12ms | 461 | 26.3ms | my $method = $request->method; # spent 26.3ms making 461 calls to HTTP::Request::method, avg 57µs/call |
| 128 | 461 | 10.5ms | 461 | 4.13ms | unless ($method =~ /^[A-Za-z0-9_!\#\$%&\'*+\-.^\`|~]+$/) { # HTTP token # spent 4.13ms making 461 calls to LWP::Protocol::http::CORE:match, avg 9µs/call |
| 129 | return new HTTP::Response &HTTP::Status::RC_BAD_REQUEST, | ||||
| 130 | 'Library does not allow method ' . | ||||
| 131 | "$method for 'http:' URLs"; | ||||
| 132 | } | ||||
| 133 | |||||
| 134 | 461 | 7.96ms | 461 | 12.2ms | my $url = $request->url; # spent 12.2ms making 461 calls to HTTP::Request::uri, avg 26µs/call |
| 135 | 461 | 2.13ms | my($host, $port, $fullpath); | ||
| 136 | |||||
| 137 | # Check if we're proxy'ing | ||||
| 138 | 461 | 4.30ms | if (defined $proxy) { | ||
| 139 | # $proxy is an URL to an HTTP server which will proxy this request | ||||
| 140 | $host = $proxy->host; | ||||
| 141 | $port = $proxy->port; | ||||
| 142 | $fullpath = $method eq "CONNECT" ? | ||||
| 143 | ($url->host . ":" . $url->port) : | ||||
| 144 | $url->as_string; | ||||
| 145 | } | ||||
| 146 | else { | ||||
| 147 | 461 | 9.09ms | 461 | 88.7ms | $host = $url->host; # spent 88.7ms making 461 calls to URI::_server::host, avg 192µs/call |
| 148 | 461 | 8.18ms | 461 | 79.2ms | $port = $url->port; # spent 79.2ms making 461 calls to URI::_server::port, avg 172µs/call |
| 149 | 461 | 8.62ms | 461 | 26.6ms | $fullpath = $url->path_query; # spent 26.6ms making 461 calls to URI::_generic::path_query, avg 58µs/call |
| 150 | 461 | 9.47ms | 461 | 2.92ms | $fullpath = "/$fullpath" unless $fullpath =~ m,^/,; # spent 2.92ms making 461 calls to LWP::Protocol::http::CORE:match, avg 6µs/call |
| 151 | } | ||||
| 152 | |||||
| 153 | # connect to remote site | ||||
| 154 | 461 | 8.75ms | 461 | 49.6s | my $socket = $self->_new_socket($host, $port, $timeout); # spent 49.6s making 461 calls to LWP::Protocol::http::_new_socket, avg 108ms/call |
| 155 | 461 | 8.09ms | 461 | 5.20ms | $self->_check_sock($request, $socket); # spent 5.20ms making 461 calls to LWP::Protocol::http::_check_sock, avg 11µs/call |
| 156 | |||||
| 157 | 461 | 2.12ms | my @h; | ||
| 158 | 461 | 14.0ms | 922 | 202ms | my $request_headers = $request->headers->clone; # spent 196ms making 461 calls to HTTP::Headers::clone, avg 425µs/call
# spent 6.25ms making 461 calls to HTTP::Message::headers, avg 14µs/call |
| 159 | 461 | 9.17ms | 461 | 138ms | $self->_fixup_header($request_headers, $url, $proxy); # spent 138ms making 461 calls to LWP::Protocol::http::_fixup_header, avg 300µs/call |
| 160 | |||||
| 161 | # spent 50.9ms (42.0+8.96) within LWP::Protocol::http::__ANON__[/project/perl/lib/LWP/Protocol/http.pm:166] which was called 922 times, avg 55µs/call:
# 922 times (42.0ms+8.96ms) by HTTP::Headers::scan at line 217 of HTTP/Headers.pm, avg 55µs/call | ||||
| 162 | 922 | 6.42ms | my($k, $v) = @_; | ||
| 163 | 922 | 16.6ms | 922 | 4.44ms | $k =~ s/^://; # spent 4.44ms making 922 calls to LWP::Protocol::http::CORE:subst, avg 5µs/call |
| 164 | 922 | 14.4ms | 922 | 4.52ms | $v =~ s/\n/ /g; # spent 4.52ms making 922 calls to LWP::Protocol::http::CORE:subst, avg 5µs/call |
| 165 | 922 | 13.9ms | push(@h, $k, $v); | ||
| 166 | 461 | 18.8ms | 461 | 143ms | }); # spent 143ms making 461 calls to HTTP::Headers::scan, avg 310µs/call |
| 167 | |||||
| 168 | 461 | 9.07ms | 461 | 22.8ms | my $content_ref = $request->content_ref; # spent 22.8ms making 461 calls to HTTP::Message::content_ref, avg 50µs/call |
| 169 | 461 | 2.21ms | $content_ref = $$content_ref if ref($$content_ref); | ||
| 170 | 461 | 1.93ms | my $chunked; | ||
| 171 | 461 | 2.01ms | my $has_content; | ||
| 172 | |||||
| 173 | 461 | 4.86ms | if (ref($content_ref) eq 'CODE') { | ||
| 174 | my $clen = $request_headers->header('Content-Length'); | ||||
| 175 | $has_content++ if $clen; | ||||
| 176 | unless (defined $clen) { | ||||
| 177 | push(@h, "Transfer-Encoding" => "chunked"); | ||||
| 178 | $has_content++; | ||||
| 179 | $chunked++; | ||||
| 180 | } | ||||
| 181 | } | ||||
| 182 | else { | ||||
| 183 | # Set (or override) Content-Length header | ||||
| 184 | 461 | 8.38ms | 461 | 77.6ms | my $clen = $request_headers->header('Content-Length'); # spent 77.6ms making 461 calls to HTTP::Headers::header, avg 168µs/call |
| 185 | 461 | 2.71ms | if (defined($$content_ref) && length($$content_ref)) { | ||
| 186 | $has_content = length($$content_ref); | ||||
| 187 | if (!defined($clen) || $clen ne $has_content) { | ||||
| 188 | if (defined $clen) { | ||||
| 189 | warn "Content-Length header value was wrong, fixed"; | ||||
| 190 | hlist_remove(\@h, 'Content-Length'); | ||||
| 191 | } | ||||
| 192 | push(@h, 'Content-Length' => $has_content); | ||||
| 193 | } | ||||
| 194 | } | ||||
| 195 | elsif ($clen) { | ||||
| 196 | warn "Content-Length set when there is no content, fixed"; | ||||
| 197 | hlist_remove(\@h, 'Content-Length'); | ||||
| 198 | } | ||||
| 199 | } | ||||
| 200 | |||||
| 201 | 461 | 2.10ms | my $write_wait = 0; | ||
| 202 | 461 | 14.6ms | 922 | 75.3ms | $write_wait = 2 # spent 73.0ms making 461 calls to HTTP::Headers::header, avg 158µs/call
# spent 2.29ms making 461 calls to LWP::Protocol::http::CORE:match, avg 5µs/call |
| 203 | if ($request_headers->header("Expect") || "") =~ /100-continue/; | ||||
| 204 | |||||
| 205 | 461 | 9.81ms | 461 | 350ms | my $req_buf = $socket->format_request($method, $fullpath, @h); # spent 350ms making 461 calls to Net::HTTP::Methods::format_request, avg 759µs/call |
| 206 | #print "------\n$req_buf\n------\n"; | ||||
| 207 | |||||
| 208 | 461 | 4.31ms | if (!$has_content || $write_wait || $has_content > 8*1024) { | ||
| 209 | # XXX need to watch out for write timeouts | ||||
| 210 | 461 | 10.0ms | 461 | 37.2ms | my $n = $socket->syswrite($req_buf, length($req_buf)); # spent 37.2ms making 461 calls to IO::Handle::syswrite, avg 81µs/call |
| 211 | 461 | 2.29ms | die $! unless defined($n); | ||
| 212 | 461 | 2.47ms | die "short write" unless $n == length($req_buf); | ||
| 213 | #LWP::Debug::conns($req_buf); | ||||
| 214 | 461 | 2.62ms | $req_buf = ""; | ||
| 215 | } | ||||
| 216 | |||||
| 217 | 461 | 2.36ms | my($code, $mess, @junk); | ||
| 218 | 461 | 1.99ms | my $drop_connection; | ||
| 219 | |||||
| 220 | 461 | 2.16ms | if ($has_content) { | ||
| 221 | my $eof; | ||||
| 222 | my $wbuf; | ||||
| 223 | my $woffset = 0; | ||||
| 224 | if (ref($content_ref) eq 'CODE') { | ||||
| 225 | my $buf = &$content_ref(); | ||||
| 226 | $buf = "" unless defined($buf); | ||||
| 227 | $buf = sprintf "%x%s%s%s", length($buf), $CRLF, $buf, $CRLF | ||||
| 228 | if $chunked; | ||||
| 229 | substr($buf, 0, 0) = $req_buf if $req_buf; | ||||
| 230 | $wbuf = \$buf; | ||||
| 231 | } | ||||
| 232 | else { | ||||
| 233 | if ($req_buf) { | ||||
| 234 | my $buf = $req_buf . $$content_ref; | ||||
| 235 | $wbuf = \$buf; | ||||
| 236 | } | ||||
| 237 | else { | ||||
| 238 | $wbuf = $content_ref; | ||||
| 239 | } | ||||
| 240 | $eof = 1; | ||||
| 241 | } | ||||
| 242 | |||||
| 243 | my $fbits = ''; | ||||
| 244 | vec($fbits, fileno($socket), 1) = 1; | ||||
| 245 | |||||
| 246 | while ($woffset < length($$wbuf)) { | ||||
| 247 | |||||
| 248 | my $time_before; | ||||
| 249 | my $sel_timeout = $timeout; | ||||
| 250 | if ($write_wait) { | ||||
| 251 | $time_before = time; | ||||
| 252 | $sel_timeout = $write_wait if $write_wait < $sel_timeout; | ||||
| 253 | } | ||||
| 254 | |||||
| 255 | my $rbits = $fbits; | ||||
| 256 | my $wbits = $write_wait ? undef : $fbits; | ||||
| 257 | my $nfound = select($rbits, $wbits, undef, $sel_timeout); | ||||
| 258 | unless (defined $nfound) { | ||||
| 259 | die "select failed: $!"; | ||||
| 260 | } | ||||
| 261 | |||||
| 262 | if ($write_wait) { | ||||
| 263 | $write_wait -= time - $time_before; | ||||
| 264 | $write_wait = 0 if $write_wait < 0; | ||||
| 265 | } | ||||
| 266 | |||||
| 267 | if (defined($rbits) && $rbits =~ /[^\0]/) { | ||||
| 268 | # readable | ||||
| 269 | my $buf = $socket->_rbuf; | ||||
| 270 | my $n = $socket->sysread($buf, 1024, length($buf)); | ||||
| 271 | unless ($n) { | ||||
| 272 | die "EOF"; | ||||
| 273 | } | ||||
| 274 | $socket->_rbuf($buf); | ||||
| 275 | if ($buf =~ /\015?\012\015?\012/) { | ||||
| 276 | # a whole response present | ||||
| 277 | ($code, $mess, @h) = $socket->read_response_headers(laxed => 1, | ||||
| 278 | junk_out => \@junk, | ||||
| 279 | ); | ||||
| 280 | if ($code eq "100") { | ||||
| 281 | $write_wait = 0; | ||||
| 282 | undef($code); | ||||
| 283 | } | ||||
| 284 | else { | ||||
| 285 | $drop_connection++; | ||||
| 286 | last; | ||||
| 287 | # XXX should perhaps try to abort write in a nice way too | ||||
| 288 | } | ||||
| 289 | } | ||||
| 290 | } | ||||
| 291 | if (defined($wbits) && $wbits =~ /[^\0]/) { | ||||
| 292 | my $n = $socket->syswrite($$wbuf, length($$wbuf), $woffset); | ||||
| 293 | unless ($n) { | ||||
| 294 | die "syswrite: $!" unless defined $n; | ||||
| 295 | die "syswrite: no bytes written"; | ||||
| 296 | } | ||||
| 297 | $woffset += $n; | ||||
| 298 | |||||
| 299 | if (!$eof && $woffset >= length($$wbuf)) { | ||||
| 300 | # need to refill buffer from $content_ref code | ||||
| 301 | my $buf = &$content_ref(); | ||||
| 302 | $buf = "" unless defined($buf); | ||||
| 303 | $eof++ unless length($buf); | ||||
| 304 | $buf = sprintf "%x%s%s%s", length($buf), $CRLF, $buf, $CRLF | ||||
| 305 | if $chunked; | ||||
| 306 | $wbuf = \$buf; | ||||
| 307 | $woffset = 0; | ||||
| 308 | } | ||||
| 309 | } | ||||
| 310 | } | ||||
| 311 | } | ||||
| 312 | |||||
| 313 | 461 | 23.0ms | 461 | 93.1s | ($code, $mess, @h) = $socket->read_response_headers(laxed => 1, junk_out => \@junk) # spent 93.1s making 461 calls to Net::HTTP::Methods::read_response_headers, avg 202ms/call |
| 314 | unless $code; | ||||
| 315 | 461 | 2.54ms | ($code, $mess, @h) = $socket->read_response_headers(laxed => 1, junk_out => \@junk) | ||
| 316 | if $code eq "100"; | ||||
| 317 | |||||
| 318 | 461 | 13.6ms | 461 | 140ms | my $response = HTTP::Response->new($code, $mess); # spent 140ms making 461 calls to HTTP::Response::new, avg 304µs/call |
| 319 | 461 | 9.11ms | 461 | 13.8ms | my $peer_http_version = $socket->peer_http_version; # spent 13.8ms making 461 calls to Net::HTTP::Methods::__ANON__[Net/HTTP/Methods.pm:81], avg 30µs/call |
| 320 | 461 | 8.36ms | 461 | 26.4ms | $response->protocol("HTTP/$peer_http_version"); # spent 26.4ms making 461 calls to HTTP::Message::protocol, avg 57µs/call |
| 321 | 461 | 4.63ms | while (@h) { | ||
| 322 | 4603 | 30.4ms | my($k, $v) = splice(@h, 0, 2); | ||
| 323 | 4603 | 99.5ms | 4603 | 776ms | $response->push_header($k, $v); # spent 776ms making 4602 calls to HTTP::Message::__ANON__[(eval 0)[HTTP/Message.pm:371]:1], avg 169µs/call
# spent 183µs making 1 call to HTTP::Message::AUTOLOAD |
| 324 | } | ||||
| 325 | 461 | 2.17ms | $response->push_header("Client-Junk" => \@junk) if @junk; | ||
| 326 | |||||
| 327 | 461 | 8.42ms | 461 | 28.1ms | $response->request($request); # spent 28.1ms making 461 calls to HTTP::Response::request, avg 61µs/call |
| 328 | 461 | 8.48ms | 461 | 292ms | $self->_get_sock_info($response, $socket); # spent 292ms making 461 calls to LWP::Protocol::http::_get_sock_info, avg 633µs/call |
| 329 | |||||
| 330 | 461 | 2.21ms | if ($method eq "CONNECT") { | ||
| 331 | $response->{client_socket} = $socket; # so it can be picked up | ||||
| 332 | return $response; | ||||
| 333 | } | ||||
| 334 | |||||
| 335 | 461 | 9.26ms | 461 | 48.4ms | if (my @te = $response->remove_header('Transfer-Encoding')) { # spent 48.2ms making 460 calls to HTTP::Message::__ANON__[(eval 0)[HTTP/Message.pm:371]:1], avg 105µs/call
# spent 157µs making 1 call to HTTP::Message::AUTOLOAD |
| 336 | $response->push_header('Client-Transfer-Encoding', \@te); | ||||
| 337 | } | ||||
| 338 | 461 | 14.1ms | 922 | 90.2ms | $response->push_header('Client-Response-Num', $socket->increment_response_count); # spent 80.8ms making 461 calls to HTTP::Message::__ANON__[(eval 0)[HTTP/Message.pm:371]:1], avg 175µs/call
# spent 9.49ms making 461 calls to LWP::Protocol::http::SocketMethods::increment_response_count, avg 21µs/call |
| 339 | |||||
| 340 | 461 | 2.12ms | my $complete; | ||
| 341 | # spent 91.0ms (32.0+59.1) within LWP::Protocol::http::__ANON__[/project/perl/lib/LWP/Protocol/http.pm:352] which was called 468 times, avg 195µs/call:
# 461 times (31.5ms+57.0ms) by LWP::Protocol::collect at line 112 of LWP/Protocol.pm, avg 192µs/call
# 7 times (458µs+2.08ms) by LWP::Protocol::collect at line 119 of LWP/Protocol.pm, avg 362µs/call | ||||
| 342 | 468 | 2.58ms | my $buf = ""; #prevent use of uninitialized value in SSLeay.xs | ||
| 343 | 468 | 2.00ms | my $n; | ||
| 344 | 468 | 9.07ms | 468 | 59.1ms | READ: # spent 59.1ms making 468 calls to Net::HTTP::Methods::read_entity_body, avg 126µs/call |
| 345 | { | ||||
| 346 | 468 | 4.05ms | $n = $socket->read_entity_body($buf, $size); | ||
| 347 | 468 | 2.12ms | die "Can't read entity body: $!" unless defined $n; | ||
| 348 | 468 | 2.43ms | redo READ if $n == -1; | ||
| 349 | } | ||||
| 350 | 468 | 2.31ms | $complete++ if !$n; | ||
| 351 | 468 | 6.03ms | return \$buf; | ||
| 352 | 461 | 23.9ms | 461 | 515ms | } ); # spent 515ms making 461 calls to LWP::Protocol::collect, avg 1.12ms/call |
| 353 | 461 | 2.00ms | $drop_connection++ unless $complete; | ||
| 354 | |||||
| 355 | 461 | 9.61ms | 461 | 9.99ms | @h = $socket->get_trailers; # spent 9.99ms making 461 calls to Net::HTTP::Methods::get_trailers, avg 22µs/call |
| 356 | 461 | 4.55ms | while (@h) { | ||
| 357 | my($k, $v) = splice(@h, 0, 2); | ||||
| 358 | $response->push_header($k, $v); | ||||
| 359 | } | ||||
| 360 | |||||
| 361 | # keep-alive support | ||||
| 362 | 461 | 4.25ms | unless ($drop_connection) { | ||
| 363 | 461 | 3.39ms | if (my $conn_cache = $self->{ua}{conn_cache}) { | ||
| 364 | my %connection = map { (lc($_) => 1) } | ||||
| 365 | split(/\s*,\s*/, ($response->header("Connection") || "")); | ||||
| 366 | if (($peer_http_version eq "1.1" && !$connection{close}) || | ||||
| 367 | $connection{"keep-alive"}) | ||||
| 368 | { | ||||
| 369 | LWP::Debug::debug("Keep the http connection to $host:$port"); | ||||
| 370 | $conn_cache->deposit("http", "$host:$port", $socket); | ||||
| 371 | } | ||||
| 372 | } | ||||
| 373 | } | ||||
| 374 | |||||
| 375 | 461 | 8.38ms | $response; | ||
| 376 | } | ||||
| 377 | |||||
| 378 | |||||
| 379 | #----------------------------------------------------------- | ||||
| 380 | package LWP::Protocol::http::SocketMethods; | ||||
| 381 | |||||
| 382 | # spent 92.1s (31.2ms+92.1) within LWP::Protocol::http::SocketMethods::sysread which was called 468 times, avg 197ms/call:
# 461 times (30.7ms+92.0s) by Net::HTTP::Methods::my_readline at line 232 of Net/HTTP/Methods.pm, avg 200ms/call
# 7 times (408µs+703µs) by Net::HTTP::Methods::my_read at line 213 of Net/HTTP/Methods.pm, avg 159µs/call | ||||
| 383 | 468 | 2.29ms | my $self = shift; | ||
| 384 | 468 | 5.09ms | if (my $timeout = ${*$self}{io_socket_timeout}) { | ||
| 385 | 468 | 8.06ms | 468 | 92.0s | die "read timeout" unless $self->can_read($timeout); # spent 92.0s making 468 calls to LWP::Protocol::http::SocketMethods::can_read, avg 197ms/call |
| 386 | } | ||||
| 387 | else { | ||||
| 388 | # since we have made the socket non-blocking we | ||||
| 389 | # use select to wait for some data to arrive | ||||
| 390 | $self->can_read(undef) || die "Assert"; | ||||
| 391 | } | ||||
| 392 | 468 | 32.1ms | 468 | 18.1ms | sysread($self, $_[0], $_[1], $_[2] || 0); # spent 18.1ms making 468 calls to LWP::Protocol::http::SocketMethods::CORE:sysread, avg 39µs/call |
| 393 | } | ||||
| 394 | |||||
| 395 | # spent 92.0s (32.4ms+92.0) within LWP::Protocol::http::SocketMethods::can_read which was called 468 times, avg 197ms/call:
# 468 times (32.4ms+92.0s) by LWP::Protocol::http::SocketMethods::sysread at line 385, avg 197ms/call | ||||
| 396 | 468 | 2.38ms | my($self, $timeout) = @_; | ||
| 397 | 468 | 2.43ms | my $fbits = ''; | ||
| 398 | 468 | 4.36ms | vec($fbits, fileno($self), 1) = 1; | ||
| 399 | 468 | 92.0s | 468 | 92.0s | my $nfound = select($fbits, undef, undef, $timeout); # spent 92.0s making 468 calls to LWP::Protocol::http::SocketMethods::CORE:sselect, avg 197ms/call |
| 400 | 468 | 2.46ms | die "select failed: $!" unless defined $nfound; | ||
| 401 | 468 | 10.8ms | return $nfound > 0; | ||
| 402 | } | ||||
| 403 | |||||
| 404 | sub ping { | ||||
| 405 | my $self = shift; | ||||
| 406 | !$self->can_read(0); | ||||
| 407 | } | ||||
| 408 | |||||
| 409 | # spent 9.49ms within LWP::Protocol::http::SocketMethods::increment_response_count which was called 461 times, avg 21µs/call:
# 461 times (9.49ms+0s) by LWP::Protocol::http::request at line 338, avg 21µs/call | ||||
| 410 | 461 | 2.35ms | my $self = shift; | ||
| 411 | 461 | 7.82ms | return ++${*$self}{'myhttp_response_count'}; | ||
| 412 | } | ||||
| 413 | |||||
| 414 | #----------------------------------------------------------- | ||||
| 415 | package LWP::Protocol::http::Socket; | ||||
| 416 | 3 | 142µs | 1 | 149µs | use vars qw(@ISA); # spent 149µs making 1 call to vars::import |
| 417 | 1 | 6µs | @ISA = qw(LWP::Protocol::http::SocketMethods Net::HTTP); | ||
| 418 | |||||
| 419 | 1 | 14µs | 1; | ||
# spent 9.34ms within LWP::Protocol::http::CORE:match which was called 1383 times, avg 7µs/call:
# 461 times (4.13ms+0s) by LWP::Protocol::http::request at line 128 of LWP/Protocol/http.pm, avg 9µs/call
# 461 times (2.92ms+0s) by LWP::Protocol::http::request at line 150 of LWP/Protocol/http.pm, avg 6µs/call
# 461 times (2.29ms+0s) by LWP::Protocol::http::request at line 202 of LWP/Protocol/http.pm, avg 5µs/call | |||||
# spent 11.8ms within LWP::Protocol::http::CORE:subst which was called 2305 times, avg 5µs/call:
# 922 times (4.52ms+0s) by LWP::Protocol::http::__ANON__[/project/perl/lib/LWP/Protocol/http.pm:166] at line 164 of LWP/Protocol/http.pm, avg 5µs/call
# 922 times (4.44ms+0s) by LWP::Protocol::http::__ANON__[/project/perl/lib/LWP/Protocol/http.pm:166] at line 163 of LWP/Protocol/http.pm, avg 5µs/call
# 461 times (2.89ms+0s) by LWP::Protocol::http::_fixup_header at line 86 of LWP/Protocol/http.pm, avg 6µs/call | |||||
# spent 92.0s within LWP::Protocol::http::SocketMethods::CORE:sselect which was called 468 times, avg 197ms/call:
# 468 times (92.0s+0s) by LWP::Protocol::http::SocketMethods::can_read at line 399 of LWP/Protocol/http.pm, avg 197ms/call | |||||
# spent 18.1ms within LWP::Protocol::http::SocketMethods::CORE:sysread which was called 468 times, avg 39µs/call:
# 468 times (18.1ms+0s) by LWP::Protocol::http::SocketMethods::sysread at line 392 of LWP/Protocol/http.pm, avg 39µs/call |