[Solved] DNS lookups slow

by **keithspg** » Tue Apr 28, 2020 1:14 am

I have multiple RPIs winning Arch. Recently, I have noticed very slow ping response. It is not the ping times, which are actually fine, it is the first response to the request which seems to take a while on the RPI.
RPI strace on ping
$this->bbcode_second_pass_code('', '# strace -e trace=open -f ping -c2 bbc.co.uk
PING bbc.co.uk (151.101.192.81) 56(84) bytes of data.
64 bytes from 151.101.192.81 (151.101.192.81): icmp_seq=1 ttl=57 time=12.7 ms
64 bytes from 151.101.192.81 (151.101.192.81): icmp_seq=2 ttl=57 time=12.4 ms

--- bbc.co.uk ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 7877ms
rtt min/avg/max/mdev = 12.415/12.577/12.740/0.162 ms
+++ exited with 0 +++')

My ping response time is pretty good at 12ms from the USA, but the time required to get this is 7877ms! It takes almost 8 seconds to get the response. The IP address shows up almost immediately on the cli, but it takes a long time to get the response. Local lookups even mDNS is snappy. Some DNS lookups are quick but others are slow like the bbc.

If I do the same thing but with the IP address, it is fast:
$this->bbcode_second_pass_code('', '# strace -e trace=open -f ping -c2 151.101.64.81
PING 151.101.64.81 (151.101.64.81) 56(84) bytes of data.
64 bytes from 151.101.64.81: icmp_seq=1 ttl=57 time=12.5 ms
64 bytes from 151.101.64.81: icmp_seq=2 ttl=57 time=12.1 ms

--- 151.101.64.81 ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1002ms
rtt min/avg/max/mdev = 12.083/12.303/12.523/0.220 ms
+++ exited with 0 +++')

Copmpare this to my Arch desktop running x64:
$this->bbcode_second_pass_code('', '
$ strace -e trace=open -f ping -c2 bbc.co.uk
PING bbc.co.uk (151.101.64.81) 56(84) bytes of data.
64 bytes from 151.101.64.81 (151.101.64.81): icmp_seq=1 ttl=57 time=16.0 ms
64 bytes from 151.101.64.81 (151.101.64.81): icmp_seq=2 ttl=57 time=24.0 ms

--- bbc.co.uk ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1001ms
rtt min/avg/max/mdev = 16.019/20.010/24.001/3.991 ms
+++ exited with 0 +++')

My networking setup on the RPi:
Connman, Ethernet (no wifi), resolvectl is resolving all requests:
my nsswitch.conf hosts line is:
$this->bbcode_second_pass_code('', 'hosts: files resolve')
my /etc/resolv.conf is a link to /run/systemd/resolve/resolv.conf

I started looking at this as I have noticed that some processes which do lookups seem to be taking longer than normal which I thought was a problem with the program, but it looks like it may be a resolving issue...

Thanks for any help!

Keith

by **summers** » Tue Apr 28, 2020 12:00 pm

I probably don't have an answer. But what do these show:
$this->bbcode_second_pass_code('', 'resolvectl status')
$this->bbcode_second_pass_code('', 'resolvectl query bbc.co.uk')
At least then can see how resolve is set up, and what it things is going on.

Anyway lag like that probably says something time out, but on retry it worked fine. Why though is anyones guess ...

by **keithspg** » Tue Apr 28, 2020 2:07 pm

This is strange to me. I have a couple Arch desktops and a number of RPis running arch. One desktop is running systemd-resolved and the other is not. When I do a nslookup it is snappy on all machines . When I do a ping, it has about 8 seconds of delay on the RPis and it is instant on the desktops. When I do a ping -n it is instant.

This is on the rpi2 (fwiw, avahi-daemon is not running and is masked):
$this->bbcode_second_pass_code('', '# resolvectl status
Global
LLMNR setting: no
MulticastDNS setting: yes
DNSOverTLS setting: no
DNSSEC setting: no
DNSSEC supported: no
Current DNS Server: 1.1.1.1
Fallback DNS Servers: 1.1.1.1
9.9.9.10
8.8.8.8
2606:4700:4700::1111
2620:fe::10
2001:4860:4860::8888
DNSSEC NTA: 10.in-addr.arpa
16.172.in-addr.arpa
168.192.in-addr.arpa
17.172.in-addr.arpa
18.172.in-addr.arpa
19.172.in-addr.arpa
20.172.in-addr.arpa
21.172.in-addr.arpa
22.172.in-addr.arpa
23.172.in-addr.arpa
24.172.in-addr.arpa
25.172.in-addr.arpa
26.172.in-addr.arpa
27.172.in-addr.arpa
28.172.in-addr.arpa
29.172.in-addr.arpa
30.172.in-addr.arpa
31.172.in-addr.arpa
corp
d.f.ip6.arpa
home
internal
intranet
lan
local
private
test

Link 2 (eth0)
Current Scopes: mDNS/IPv4 mDNS/IPv6
DefaultRoute setting: no
LLMNR setting: no
MulticastDNS setting: yes
DNSOverTLS setting: no
DNSSEC setting: no
DNSSEC supported: no

# resolvectl query bbc.co.uk
bbc.co.uk: 151.101.192.81 -- link: eth0
151.101.128.81 -- link: eth0
151.101.64.81 -- link: eth0
151.101.0.81 -- link: eth0

-- Information acquired via protocol DNS in 28.1ms.
-- Data is authenticated: no
')

Interestingly, this is what I get on my desktop:
$this->bbcode_second_pass_code('', 'desktop:~$ time ping -c2 bbc.co.uk
PING bbc.co.uk (151.101.192.81) 56(84) bytes of data.
64 bytes from 151.101.192.81 (151.101.192.81): icmp_seq=1 ttl=57 time=11.9 ms
64 bytes from 151.101.192.81 (151.101.192.81): icmp_seq=2 ttl=57 time=12.8 ms

--- bbc.co.uk ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1002ms
rtt min/avg/max/mdev = 11.948/12.370/12.793/0.422 ms

real 0m1.022s
user 0m0.000s
sys 0m0.007s
desktop:~$ time ping -n -c2 bbc.co.uk
PING bbc.co.uk (151.101.192.81) 56(84) bytes of data.
64 bytes from 151.101.192.81: icmp_seq=1 ttl=57 time=18.6 ms
64 bytes from 151.101.192.81: icmp_seq=2 ttl=57 time=12.4 ms

--- bbc.co.uk ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1002ms
rtt min/avg/max/mdev = 12.366/15.499/18.632/3.133 ms

real 0m1.022s
user 0m0.007s
sys 0m0.000s')

And this is on a Pi2:
$this->bbcode_second_pass_code('', 'rpi2:~# time ping -c2 bbc.co.uk
PING bbc.co.uk (151.101.192.81) 56(84) bytes of data.
64 bytes from 151.101.192.81 (151.101.192.81): icmp_seq=1 ttl=57 time=11.1 ms
64 bytes from 151.101.192.81 (151.101.192.81): icmp_seq=2 ttl=57 time=11.5 ms

--- bbc.co.uk ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 7891ms
rtt min/avg/max/mdev = 11.089/11.303/11.517/0.214 ms

real 0m7.956s
user 0m0.025s
sys 0m0.009s
rpi2:~# time ping -n -c2 bbc.co.uk
PING bbc.co.uk (151.101.128.81) 56(84) bytes of data.
64 bytes from 151.101.128.81: icmp_seq=1 ttl=57 time=11.6 ms
64 bytes from 151.101.128.81: icmp_seq=2 ttl=57 time=11.2 ms

--- bbc.co.uk ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1006ms
rtt min/avg/max/mdev = 11.226/11.394/11.562/0.168 ms

real 0m1.055s
user 0m0.020s
sys 0m0.010s')

by **keithspg** » Tue Apr 28, 2020 2:21 pm

I was looking around and turned on debug info on systemd-resolved and this is the ping to bbc:
$this->bbcode_second_pass_code('', 'Apr 28 09:17:58 livingrune systemd-resolved[1329]: Sent message type=error sender=n/a destination=:1.269 path=n/a interface=n/a member=n/a cookie=793 reply_cookie=2 signature=s error-name=org.freedesktop.DBus.Error.Timeout error-message=All attempts to contact name servers or networks failed
Apr 28 09:17:58 livingrune systemd-resolved[1329]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=RemoveMatch cookie=794 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 28 09:17:58 livingrune systemd-resolved[1329]: Freeing transaction 7428.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Got message type=method_call sender=:1.270 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1 interface=org.freedesktop.resolve1.Manager member=ResolveHostname cookie=2 reply_cookie=0 signature=isit error-name=n/a error-message=n/a
Apr 28 09:19:07 livingrune systemd-resolved[1329]: idn2_lookup_u8: bbc.co.uk → bbc.co.uk
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Looking up RR for bbc.co.uk IN A.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Looking up RR for bbc.co.uk IN AAAA.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=AddMatch cookie=795 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetNameOwner cookie=796 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.70 path=n/a interface=n/a member=n/a cookie=401 reply_cookie=796 signature=s error-name=n/a error-message=n/a
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Positive cache hit for bbc.co.uk IN A
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Transaction 53407 for <bbc.co.uk IN A> on scope dns on */* now complete with <success> from cache (unsigned).
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Freeing transaction 53407.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Sent message type=method_return sender=n/a destination=:1.270 path=n/a interface=n/a member=n/a cookie=797 reply_cookie=2 signature=a(iiay)st error-name=n/a error-message=n/a
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=RemoveMatch cookie=798 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.70 path=n/a interface=n/a member=n/a cookie=400 reply_cookie=795 signature=n/a error-name=n/a error-message=n/a
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Got message type=method_call sender=:1.271 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1 interface=org.freedesktop.resolve1.Manager member=ResolveAddress cookie=2 reply_cookie=0 signature=iiayt error-name=n/a error-message=n/a
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Looking up RR for 81.64.101.151.in-addr.arpa IN PTR.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=AddMatch cookie=799 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetNameOwner cookie=800 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.70 path=n/a interface=n/a member=n/a cookie=403 reply_cookie=800 signature=s error-name=n/a error-message=n/a
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Cache miss for 81.64.101.151.in-addr.arpa IN PTR
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Transaction 37316 for <81.64.101.151.in-addr.arpa IN PTR> scope dns on */*.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Using feature level UDP+EDNS0 for transaction 37316.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Using DNS server 1.1.1.1 for transaction 37316.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Sending query packet with id 37316.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Cache miss for 81.64.101.151.in-addr.arpa IN PTR
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Transaction 16480 for <81.64.101.151.in-addr.arpa IN PTR> scope mdns on eth0/INET.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Delaying mdns transaction for 107111us.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.70 path=n/a interface=n/a member=n/a cookie=402 reply_cookie=799 signature=n/a error-name=n/a error-message=n/a
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Match type='signal',sender='org.freedesktop.DBus',path='/org/freedesktop/DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',arg0=':1.271' successfully installed.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Timeout reached on transaction 16480.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Retrying transaction 16480.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Cache miss for 81.64.101.151.in-addr.arpa IN PTR
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Transaction 16480 for <81.64.101.151.in-addr.arpa IN PTR> scope mdns on eth0/INET.
Apr 28 09:19:07 livingrune systemd-resolved[1329]: Sending query packet with id 0 on interface 2/AF_INET.
Apr 28 09:19:08 livingrune systemd-resolved[1329]: Timeout reached on transaction 16480.
Apr 28 09:19:08 livingrune systemd-resolved[1329]: Retrying transaction 16480.
Apr 28 09:19:08 livingrune systemd-resolved[1329]: Cache miss for 81.64.101.151.in-addr.arpa IN PTR
Apr 28 09:19:08 livingrune systemd-resolved[1329]: Transaction 16480 for <81.64.101.151.in-addr.arpa IN PTR> scope mdns on eth0/INET.
Apr 28 09:19:08 livingrune systemd-resolved[1329]: Sending query packet with id 0 on interface 2/AF_INET.
Apr 28 09:19:09 livingrune systemd-resolved[1329]: Processing incoming packet on transaction 37316 (rcode=NXDOMAIN).
Apr 28 09:19:09 livingrune systemd-resolved[1329]: Added NXDOMAIN cache entry for 81.64.101.151.in-addr.arpa IN ANY 3600s
Apr 28 09:19:09 livingrune systemd-resolved[1329]: Transaction 37316 for <81.64.101.151.in-addr.arpa IN PTR> on scope dns on */* now complete with <rcode-failure> from network (unsigned).
Apr 28 09:19:11 livingrune systemd-resolved[1329]: Timeout reached on transaction 16480.
Apr 28 09:19:11 livingrune systemd-resolved[1329]: Retrying transaction 16480.
Apr 28 09:19:11 livingrune systemd-resolved[1329]: Cache miss for 81.64.101.151.in-addr.arpa IN PTR
Apr 28 09:19:11 livingrune systemd-resolved[1329]: Transaction 16480 for <81.64.101.151.in-addr.arpa IN PTR> scope mdns on eth0/INET.
Apr 28 09:19:11 livingrune systemd-resolved[1329]: Sending query packet with id 0 on interface 2/AF_INET.
Apr 28 09:19:15 livingrune systemd-resolved[1329]: Timeout reached on transaction 16480.
Apr 28 09:19:15 livingrune systemd-resolved[1329]: Retrying transaction 16480.
Apr 28 09:19:15 livingrune systemd-resolved[1329]: Transaction 16480 for <81.64.101.151.in-addr.arpa IN PTR> on scope mdns on eth0/INET now complete with <attempts-max-reached> from none (unsigned).
Apr 28 09:19:15 livingrune systemd-resolved[1329]: Freeing transaction 37316.
Apr 28 09:19:15 livingrune systemd-resolved[1329]: Sent message type=error sender=n/a destination=:1.271 path=n/a interface=n/a member=n/a cookie=801 reply_cookie=2 signature=s error-name=org.freedesktop.DBus.Error.Timeout error-message=All attempts to contact name servers or networks failed
Apr 28 09:19:15 livingrune systemd-resolved[1329]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=RemoveMatch cookie=802 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 28 09:19:15 livingrune systemd-resolved[1329]: Freeing transaction 16480.')

by **summers** » Tue Apr 28, 2020 3:32 pm

Only thing that immediately stands out for me, is you are doing MulticastDNS / mDNS - me I've always had a DNS server, and default route.

So must be something going wrong with mDNS - and alas I know nothing about it. Anyway that would be where I'd look. I'll take at the logs, and see if I can see anything.

by **keithspg** » Tue Apr 28, 2020 8:15 pm

We have a winner!!

It was indeed mDNS messing with it. I had avahi masked and was trying to let systemd-resolved find the mDNS addresses. That causes the time delay of about 8 seconds per DNS ping. Maybe I wasn't 'doing it right', or something, but now I have avahi-daemon back on, added the mdns_minimal to nsswitch.conf and turned mdns off for systemd-resolved in the configuration file and all interfaces "resolvectl mdns eth0 off" and bingo, we are back with snappy pings and I can ping my *.local addresses by using avahi.

Thanks for the help!