5

注: 以下の履歴は削除したくありませんが、以前は Heroku の問題だと思っていましたが、そうではありません。curl と ruby​​ の Net::HTTP 経由で投稿を送信するローカル マシンの問題だと思います

私は現在、Heroku(無料)でRailsアプリの作業を始めています。アプリにテストデータを取得するために、DEV DBからテストデータを取得し、JSON REST APIに投稿するrakeタスクがあります次のようなherokuアプリ:

uri = URI.parse("http://SITENAME.herokuapp.com")
http = Net::HTTP.new(uri.host, uri.port)
request = Net::HTTP::Post.new("/users.json")
request.add_field('Content-Type', 'application/json')
request.body = {'user' => User.first.to_hash }.to_json
response = http.request(request)

何らかの理由で、すべてのリクエストにほぼ正確に 10 秒かかります。次に、一番上の行を次のように変更しました。

uri = URI.parse("http://localhost:3000")

...そして、リクエストは信じられないほど高速に処理されます。Heroku が無料版で POSTS を遅らせているかどうか知っている人はいますか? (ワーカー dyno にお金を払ってほしいので、それは理にかなっています) 最終的には有料版を購入する予定ですが、その前に DEV をもう少し進めたいと思っています。また、意図的に速度を落としていない場合は、投稿に時間がかかる理由がわかるまで、使用するのを少し躊躇します。10 秒かかっている行は次のとおりです。

response = http.request(request)

それは明らかだったと確信していますが、私はそれについて言及したいと思いました。

UPDATE 3/12 今日のログの一部を投稿したかっただけです。すべてのリクエストに 10 秒かかります。

1400
Before: 2013-03-12 21:30:33 UTC
After: 2013-03-12 21:30:43 UTC
1401
Before: 2013-03-12 21:30:43 UTC
After: 2013-03-12 21:30:54 UTC
1402
Before: 2013-03-12 21:30:54 UTC
After: 2013-03-12 21:31:04 UTC
1403
Before: 2013-03-12 21:31:04 UTC
After: 2013-03-12 21:31:14 UTC
1404
Before: 2013-03-12 21:31:14 UTC
After: 2013-03-12 21:31:24 UTC
1405
Before: 2013-03-12 21:31:24 UTC
After: 2013-03-12 21:31:34 UTC

UPDATE 3/15 ブロックの原因が Net::HTTP::Post ライブラリだけではないことを確認するために、上記と同じリクエストを curl で行い、10 秒かかりました。

curl -X POST -H "Content-type: application/json" -d {"params":{"q":"query"} http://SITENAME.herokuapp.com/users.json

遅延がどこで発生しているかを知るために (new_relic 以外で) 使用できる heroku トリックを持っている人はいますか?

UPDATE 3/15 #2 Heroku アプリで unicorn に切り替えたところ、Ruby Net::HTTP::Post とシェルからの curl の使用の両方で 10 秒の遅延が発生します。localhost に切り替えると、投稿はすぐに戻ってきます。

3/28 更新

最近のコメントによると、応答時間が非常に速いherokuログを投稿しています。

2013-03-29T03:22:06+00:00 app[web.1]: Started POST "/user.json" for IP
2013-03-29T03:22:06+00:00 app[web.1]:   Parameters: {"user"=>{data}}
2013-03-29T03:22:06+00:00 app[web.1]: Processing by UserController#create as JSON
2013-03-29T03:22:06+00:00 app[web.1]:   User Load (2.2ms)  <<<SQL>>>
2013-03-29T03:22:06+00:00 app[web.1]: Completed 200 OK in 3ms (Views: 0.1ms | ActiveRecord: 2.2ms)
2013-03-29T03:22:06+00:00 heroku[router]: at=info method=POST path=/users.json host=HOST.herokuapp.com fwd="66.31.201.99" dyno=web.1 connect=2ms service=33ms status=200 bytes=16
2013-03-29T03:22:16+00:00 app[web.1]: Started POST "/users.json" for 66.31.201.99 at 2013-03-29 03:22:16 +0000
2013-03-29T03:22:16+00:00 app[web.1]: Processing by UserController#create as JSON
2013-03-29T03:22:16+00:00 heroku[router]: at=info method=POST path=/users.json host=HOST.herokuapp.com fwd="66.31.201.99" dyno=web.1 connect=8ms service=19ms status=200 bytes=16
2013-03-29T03:22:16+00:00 app[web.1]:   Parameters: Parameters: {"user"=>{data}}
2013-03-29T03:22:16+00:00 app[web.1]:   User Load (2.0ms)  SQL
2013-03-29T03:22:16+00:00 app[web.1]: Completed 200 OK in 3ms (Views: 0.1ms | ActiveRecord: 2.0ms)

更新 3/28 #2

オンライン シェル (www.compileonline.com/execute_bash_online.php) からカールを試してみたところ、すぐに返されたので、私のマシンに問題があると思います。カールが引っかかっている場所をトラブルシューティングする方法を知っている人は誰でも. ローカルでは 10 秒ですが、オンライン シェルでは瞬時に実行される要求の形式は次のとおりです。

curl -X POST -H "Content-type: application/json" -d '{"user":"payload"}' http://APP.herokuapp.com/users.json

更新 3/28 #3

マシンの何かが原因で遅延が発生しています。以下を実行して現在のシステム時刻を取得し、詳細モードでカールを実行すると、カールが送信される前に 10 秒の遅延が発生します。

date +"%T" && curl -X POST -H "Content-type: application/json" -d '{"user":"payload"}' http://APP.herokuapp.com/users.json -v --trace-time -S

...そして出力...

00:44:16  [start time from date +"%T"]
00:44:26.653510 * About to connect() to APP.herokuapp.com port 80 (#0)
00:44:26.653632 *   Trying 184.72.248.52... connected
00:44:26.675676 > POST /users.json HTTP/1.1
00:44:26.675676 > User-Agent: curl/7.22.0 (i686-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
00:44:26.675676 > Host: APP.herokuapp.com
00:44:26.675676 > Accept: */*
00:44:26.675676 > Content-type: application/json
00:44:26.675676 > Content-Length: 653
00:44:26.675676 > 
00:44:26.675954 * upload completely sent off: 653out of 653 bytes
00:44:26.717286 < HTTP/1.1 200 OK
00:44:26.717380 < Cache-Control: max-age=0, private, must-revalidate
00:44:26.717518 < Content-Type: application/json; charset=utf-8
00:44:26.717552 < Date: Fri, 29 Mar 2013 04:44:33 GMT
00:44:26.717584 < Etag: "7363e85fe9edee6f053a4b319588c086"
00:44:26.717616 < Status: 200 OK
00:44:26.717647 < X-Rack-Cache: invalidate, pass
00:44:26.717678 < X-Request-Id: 19ff002048e4e2d5e17a8203576a4194
00:44:26.717708 < X-Runtime: 0.008901
00:44:26.717739 < X-Ua-Compatible: IE=Edge,chrome=1
00:44:26.717771 < transfer-encoding: chunked
00:44:26.717802 < Connection: keep-alive
00:44:26.717832 < 
00:44:26.717925 * Connection #0 to host APP.herokuapp.com left intact
00:44:26.717998 * Closing connection #0

最初のタイムスタンプと connect() 呼び出しの間に 10 秒の遅延があることがわかります。シェルで実行して、ホストの解決が問題であるかどうかを既に確認しようとしましたhost APP.herokuapp.comが、すぐに戻ります。

更新 3/28 #4

上記の例を更新して-4フラグを含め、ipv4 の使用を強制し、開発マシンですぐに返されるようにしました。

date +"%T" && curl -4 -X POST -H "Content-type: application/json" -d '{"user":"payload"}' http://APP.herokuapp.com/users.json -v --trace-time -S

の手順を使用して自分のマシンで ipv6 を無効にしようとしましたhttp://www.upubuntu.com/2011/05/how-to-disable-ipv6-under-ubuntu.htmlが、まだ機能していません。問題は、作成したいリクエストが Net::HTTP と HTTParty を介して行われることです。そのため、IPv6 の問題をシステム全体で修正したいので、curl のこのバンドエイドは解決策ではありません。

4

1 に答える 1

0

Heroku のログは、リクエストの処理にかかった時間について何を示していますか? ログは、使用時間に関して Heroku で実行したすべてのアプリ (開発と運用の両方) で正確です。各リクエストに 10 秒が使用されていることを示す heroku ログですか、それともクライアント側の何らかのタイミング メカニズムですか?

コード パスの一部を一時的に削除して、時間がかかっている可能性のあるものを絞り込むことができるかどうかを確認します。たとえば、複雑なビューのレンダリングをスキップして、代わりにコントローラーから直接 200 をレンダリングすることができます。次に、コントローラーのコードをコメントアウトしてみてください。時間がかかっているものが見つかるまで、さまざまな部品を取り出し続けます。

于 2013-03-27T04:14:43.580 に答える