[systemd-devel] high latency on systemd-resolved repsonses of LLMNR names

Paul Freeman paul at coredev.org.uk
Sun Apr 9 18:22:11 UTC 2017


Hi,
  We are seeing high latency (>100ms) when resolving local names via 
LLMNR.

systemd v233 / Gentoo

There appears to be a large delay between systemd-resolved receiving 
the udp query over 127.0.0.53:53 and when it dispatches the LLMNR query:

18:29:38.752644 clock_gettime(CLOCK_BOOTTIME, {18217, 767968786}) = 0
18:29:38.752854 recvfrom(12, NULL, 0, MSG_PEEK|MSG_TRUNC, NULL, NULL) = 
46
18:29:38.753119 recvmsg(12, {msg_name={sa_family=AF_INET, 
sin_port=htons(52277), sin_addr=inet_addr("127.0.0.1")}, 
msg_namelen=128->16, msg_iov=[{iov_base="9m\1 
\0\1\0\0\0\0\0\1\5zeusv\0\0\1\0\1\0\0)\20\0\0\0\0\0"..., iov_len=3936}], 
msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_IP, 
cmsg_type=IP_PKTINFO, cmsg_data={ipi_ifindex=if_nametoindex("lo"), 
ipi_spec_dst=inet_addr("127.0.0.53"), 
ipi_addr=inet_addr("127.0.0.53")}}, {cmsg_len=20, cmsg_level=SOL_IP, 
cmsg_type=IP_TTL, cmsg_data=[64]}], msg_controllen=56, msg_flags=0}, 0) 
= 46
18:29:38.753680 stat("/etc/hosts", {st_dev=makedev(8, 4), 
st_ino=17019407, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, 
st_blksize=4096, st_blocks=8, st_size=1213, 
st_atime=2017/01/23-05:40:35.417021678, st_mtime=2016/09/01-21:55:25, 
st_ctime=2017/03/20-01:21:31.905862840}) = 0
18:29:38.754087 stat("/etc/resolv.conf", {st_dev=makedev(8, 4), 
st_ino=1667316, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, 
st_blksize=4096, st_blocks=8, st_size=484, 
st_atime=2017/04/07-02:39:49.250057911, 
st_mtime=2017/04/07-02:26:21.445885318, 
st_ctime=2017/04/07-02:39:55.170044459}) = 0
18:29:38.754466 getrandom("G\355", 2, GRND_NONBLOCK) = 2
18:29:38.754665 stat("/etc/resolv.conf", {st_dev=makedev(8, 4), 
st_ino=1667316, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, 
st_blksize=4096, st_blocks=8, st_size=484, 
st_atime=2017/04/07-02:39:49.250057911, 
st_mtime=2017/04/07-02:26:21.445885318, 
st_ctime=2017/04/07-02:39:55.170044459}) = 0
18:29:38.755028 clock_gettime(CLOCK_BOOTTIME, {18217, 770345701}) = 0
18:29:38.755224 clock_gettime(CLOCK_BOOTTIME, {18217, 770532540}) = 0
18:29:38.755399 getrandom("$\367\2557x\301\261!", 8, GRND_NONBLOCK) = 8
18:29:38.755581 timerfd_settime(19, TFD_TIMER_ABSTIME, {it_interval={0, 
0}, it_value={18217, 960132000}}, NULL) = 0
18:29:38.755766 epoll_wait(4, [{EPOLLIN, {u32=44602104, 
u64=292102378232}}], 20, -1) = 1

<delay 194ms>

18:29:38.950146 clock_gettime(CLOCK_BOOTTIME, {18217, 965532171}) = 0
18:29:38.950445 read(19, "\1\0\0\0\0\0\0\0", 8) = 8
18:29:38.950760 sendmsg(13, {msg_name={sa_family=AF_INET, 
sin_port=htons(5355), sin_addr=inet_addr("224.0.0.252")}, 
msg_namelen=16, 
msg_iov=[{iov_base="G\355\0\0\0\1\0\0\0\0\0\0\5zeusv\0\0\1\0\1", 
iov_len=23}], msg_iovlen=1, msg_control=[{cmsg_len=28, 
cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, 
cmsg_data={ipi_ifindex=if_nametoindex("eth0"), 
ipi_spec_dst=inet_addr("0.0.0.0"), ipi_addr=inet_addr("0.0.0.0")}}], 
msg_controllen=28, msg_flags=0}, 0) = 23
18:29:38.951422 timerfd_settime(19, TFD_TIMER_ABSTIME, {it_interval={0, 
0}, it_value={18218, 278485000}}, NULL) = 0
18:29:38.951757 epoll_wait(4, [{EPOLLIN, {u32=44630672, 
u64=292102406800}}], 20, -1) = 1
18:29:38.952078 clock_gettime(CLOCK_BOOTTIME, {18217, 967408726}) = 0
18:29:38.952388 recvfrom(13, NULL, 0, MSG_PEEK|MSG_TRUNC, NULL, NULL) = 
23
18:29:38.952782 recvmsg(13, {msg_name={sa_family=AF_INET, 
sin_port=htons(5355), sin_addr=inet_addr("192.168.166.49")}, 
msg_namelen=128->16, 
msg_iov=[{iov_base="G\355\0\0\0\1\0\0\0\0\0\0\5zeusv\0\0\1\0\1", 
iov_len=3936}], msg_iovlen=1, msg_control=[{cmsg_len=28, 
cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, 
cmsg_data={ipi_ifindex=if_nametoindex("eth0"), 
ipi_spec_dst=inet_addr("192.168.166.49"), 
ipi_addr=inet_addr("224.0.0.252")}}, {cmsg_len=20, cmsg_level=SOL_IP, 
cmsg_type=IP_TTL, cmsg_data=[255]}], msg_controllen=56, msg_flags=0}, 0) 
= 23
18:29:38.953365 epoll_wait(4, [{EPOLLIN, {u32=44630672, 
u64=292102406800}}], 20, -1) = 1
18:29:38.953616 clock_gettime(CLOCK_BOOTTIME, {18217, 968941015}) = 0
18:29:38.953831 recvfrom(13, NULL, 0, MSG_PEEK|MSG_TRUNC, NULL, NULL) = 
39
18:29:38.954057 recvmsg(13, {msg_name={sa_family=AF_INET, 
sin_port=htons(5355), sin_addr=inet_addr("192.168.166.52")}, 
msg_namelen=128->16, 
msg_iov=[{iov_base="G\355\200\0\0\1\0\1\0\0\0\0\5zeusv\0\0\1\0\1\300\f\0\1\0\1\0\0\0"..., 
iov_len=3936}], msg_iovlen=1, msg_control=[{cmsg_len=28, 
cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, 
cmsg_data={ipi_ifindex=if_nametoindex("eth0"), 
ipi_spec_dst=inet_addr("192.168.166.49"), 
ipi_addr=inet_addr("192.168.166.49")}}, {cmsg_len=20, cmsg_level=SOL_IP, 
cmsg_type=IP_TTL, cmsg_data=[255]}], msg_controllen=56, msg_flags=0}, 0) 
= 39
18:29:38.954738 clock_gettime(CLOCK_BOOTTIME, {18217, 970057860}) = 0
18:29:38.954965 sendmsg(12, {msg_name={sa_family=AF_INET, 
sin_port=htons(52277), sin_addr=inet_addr("127.0.0.1")}, msg_namelen=16, 
msg_iov=[{iov_base="9m\201\200\0\1\0\1\0\0\0\1\5zeusv\0\0\1\0\1\300\f\0\1\0\1\0\0\0"..., 
iov_len=50}], msg_iovlen=1, msg_control=[{cmsg_len=28, 
cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, 
cmsg_data={ipi_ifindex=if_nametoindex("lo"), 
ipi_spec_dst=inet_addr("127.0.0.53"), ipi_addr=inet_addr("0.0.0.0")}}], 
msg_controllen=28, msg_flags=0}, 0) = 50
18:29:38.955455 timerfd_settime(19, TFD_TIMER_ABSTIME, {it_interval={0, 
0}, it_value={0, 0}}, NULL) = 0
18:29:38.956742 epoll_wait(4, ^Cstrace: Process 938 detached
  <detached ...>


A timeley LLMNR response is received back on the interface within 
~400µs.
1	0.000000	192.168.166.49	224.0.0.252	LLMNR	65	Standard query 0x3cc3 A 
zeusv
2	0.000417	192.168.166.52	192.168.166.49	LLMNR	81	Standard query 
response 0x3cc3 A zeusv A 192.168.166.52

We see no other network traffic from the test system during the query.


; <<>> DiG 9.11.0-P3 <<>> zeusv
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 14701
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 65494
;; QUESTION SECTION:
;zeusv.				IN	A

;; ANSWER SECTION:
zeusv.			30	IN	A	192.168.166.52

;; Query time: 203 msec
;; SERVER: 127.0.0.53#53(127.0.0.53)
;; WHEN: Sun Apr 09 18:29:38 BST 2017
;; MSG SIZE  rcvd: 50


~ # while true; do systemd-resolve --flush-caches; dig zeusv a | grep 
time: ; sleep 0.3; done
;; Query time: 204 msec
;; Query time: 168 msec
;; Query time: 144 msec
;; Query time: 151 msec
;; Query time: 152 msec
;; Query time: 190 msec
;; Query time: 173 msec
;; Query time: 123 msec
;; Query time: 139 msec
;; Query time: 181 msec
;; Query time: 201 msec
;; Query time: 192 msec
;; Query time: 172 msec
;; Query time: 134 msec


any help appreciated.

Paul



More information about the systemd-devel mailing list