3

特定の https Web サイトでresponse_dataとresponse_doneイベントを処理する間に約 120 秒の遅延があることに気付きました。WWW::Mechanize私は通常の Web ブラウザで確認しましたが、このような遅さは経験していないので、何か間違っているのではないかと思います。

イベントを追跡するために私がしたことは次のとおりです（何らかの理由でuse LWP::Debug qw(+)何もしませんでした）：

use WWW::Mechanize;
use Time::HiRes qw(gettimeofday);
use IO::Handle;

my $mech = WWW::Mechanize->new(
  timeout     => 3,
  autocheck   => 1,       # check success of each query
  stack_depth => 0,       # no keeping history
  keep_alive  => 50,      # connection pool
);

$mech->agent_alias( 'Windows IE 6' );
open my $debugfile, '>traffic.txt';
$debugfile->autoflush(1);

$mech->add_handler( request_send => sub {
    my $cur_time = gettimeofday();
    my $req = shift;
    print $debugfile "\n$cur_time === BEGIN HTTP REQUEST ===\n";
    print $debugfile $req->dump();
    print $debugfile "\n$cur_time ===   END HTTP REQUEST ===\n";
    return
  }
);
$mech->add_handler( response_header => sub {
    my $cur_time = gettimeofday();
    my $res = shift;
    print $debugfile "\n$cur_time === GOT RESPONSE HDRS ===\n";
    print $debugfile $res->dump();
    return
  }
);
$mech->add_handler( response_data => sub {
    my $cur_time = gettimeofday();
    my $res = shift;
    my $content_length = length($res->content);
    print $debugfile "$cur_time === Got response data chunk resp size = $content_length ===\n";
    return
  }
);
$mech->add_handler( response_done => sub {
    my $cur_time = gettimeofday();
    my $res = shift;
    print $debugfile "\n$cur_time === BEGIN HTTP RESPONSE ===\n";
    print $debugfile $res->dump();
    print $debugfile "\n===   END HTTP RESPONSE ===\n";
    return
  }
);

以下はトレースの抜粋です (URL と Cookie は難読化されています)。

1347463214.24724 === BEGIN HTTP REQUEST ===
GET https://...
Accept-Encoding: gzip
Referer: https://...
User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)
Cookie: ...
Cookie2: $Version="1"

(no content)

1347463214.24724 ===   END HTTP REQUEST ===

1347463216.13134 === GOT RESPONSE HDRS ===
HTTP/1.1 200 OK
Date: Wed, 12 Sep 2012 15:20:08 GMT
Accept-Ranges: bytes
...
Server: Lotus-Domino
Content-Length: 377806
Content-Type: application/octet-stream
Last-Modified: Fri, 07 Sep 2012 06:25:33 GMT
Client-Peer: ...
Client-Response-Num: 1
Client-SSL-Cert-Issuer: ...
Client-SSL-Cert-Subject: ...
Client-SSL-Cipher: DES-CBC3-SHA
Client-SSL-Socket-Class: IO::Socket::SSL

(no content)
1347463216.48305 === Got response data chunk resp size = 4096 ===

1347463337.98131 === BEGIN HTTP RESPONSE ===
HTTP/1.1 200 OK
Date: Wed, 12 Sep 2012 15:20:08 GMT
Accept-Ranges: bytes
...
Server: Lotus-Domino
Content-Length: 377806
Content-Type: application/octet-stream
Last-Modified: Fri, 07 Sep 2012 06:25:33 GMT
Client-Date: Wed, 12 Sep 2012 15:22:17 GMT
Client-Peer: ...
Client-Response-Num: 1
Client-SSL-Cert-Issuer: ...
Client-SSL-Cert-Subject: ...
Client-SSL-Cipher: DES-CBC3-SHA
Client-SSL-Socket-Class: IO::Socket::SSL

PK\3\4\24\0\6\0\10\0\0\0!\0\x88\xBC\21Xi\2\0\0\x84\22\0\0\23\0\10\2[Content_Types].xml \xA2...
(+ 377294 more bytes not shown)

===   END HTTP RESPONSE ===

「Got response data chunk」メッセージと「BEGIN HTTP RESPONSE」メッセージの間に、121.5 秒のギャップが見られます。LWP::UserAgent全量のデータを受信した後、2 分間ハングすることがある気がします。

それがどこから来たのか手がかりはありますか？

EDITここは Wireshark のスクリーンショットです: 120 秒後に FIN/ACK メッセージを受け取ります…</p>

Wireshark の抜粋

ありがとう

4

4 に答える 4

3

あなたの取引は実際にそれだけの時間がかかっている可能性が高いと思います。のドキュメントはこれをLWP::UserAgent言います

[response_dataハンドラー]は、同じリクエストの後続のチャンクに対して再度呼び出されるTRUE値を返す必要があります

したがって、ハンドラーは何も返さないため、最初に返されたデータパケットのみをトレースします。

出力によると、最初の4KBのデータは2.2秒、つまり1秒あたり約2KBで到着します。データ全体の長さは369KBであるため、さらに92個のデータパケットを受信すると予想され、1秒あたり2KBの場合、送信には3分かかります。2分で返事が来るので時間は妥当だと思います

于 2012-09-12T16:35:53.950 に答える
3

ボロディンの答えのおかげで、私はそれを修正する方法を見つけました:

response_dataこの方法でイベント ハンドラー サブを変更しました。

if($res->header('Content-Length') == length($res->content)) {
    die "OK"; # Got whole data, not waiting for server to end the communication channel.
}
return 1; # In other cases make sure the handler is called for subsequent chunks

そして、X-Diedヘッダーが等しい場合OK、呼び出し元のエラーを無視します。

于 2012-09-12T16:59:30.903 に答える