今回はPostgreSQLにログインするために、psql -h localhost としてた時に最初のログインまでが時間がかかり、ログイン後は問題なくクエリのレスポンスが返ってきた。
psql -h 127.0.0.1では発生せず。
結論
先に結論から。
PostgreSQLに限らず発生する問題でした。
/etc/hostsに次の２行が書いてあった。
localhost 127.0.0.1
localhost ::1
この場合、psql -h localhostだと::1のIPv6アドレスのlistenポートに接続しに行く。IPv6はnftables(firewall)で全拒否してたため、接続できずタイムアウトするまで待ってからIPv4の127.0.0.1で接続しにいく動作だった。そのためログイン時間が大幅に増えた。
このような動作をするクライアントソフトの場合、PostgreSQLに限らず発生する。
/etc/hostsの::1のほうを消して解決した。
調査方法
今回はstraceコマンドを使った。strace psql -h localhost とすれば呼び出しているsystemcallがすべて表示される。ネットワークのソケット接続も表示される。
時間がかかる処理の時に一時的に出力が止まるので、その前後のstraceの結果を見る。
connect(5, {sa_family=AF_INET6, sin6_port=htons(5432), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, 28) = -1 EINPROGRESS (現在処理中の操作です)
poll([{fd=5, events=POLLOUT|POLLERR}], 1, -1
ここで長い時間止まる
) = 1 ([{fd=5, revents=POLLOUT|POLLERR|POLLHUP}])
getsockopt(5, SOL_SOCKET, SO_ERROR, [110], [4]) = 0
connect(5, {sa_family=AF_INET, sin_port=htons(5432), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (現在処理中の操作です)
するとこのようになっている。
前半の行にAF_INET6, "::1" と出ているのでIPv6の::1に接続しにいくことがわかる。その後しばらくしてから、sa_family=AF_INET, sin_addr=inet_addr("127.0.0.1") が出力されるので127.0.0.1のIPv4接続に切り替えて接続しにいったことがわかる。
今回のようなケースは、PostgreSQLの設定をいじっていても解決できない。このような場合にstraceコマンドを使うとサクッと解決できる場合がある。
straceは出力が多いので、ネットワーク関係に限定したログのみを出すなど出力を限定すると追いやすい。(-e trace=network オプション)
