headlint を並列化したら、自分のサイトだけ遅くなった

headlint という CLI を作った。
URL を渡すと OGP・favicon・robots まわりを見て、足りないものを ✗ や ! で出してくれるやつ。

v0.2.0 でファイル分割と型付けをやり直して、ついでに速くした。速くするほうで一つ引っかかったので書いておく。

取得を並列にした

headlint はページを取ったあと、og:image、rel=icon の全部、manifest、/favicon.ico、robots.txt、Sitemap と、見つけたものを 1 件ずつ取りに行っていた。github.com だと 9 回。

どれも互いに関係ないので、std::thread::scope で全部同時に投げるようにした。依存は増えていない。

で、--validate を 3 回ずつ測った。単位は秒。

サイト	直列	並列
github.com	5.79 / 2.51 / 2.45	0.54 / 0.15 / 0.17
zenn.dev	0.24 / 0.44 / 0.20	0.09 / 0.13 / 0.09
polidog.jp	0.17 / 0.17 / 1.24	3.24 / 5.24 / 4.26

自分のサイトだけ遅くなった。 出力は直列版と同じなので、壊れてはいない。ただ遅い。

1 件ずつ時間を出す

fetch::get に経過時間を出す eprintln! を一時的に入れた。

DBG 42.000852ms https://polidog.jp None
DBG 14.227016ms https://polidog.jp/robots.txt None
DBG 32.451429ms https://polidog.jp/assets/favicon/icon-180.png None
DBG 60.13784ms https://polidog.jp/favicon.ico None
DBG 68.407055ms https://polidog.jp/assets/ogp/top.jpg None
DBG 68.617ms https://polidog.jp/favicon.ico None
DBG 1.093908388s https://polidog.jp/assets/ogp/top.jpg None
DBG 2.104461804s https://polidog.jp/assets/favicon/icon-32.png None

ほとんどは 50ms 前後で、いくつかだけ 1.09 秒と 2.10 秒。遅いのがきっちり 1 秒・2 秒に揃っている。

polidog.jp は Cloudflare の後ろにいるので、同時に来たから絞られているのかと思った。curl で同じ URL を 7 本同時に叩いてみたら、一番遅くても 0.26 秒。サーバーは悪くない。

ureq 2 は接続のたびに getaddrinfo を呼ぶので、DNS が詰まっているのかとも思った。8 スレッドで同時に引いても全部一瞬だった。

IPv6 だった

curl の結果を見直すと、time_connect が 0.208 秒のものが 3 本あって、ほかは 0.009 秒だった。この 0.2 秒は、curl の Happy Eyeballs（IPv6 がつながらなかったら 200ms で IPv4 も試す）の待ち時間に見える。

なので IPv6 と IPv4 に固定して、8 本同時を 3 回ずつやってみた。遅いほうから 4 本。

	接続にかかった時間（秒）
`curl -6`	1.06 / 2.06 / 2.25 / 4.13
`curl -4`	0.008 / 0.009 / 0.010 / 0.010

IPv6 だけ、1 秒・2 秒・4 秒で待たされている。 倍々になっていくのは、TCP の SYN が落ちて再送されたときの待ち時間と同じ形。この環境だと、IPv6 で同時に接続を張ると SYN がときどき落ちる。

curl は 0.2 秒で IPv4 に逃げていた。ureq 2 には Happy Eyeballs が無くて、解決したアドレスを順番に試すだけなので、再送をそのまま待っていた。

なぜ IPv6 で SYN が落ちるのかは、まだ分かっていない。

IPv4 を先に試す

ureq 2 には名前解決を差し替える口があるので、IPv4 が先に来るように並べ替えた。IPv6 のアドレスは後ろに残しているので、IPv6 しかないホストにもつながる。

.resolver(|addr: &str| {
    let mut addrs: Vec<_> = addr.to_socket_addrs()?.collect();
    addrs.sort_by_key(|a| a.is_ipv6());
    Ok(addrs)
})

測り直した。4 回ずつ、単位は秒。

サイト	直列	並列 + IPv4 優先
polidog.jp	1.21 / 1.19 / 0.16 / 0.16	0.11 / 0.10 / 0.12 / 0.12
github.com	0.61 / 0.29 / 0.26 / 0.22	0.14 / 0.14 / 0.13 / 0.14
zenn.dev	0.25 / 0.18 / 0.20 / 0.19	0.09 / 0.09 / 0.09 / 0.09

2〜4 倍速くなって、ばらつきも消えた。

並列にしたせいではなかった

振り返ると、遅くなった原因は並列化そのものではなく、この環境の IPv6 で SYN が落ちることと、ureq 2 に Happy Eyeballs が無いことの組み合わせだった。

直列のときも polidog.jp で 1.2 秒かかる回があったので、罠はたぶん前からあった。接続を使い回していたから踏む回数が少なかっただけで、並列にして新しい接続を一気に張るようになったら、それが表に出てきた。

Cloudflare も DNS も外れで、決め手になったのは curl の time_connect にあった 0.2 秒だった。

取得を並列にした

1 件ずつ時間を出す

IPv6 だった

IPv4 を先に試す

並列にしたせいではなかった

カテゴリ