自宅ルーターとglibcの相性問題
TL;DR
- raspberry apiからのcurl実行時間が常に5秒以上を要する状態になった[1]
- 問題の原因は自宅ルーターへのDNSへの問い合わせにあった
- それはglibcのデフォルト挙動とDNSサーバーの相性の問題だった
- glibcの挙動を変える設定を追加すると問題は解消した
検証環境はRaspberry Pi OSです。
$ uname -a
Linux rpi3 4.14.50-v7+ #1122 SMP Tue Jun 19 12:26:26 BST 2018 armv7l GNU/Linux
$ cat /etc/debian_version
9.4
通信が遅くなっていることの気づき
あるとき、curl, pingの実行に5秒以上かかることに気づきました。localhostに対してはそうではないので、この遅延は外部アクセスに限定されるものと思われます。
$ time curl -s -o /dev/null www.google.com
real 0m5.686s
user 0m0.027s
sys 0m0.043s
$ time ping -q -c 1 www.google.com
PING www.google.com(nrt20s01-in-x04.1e100.net (2404:6800:4004:806::2004)) 56 data bytes
--- www.google.com ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 5.937/5.937/5.937/0.000 ms
real 0m5.053s
user 0m0.002s
sys 0m0.021s
遅延の原因を特定する
まず、IPv4/IPv6指定で接続すると遅くないことがわかりました。
$ time curl -4 -s -o /dev/null https://www.google.com/
real 0m0.407s
user 0m0.233s
sys 0m0.029s
$ time curl -6 -s -o /dev/null https://www.google.com/
real 0m0.375s
user 0m0.184s
sys 0m0.037s
次に、遅延が発生するときどの処理に時間がかかっているのか、下記のcurlのメトリクス取得方法に従って確認しました。
するとtime_namelookupに5秒以上を要していることがわかりました。これはコマンド実行時間のほぼ全体を占める数値です。このことから、今回はIPv4/IPv6に関連する名前解決処理を改善する必要があるということがわかりました。
$ curl -w "@curl-format.txt" -o /dev/null -s "https://www.google.com/"
time_namelookup: 5.514973s
time_connect: 5.530668s
time_appconnect: 5.626983s
time_pretransfer: 5.627095s
time_redirect: 0.000000s
time_starttransfer: 5.638028s
----------
time_total: 5.638117s
問題の原因は自宅ルーターのDNSへの問い合わせにあった
IPv4/IPv6に関連する名前解決の設定項目を探るため色々とググってみたところ、resolv.confの設定が解決策になるかもしれないという情報を得ました。
If you don't want IPv6 enabled at all, you can disable IPv6 to accomplish this.
http://www.webupd8.org/2010/05/how-to-disable-ipv6-in-ubuntu-1004.html
if not, you can try adddingoptions single-requestTo your /etc/resolv.conf file. (see http://udrepper.livejournal.com/20948.html for gory details)
options single-requestの指定を追加すると良いことはわかりましたが、ところでこのsingle-requestとはどのような設定項目なのでしょう。
/etc/resolv.confのoptions single-requestとは？
options single-requestをresolv.confのmanualで確認すると、IPv6, IPv4の名前解決処理の並列実行を直列化するオプションであることがわかりました。ネットワーク機器によっては名前解決を並列実行するとタイムアウトにつながる可能性があるので、その回避作としてsingle-requestが用意されているようです。
$ man resolv.conf
single-request (since glibc 2.10)
Sets RES_SNGLKUP in _res.options. By default, glibc performs IPv4 and IPv6 lookups in parallel since version 2.9. Some appliance DNS servers cannot
handle these queries properly and make the requests time out. This option disables the behavior and makes glibc perform the IPv6 and IPv4 requests
sequentially (at the cost of some slowdown of the resolving process).
resolv.confに設定を追加して効果を見る
実際にsingle-requestの設定をresolv.confに追加して、curl実行の遅延が解消されるかを確認しました。
$ cat /etc/resolv.conf
...
options=single-request
すると、期待通り問題が解消することが確認できました。
$ time curl -s -o /dev/null www.google.com
real 0m0.216s
user 0m0.087s
sys 0m0.011s
resolv.confの設定を永続化する
設定は直接/etc/resolv.confに書いても一時的に効果は得られます。ただし再起動などによってリセットされるので、/etc/resolv.confの管理体制に応じて適切に変更作業を行う必要があります。ここではresolvconfによる管理体制下での作業を記載します。
# resolvconf の設定にオプションを追加
$ cat /etc/resolvconf.conf
...
resolv_conf_options=single-request
# オプションの反映
$ sudo ip link set eth0 down && sudo ip link set eth0 up
# resolv.confへの反映を確認
$ cat /etc/resolv.conf
options single-request
resolvconf環境でのresolv.conf編集は別記事を書きましたので、こちらも参考にしていただければと思います。
別の対策: 相性の悪いDNSサーバーを対象から外す
single-request設定追加によって問題を解消することができましたが、そもそも今回は192.168.0.1のDNSサーバーとglibcの挙動に問題の原因がありました。ですのでそのDNSサーバーをリストから外すという対応も有効です。状況に応じて対応を使い分けると良いと思います。
# 自宅ルーターのDNSサーバーは対象外にする
# nameserver 192.168.0.1
nameserver 8.8.8.8
nameserver 8.8.8.4
nameserver 2001:4860:4860::8888
nameserver 2001:4860:4860::8844
# この場合single-requestは不要
# options single-request
まとめ
今回、DNS問い合わせ処理にはサーバーとクライアントの組み合わせ次第では遅延問題が起きるということがわかりました。そして、/etc/resolv.confにoptions single-requestを記述することでglibcの挙動を変更する、もしくはDNSサーバーリストを変更する、という対応でこの遅延問題に対処できました。
ちなみに自宅ルーターはこちらの製品を利用しています。
余談1: raspberry pi以外のLinux環境でも同じ問題は起きうる
ubuntu(20.04LTS)でもresolv.confの設定次第で遅延問題が起きることを確認しています。ホストOSとしてのUbuntuでもWSL上のUbuntuでも同様でした。一方、macOSでは発生しません。
余談2: ruby, pythonなども影響をうける
余談ですが、ruby, pythonなどでglibcのgetaddrinfoを呼ぶ関数を実行する場合にも同様の問題が発生します。
resolv.confを未編集状態でのpythonの実行例を記載しますが、socket.getaddrinfoを使ってstraceで経過観察すると最初のrecvfromから次のrecvfromまで5秒間の空きがあるのが見える。これは冒頭でcurlやpingを使ったときに見られたものと同じ状況です。
$ strace -t -econnect,setsockopt,recvfrom python3 -c 'import socket; socket.getaddrinfo("www.google.com",80,family=socket.AF_UNSPEC)'
07:42:57 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
07:42:57 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
07:42:57 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.0.1")}, 16) = 0
07:42:57 recvfrom(3, "+8\201\200\0\1\0\1\0\0\0\0\3www\6google\3com\0\0\34\0\1"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.0.1")}, [28->16]) = 60
07:43:02 recvfrom(3, "\307Y\201\200\0\1\0\1\0\0\0\0\3www\6google\3com\0\0\1\0\1"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.0.1")}, [28->16]) = 48
07:43:02 recvfrom(3, "+8\201\200\0\1\0\1\0\0\0\0\3www\6google\3com\0\0\34\0\1"..., 65536, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.0.1")}, [28->16]) = 60
07:43:02 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("172.217.175.228")}, 16) = 0
07:43:02 connect(3, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "2404:6800:4004:80f::2004", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, 28) = 0
07:43:02 +++ exited with 0 +++
socket.getaddrinfoの引数にfamily=socket.AF_UNSPECを指定した場合も同様の結果になります。一方、family=socket.AF_INETやfamily=socket.AF_INET6の場合はDNS問い合わせが並列実行されないのでタイムアウトも発生しません。curlのときに-4, -6指定したときとそうでないときに違いがあったのと同じですね。
-
このRaspberry Piは稼働し始めてから3~4年が経過するのですが、雰囲気で運用していたので今更この問題に気づく結果となりました。 ↩︎
Discussion