[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