search

txxxxc / isucon11-qualify

0 stars 0 forks source link

タイムアウトの原因を知る #16

Closed txxxxc closed 3 months ago

txxxxc commented 3 months ago

なんかタイムアウトでスコアの増加が妨げられてるっぽいけど全然分からん とりあえずタイムアウトがトラッキングできるような仕組みを作る

あとは、journalctlで監視できたりせんかな

txxxxc commented 3 months ago

まあgrepが一番まるそう

txxxxc commented 3 months ago

echoのタイムアウトのミドルウェアがあるからこれ使ってみるか https://echo.labstack.com/docs/middleware/timeout

txxxxc commented 3 months ago

一旦これを仕込んでみてベンチを取る

txxxxc commented 3 months ago

やばすぎるけど

00:11:13.140902 ERR: load: status code: 期待する HTTP ステータスコード以外が返却されました (expected: 201): 202 (POST: /api/isu)
00:11:13.375745 ERR: load: status code: 期待する HTTP ステータスコード以外が返却されました (expected: 200,304): 202 (GET: /api/isu/af32c612-e0fc-493e-8677-d03eba4f46ee)
00:11:13.813556 ERR: load: status code: 期待する HTTP ステータスコード以外が返却されました (expected: 200,304): 202 (GET: /api/isu/72c53edf-1f76-4423-93bf-eca0d43b2afc)
00:11:13.860036 ERR: load: status code: 期待する HTTP ステータスコード以外が返却されました (expected: 200,304): 202 (GET: /api/isu/72c53edf-1f76-4423-93bf-eca0d43b2afc)
00:11:14.061327 ERR: load: status code: 期待する HTTP ステータスコード以外が返却されました (expected: 200,304): 202 (GET: /api/isu/b313ea49-e201-44e3-856b-6f9cb278d705/icon)
00:11:14.072516 ERR: load: status code: 期待する HTTP ステータスコード以外が返却されました (expected: 200,304): 202 (GET: /api/isu/4c2e15d5-4225-47e7-a771-5148185b8442)
00:11:14.081635 ERR: load: status code: 期待する HTTP ステータスコード以外が返却されました (expected: 200,304): 202 (GET: /api/isu/72c53edf-1f76-4423-93bf-eca0d43b2afc)
00:11:14.231522 ERR: load: status code: 期待する HTTP ステータスコード以外が返却されました (expected: 200,304): 202 (GET: /api/isu/72c53edf-1f76-4423-93bf-eca0d43b2afc)
00:11:14.370364 ERR: load: status code: 期待する HTTP ステータスコード以外が返却されました (expected: 201): 202 (POST: /api/isu)
00:11:14.372501 ERR: load: status code: 期待する HTTP ステータスコード以外が返却されました (expected: 201): 202 (POST: /api/isu)
00:11:14.612448 ERR: load: status code: 期待する HTTP ステータスコード以外が返却されました (expected: 200,304): 202 (GET: /api/isu/efc0fd51-8746-4a1a-8e9f-4a9cfbd5e1ed)
txxxxc commented 3 months ago

これなに

2024-06-08  0:13:41 60 [Warning] Aborted connection 60 to db: 'isucondition' user: 'isucon' host: 'localhost' (Got timeout reading communication packets)
txxxxc commented 3 months ago

正直何が原因なんか分からんので、一旦タイムアウトの秒数を増やしてみる

txxxxc commented 3 months ago

ログ読んでも分からんから一旦Timeoutの機構を外してみても良さそう

txxxxc commented 3 months ago

Timeoutはずしたら治ったけどどうすんの？って感じではある。

txxxxc commented 3 months ago

なんだかんだ大体Timeout多くてどうしようかなってなってる

+-------+-----+------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| COUNT | 1XX | 2XX  | 3XX |  4XX  | 5XX | METHOD |             URI              |  MIN  |  MAX  |   SUM    |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  |
+-------+-----+------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| 51350 | 0   | 4249 | 0   | 47101 | 0   | POST   | ^/api/condition/[\w\d-]+$    | 0.004 | 0.144 | 4982.652 | 0.097 | 0.104 | 0.104 | 0.104 | 0.014  | 0.000     | 139.000    | 1541.000     | 0.030      |
| 605   | 0   | 244  | 0   | 361   | 0   | GET    | ^/api/isu/[\w\d-]+$          | 0.012 | 3.004 | 390.756  | 0.646 | 1.000 | 1.004 | 1.004 | 0.461  | 0.000     | 160.000    | 25608.000    | 42.327     |
| 512   | 0   | 169  | 0   | 343   | 0   | POST   | /api/isu                     | 0.004 | 1.008 | 355.168  | 0.694 | 1.000 | 1.004 | 1.004 | 0.388  | 0.000     | 8298.000   | 26196.000    | 51.164     |
| 178   | 0   | 49   | 0   | 129   | 0   | GET    | /api/isu                     | 0.408 | 3.000 | 130.728  | 0.734 | 1.004 | 1.004 | 3.000 | 0.528  | 0.000     | 10000.000  | 44105.000    | 247.781    |
| 261   | 0   | 196  | 0   | 65    | 0   | GET    | ^/api/isu/[\w\d-]+/icon$     | 1.000 | 3.004 | 67.084   | 0.257 | 1.000 | 1.000 | 3.000 | 0.496  | 0.000     | 135259.000 | 3817980.000  | 14628.276  |
| 223   | 0   | 80   | 0   | 143   | 0   | POST   | /api/auth                    | 0.008 | 3.008 | 48.120   | 0.216 | 1.000 | 1.000 | 3.000 | 0.514  | 0.000     | 19.000     | 1288.000     | 5.776      |
| 36    | 0   | 8    | 0   | 28    | 0   | GET    | /api/trend                   | 0.028 | 1.004 | 28.580   | 0.794 | 1.000 | 1.004 | 1.004 | 0.387  | 0.000     | 4495.000   | 33952.000    | 943.111    |
| 120   | 0   | 76   | 0   | 44    | 0   | GET    | ^/api/isu/[\w\d-]+/graph$    | 1.000 | 1.004 | 9.840    | 0.082 | 0.140 | 0.988 | 1.000 | 0.249  | 0.000     | 6875.000   | 347623.000   | 2896.858   |
| 165   | 0   | 117  | 0   | 48    | 0   | GET    | ^/api/condition/[\w\d-]+$    | 0.012 | 1.000 | 7.996    | 0.048 | 0.004 | 0.372 | 1.000 | 0.189  | 0.000     | 6382.000   | 238502.000   | 1445.467   |
| 4     | 0   | 4    | 0   | 0     | 0   | POST   | /initialize                  | 0.320 | 0.488 | 1.584    | 0.396 | 0.488 | 0.488 | 0.488 | 0.069  | 23.000    | 23.000     | 92.000       | 23.000     |
| 258   | 0   | 48   | 210 | 0     | 0   | GET    | /assets/vendor.ee7444dd.js   | 0.000 | 0.088 | 1.476    | 0.006 | 0.016 | 0.044 | 0.072 | 0.015  | 0.000     | 743417.000 | 35684016.000 | 138310.140 |
| 258   | 0   | 48   | 210 | 0     | 0   | GET    | /assets/index.23dac98b.js    | 0.000 | 0.068 | 1.376    | 0.005 | 0.012 | 0.032 | 0.052 | 0.010  | 0.000     | 26667.000  | 1280016.000  | 4961.302   |
| 258   | 0   | 48   | 210 | 0     | 0   | GET    | /assets/favicon.d0f5f504.svg | 0.000 | 0.072 | 1.368    | 0.005 | 0.012 | 0.036 | 0.056 | 0.011  | 0.000     | 592.000    | 28416.000    | 110.140    |
| 258   | 0   | 48   | 210 | 0     | 0   | GET    | /assets/index.144d8ca8.css   | 0.000 | 0.060 | 1.076    | 0.004 | 0.008 | 0.028 | 0.048 | 0.009  | 0.000     | 19066.000  | 915168.000   | 3547.163   |
| 110   | 0   | 88   | 22  | 0     | 0   | GET    | /                            | 0.004 | 0.048 | 0.508    | 0.005 | 0.012 | 0.016 | 0.024 | 0.007  | 0.000     | 528.000    | 46464.000    | 422.400    |
| 54    | 0   | 40   | 0   | 14    | 0   | GET    | /api/user/me                 | 0.000 | 0.044 | 0.416    | 0.008 | 0.020 | 0.032 | 0.044 | 0.010  | 21.000    | 45.000     | 1755.000     | 32.500     |
| 258   | 0   | 48   | 210 | 0     | 0   | GET    | /assets/logo_white.svg       | 0.000 | 0.060 | 0.416    | 0.002 | 0.004 | 0.004 | 0.044 | 0.006  | 0.000     | 3285.000   | 157680.000   | 611.163    |
| 44    | 0   | 44   | 0   | 0     | 0   | GET    | /assets/logo_orange.svg      | 0.000 | 0.044 | 0.212    | 0.005 | 0.020 | 0.024 | 0.044 | 0.011  | 3288.000  | 3288.000   | 144672.000   | 3288.000   |
| 108   | 0   | 36   | 72  | 0     | 0   | GET    | ^/isu/[\w\d-]+/condition$    | 0.000 | 0.004 | 0.096    | 0.001 | 0.004 | 0.004 | 0.004 | 0.002  | 0.000     | 528.000    | 19008.000    | 176.000    |
| 30    | 0   | 8    | 0   | 22    | 0   | POST   | /api/signout                 | 0.000 | 0.012 | 0.044    | 0.001 | 0.004 | 0.004 | 0.012 | 0.003  | 21.000    | 21.000     | 462.000      | 15.400     |
| 36    | 0   | 36   | 0   | 0     | 0   | GET    | ^/isu/[\w\d-]+/graph$        | 0.000 | 0.004 | 0.028    | 0.001 | 0.004 | 0.004 | 0.004 | 0.002  | 528.000   | 528.000    | 19008.000    | 528.000    |
| 36    | 0   | 36   | 0   | 0     | 0   | GET    | ^/isu/[\w\d-]+$              | 0.004 | 0.004 | 0.028    | 0.001 | 0.004 | 0.004 | 0.004 | 0.002  | 528.000   | 528.000    | 19008.000    | 528.000    |
| 12    | 0   | 4    | 8   | 0     | 0   | GET    | /register                    | 0.004 | 0.004 | 0.008    | 0.001 | 0.004 | 0.004 | 0.004 | 0.001  | 0.000     | 528.000    | 2112.000     | 176.000    |
| 1     | 0   | 0    | 0   | 1     | 0   | GET    | /index.asp                   | 0.000 | 0.000 | 0.000    | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 71.000    | 71.000     | 71.000       | 71.000     |
+-------+-----+------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
txxxxc commented 3 months ago

まじで何が原因変わらんｗ

txxxxc commented 3 months ago

ログ見たらだいたい499が多かった この499でタイムアウトが多いのが良くないのか；；

txxxxc commented 3 months ago

なんか普通にベンチマークのインスタンスと性能ちゃいすぎる説ない？

txxxxc commented 3 months ago

499とは↓

499エラーは、Nginx特有のエラーコードで、クライアントがリクエストをキャンセルしたことを示します。

具体的には、以下の状況で発生します。

* **クライアント側のタイムアウト:** クライアントが設定したタイムアウト時間内にサーバーからの応答がなかった場合。
* **クライアントによるリクエストのキャンセル:** ユーザーがブラウザの「停止」ボタンを押す、ページをリロードする、または他のページに移動するなど、何らかの理由でリクエストをキャンセルした場合。

499エラーは、サーバーがレスポンスを送信する前にクライアントが接続を閉じたため、実際のHTTPステータスコードとしてはクライアントに返されません。代わりに、Nginxのエラーログに記録されます。

499エラーが発生する原因としては、以下のようなものが考えられます。

* **サーバー側の問題:**
    * サーバーの過負荷
    * スクリプトの実行時間の長さ
    * ネットワークの遅延
* **クライアント側の問題:**
    * クライアントのネットワーク環境の不安定さ
    * クライアントの設定ミス

499エラーが発生した場合、まずはサーバー側の問題がないか確認し、問題があれば修正を試みてください。
もしサーバー側に問題がない場合は、クライアント側の問題を疑い、ネットワーク環境の改善や設定の見直しなどを検討してください。

参考情報:

* 【5つの方法】HTTP 499エラーを解決するには - Kinsta: [https://kinsta.com/jp/knowledgebase/499-error/](https://kinsta.com/jp/knowledgebase/499-error/)
* Nginxのステータスコード499とは - ISU ﾜｻﾞｯﾌﾟ: [https://scrapbox.io/isuwazap/Nginx%E3%81%AE%E3%82%B9%E3%83%86%E3%83%BC%E3%82%BF%E3%82%B9%E3%82%B3%E3%83%BC%E3%83%89499%E3%81%A8%E3%81%AF](https://scrapbox.io/isuwazap/Nginx%E3%81%AE%E3%82%B9%E3%83%86%E3%83%BC%E3%82%BF%E3%82%B9%E3%82%B3%E3%83%BC%E3%83%89499%E3%81%A8%E3%81%AF)

これらの情報が、499エラーの理解に役立つことを願っています。

nginx特有って何

txxxxc commented 3 months ago

これで499多発は流石につらすぎないか

+-------+--------+------------------------------+-------+-------+-------+----------+
| COUNT | METHOD |             URI              |  MIN  |  AVG  |  MAX  |   SUM    |
+-------+--------+------------------------------+-------+-------+-------+----------+
| 51350 | POST   | ^/api/condition/[\w\d-]+$    | 0.004 | 0.097 | 0.144 | 4982.652 |

読み込みの遅いサイトでクライアントが痺れを切らして途中でロードを止めたりすると発生する。

https://scrapbox.io/isuwazap/Nginx%E3%81%AE%E3%82%B9%E3%83%86%E3%83%BC%E3%82%BF%E3%82%B9%E3%82%B3%E3%83%BC%E3%83%89499%E3%81%A8%E3%81%AF

txxxxc commented 3 months ago

dbの接続数のやつ忘れたなんやっけ

txxxxc commented 3 months ago

てかそもそもタイムアウトのやつで死ぬ原因が分からん 一旦300秒くらいにしてみる？

txxxxc commented 3 months ago

ここ10でした犯罪すぎる

    db.SetMaxOpenConns(2000)
txxxxc commented 3 months ago

なんかあんまりこれ変えても一緒でしたわ；；

txxxxc commented 3 months ago

これ変えたらめちゃくちゃ固まった てかそもそも#7でランダムのPOSTドロップ解消したけど、解消前でもリクエスト捌ききれてなかったのに、リクエスト数増やしても意味ないやんではある。なので、一旦revertしたほうがいい説あります。

一定確率でドロップされる条件で捌ききれるようになったら追加しましょう。

てか、タイムアウトの原因は何？

txxxxc commented 3 months ago

もうちょいタイムアウトのやつ見てみますか ていうかminimum reproductionが求められるかもしれん タイム・アウトしたときにどのようなレスポンスが返されるか知らん https://echo.labstack.com/docs/middleware/timeout

txxxxc commented 3 months ago

以下のコードだと良く分からんけど200が返ってくるようになるっぽい。

package main

import (
    "time"

    "github.com/labstack/echo/v4"
    "github.com/labstack/echo/v4/middleware"
)

// main server function

func main() {

    e := echo.New()
    e.Use(middleware.Logger())
    e.Use(middleware.Recover())
    e.Use(middleware.TimeoutWithConfig(middleware.TimeoutConfig{
        Skipper:      middleware.DefaultSkipper,
        ErrorMessage: "custom timeout error message returns to client",
        OnTimeoutRouteErrorHandler: func(err error, c echo.Context) {
            c.Logger().Errorf("Timeout path: %s", c.Path())
        },
        Timeout: 5 * time.Second,
    }))
    e.GET("/", func(c echo.Context) error {
        // wait for 10 seconds
        time.Sleep(10 * time.Second)
        // returns response
        return c.String(200, "Hello, World!")
    })
    // run server
    e.Logger.Fatal(e.Start(":8080"))
}


## server log
{"time":"2024-06-08T15:26:49.505354+09:00","id":"","remote_ip":"::1","host":"localhost:8080","method":"GET","uri":"/","user_agent":"cur
l/8.6.0","status":200,"error":"","latency":5001562958,"latency_human":"5.001562958s","bytes_in":0,"bytes_out":0}
{"time":"2024-06-08T15:26:54.511756+09:00","level":"ERROR","prefix":"echo","file":"main.go","line":"21","message":"Timeout path: /"}

## curl
❯ curl http://localhost:8080
custom timeout error message returns to client
txxxxc commented 3 months ago

一旦503が帰ってるぽいです。 これでなぜバグるのか

* Host localhost:8080 was resolved.
* IPv6: ::1
* IPv4: 127.0.0.1
*   Trying [::1]:8080...
* Connected to localhost (::1) port 8080
> GET / HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/8.6.0
> Accept: */*
>
< HTTP/1.1 503 Service Unavailable
< Date: Sat, 08 Jun 2024 06:33:21 GMT
< Content-Length: 46
< Content-Type: text/plain; charset=utf-8
<
* Connection #0 to host localhost left intact
custom timeout error message returns to client⏎
txxxxc commented 3 months ago

Timeout仕込んだら202帰って来る理由、これかもしれねぇ

nginxは基本的にはAPIが出力したステータスコードをそのまま返します。しかし、特定の状況下ではnginxがステータスコードを変換する場合があります。

ステータスコードを変換する状況

proxy_intercept_errorsディレクティブが有効な場合: このディレクティブが有効になっていると、upstreamサーバー（APIサーバー）からエラーが返ってきた際に、nginxが指定したエラーページを表示し、ステータスコードを200 OKに変換します。
txxxxc commented 3 months ago

202が帰ったり、各エンドポイントで変なステータスコードが返ってくる理由は分からん。 nginxを経由したらなにかわかるかもしれん

txxxxc commented 3 months ago

でもなんかcurlでnginx叩くとsslの関係で全然うまく行きません。これなんで？

txxxxc commented 3 months ago

これでポートのListenができるらしい

sudo lsof -i -P -n | grep LISTEN
txxxxc commented 3 months ago 
このコマンドは、現在システム上でリッスン状態にあるネットワークポートと、それらのポートを使用しているプロセスを一覧表示するためのものです。

各要素の意味は以下の通りです。

* `sudo`: 管理者権限でコマンドを実行します。ネットワーク関連の情報にアクセスするために必要です。
* `lsof`: "list open files" の略で、開いているファイルやネットワークソケットを一覧表示するコマンドです。
* `-i`: ネットワーク関連のファイル (ソケット) のみを表示します。
* `-P`: ポート番号をサービス名ではなく数値で表示します。
* `-n`: IPアドレスとポート番号を名前解決せず、数値で表示します。これにより、DNSルックアップの遅延を避けることができます。
* `|`: パイプ演算子で、`lsof` の出力を `grep` コマンドに渡します。
* `grep`: 指定したパターンに一致する行を抽出するコマンドです。
* `LISTEN`: リッスン状態のソケット (つまり、接続を受け入れる準備ができているポート) を持つ行のみを抽出します。

つまり、このコマンドを実行すると、現在システム上でどのプロセスがどのポートでリッスンしているかを確認できます。これは、Webサーバーがどのポートで待ち受けているかを確認したり、セキュリティ上の問題がないかチェックしたりするのに役立ちます。
txxxxc commented 3 months ago

これバグってますやん https://github.com/labstack/echo/issues/1953

txxxxc commented 3 months ago

これでnginxのconfig知れるの知らんすぎる

sudo nginx -T
txxxxc commented 3 months ago

なんかもういったん分からんのでとりあえずやめます。 いうてlogの499を見たらわかる説。そっちの線で行くわ

txxxxc commented 3 months ago

せっかくなら高確率でドロップするやつも一緒にやるか(あんまり良い気がせんけど、いうて後で修正するならええやんってなった)

txxxxc commented 3 months ago

ドロップ復活させたらめっちゃスコア上がってて草

01:04:36.841052 score: 5491(5494 - 3) : pass
01:04:36.843469 <=== sendResult finish
01:04:36.843453 deduction: 0 / timeout: 31
txxxxc commented 3 months ago

今日の格言 今のリクエスト数も捌けてないのに、トラフィックを増やすな！

txxxxc commented 3 months ago

499(クライアント側が飽きてリロードした=Timeout)しているエンドポイント

isucon:~$ cat /var/log/nginx/access.log | grep '\"status\":\"499\"' | grep -v "POST /api/condition" | jq '.uri'
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/isu"
"/api/isu"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/isu"
"/api/trend"
"/api/isu"
"/api/isu"
"/api/isu"
"/api/trend"
"/api/trend"
"/api/isu"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/isu"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/isu"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/trend"
"/api/condition/7c4d051b-8b8d-4ff0-b0d4-d83465f7eca4?condition_level=info%2Cwarning%2Ccritical&end_time=1630319335"
"/api/isu/9e5c1109-beff-4598-b8f1-658d1994d55f"
"/api/isu/4b5162c7-836f-418f-8f35-79695eaaf263/graph?datetime=1629385200"
"/api/isu"
"/api/isu/0c0c04ce-cabe-4a6e-a629-c4a9de2db73e/icon"
"/api/isu/fea9ce9e-ea44-41e8-b486-9db2c99b0d01/icon"
"/api/isu/59738687-f042-4bc5-aa6c-3df947341dac/icon"
"/api/isu/4c29641f-53fa-4b23-9834-e379fd426198/icon"
"/api/isu/32b31f59-1788-4e94-9494-fc2181ec7939/icon"
"/api/condition/d2fdcb64-2465-4f7a-991e-e0891cdf031e?condition_level=info%2Cwarning%2Ccritical&end_time=1629514930"
"/api/condition/8414926e-18f2-4828-acef-ce8656a0134c?condition_level=info%2Cwarning%2Ccritical&end_time=1630250327"
"/api/condition/f4fa882d-5043-4890-97aa-08998ce603ae?condition_level=info%2Cwarning%2Ccritical&end_time=1628758787"
txxxxc commented 3 months ago

いったんできたっぽいのでマージします。