4

The sum of the DNS queries for the following dig command take less than 200 ms to complete, but the entire command takes over 4 seconds. Why does dig +trace take so much longer than the sum of the DNS queries?

time dig @1.1.1.1 google.com +trace

; <<>> DiG 9.16.1-Ubuntu <<>> @1.1.1.1 google.com +trace
; (1 server found)
;; global options: +cmd
.           518226  IN  NS  a.root-servers.net.
.           518226  IN  NS  b.root-servers.net.
.           518226  IN  NS  c.root-servers.net.
.           518226  IN  NS  d.root-servers.net.
.           518226  IN  NS  e.root-servers.net.
.           518226  IN  NS  f.root-servers.net.
.           518226  IN  NS  g.root-servers.net.
.           518226  IN  NS  h.root-servers.net.
.           518226  IN  NS  i.root-servers.net.
.           518226  IN  NS  j.root-servers.net.
.           518226  IN  NS  k.root-servers.net.
.           518226  IN  NS  l.root-servers.net.
.           518226  IN  NS  m.root-servers.net.
.           518226  IN  RRSIG   NS 8 0 518400 20200611050000 20200529040000 48903 . UPDRbakA0IKukt7UAHMmcGhNsg7QHWkEifKreuLASnSxAYH4N+i4EDLy RniJQJswKaBaZJS1Eput7i1RUKKaryv57q4ZxgjFbQOSiwvJJAgJqoUe n/XTH8SAUwbJHFVMkpi0XlctOeeX9uLv438khUJyPkxMyTUxTHBeqRev i5kboRwLWwXA7ui+q/lNTt9NCSnBKZSk9qULvOi3WuxVCOCYrQerLDgH UKVzhDxfoS7sIGNSKw7cIq2Cq7txU1sI9A5DZLzfGZzHNFNgZVWzYmS9 gFMyDepVljc4c0RJpnzFVACKUYjAMC/wqTtybgwIhL9h+TwBiT4+323k 0gpqog==
;; Received 525 bytes from 1.1.1.1#53(1.1.1.1) in 12 ms

com.            172800  IN  NS  k.gtld-servers.net.
com.            172800  IN  NS  g.gtld-servers.net.
com.            172800  IN  NS  d.gtld-servers.net.
com.            172800  IN  NS  e.gtld-servers.net.
com.            172800  IN  NS  j.gtld-servers.net.
com.            172800  IN  NS  l.gtld-servers.net.
com.            172800  IN  NS  i.gtld-servers.net.
com.            172800  IN  NS  b.gtld-servers.net.
com.            172800  IN  NS  m.gtld-servers.net.
com.            172800  IN  NS  c.gtld-servers.net.
com.            172800  IN  NS  f.gtld-servers.net.
com.            172800  IN  NS  h.gtld-servers.net.
com.            172800  IN  NS  a.gtld-servers.net.
com.            86400   IN  DS  30909 8 2 E2D3C916F6DEEAC73294E8268FB5885044A833FC5459588F4A9184CF C41A5766
com.            86400   IN  RRSIG   DS 8 1 86400 20200611050000 20200529040000 48903 . Vloranh+Ko0eMmq+QYgOK+yTHESioE5rM6rMNCH001IQqlQ2QkHGTqbI 7V4m2gLaPRgWBcnVe6MzaiVICjs0XupPqXMoZ4NvPCpEzM/QpfVSjjZ+ EKOxxZQ+A9jn9KH36OKEoS/XIJnke2Q/liFXJwRmcw8Wac501YORtUZP H4r/N4BEkWI+jIcYbzIqeZ+PcMaRB2Of+b1loNZ9MrOb+UdVUa0qT/0i 13sop9ynCs5Zfpds15L1lFnj6Lym244KjfYnPJQjjLlWtdk17DCW9TwY KFWM/BaPUJ/6m3qveENjAnsqVu+0GBqZTdPSwpkGjIGVzGOHd1ohdr0B wRE1hA==
;; Received 1198 bytes from 192.112.36.4#53(g.root-servers.net) in 68 ms

google.com.     172800  IN  NS  ns2.google.com.
google.com.     172800  IN  NS  ns1.google.com.
google.com.     172800  IN  NS  ns3.google.com.
google.com.     172800  IN  NS  ns4.google.com.
CK0POJMG874LJREF7EFN8430QVIT8BSM.com. 86400 IN NSEC3 1 1 0 - CK0Q1GIN43N1ARRC9OSM6QPQR81H5M9A NS SOA RRSIG DNSKEY NSEC3PARAM
CK0POJMG874LJREF7EFN8430QVIT8BSM.com. 86400 IN RRSIG NSEC3 8 2 86400 20200602045009 20200526034009 39844 com. B2EYsHhknBbnBb/ztws9dVndTXw1YepK2JNj7oyVOa+YSrPZXGMn9VTs X0+TGRlQolc5paKNQQF110lip0laiACz8TNQ/R4NX3rqvYeu240/9zBZ B48qzQO/Gz4lQX8XMhv4RuLKiaeKEj/G2lN7tWT4PEo+pDZ7FLwABENi CZTfy7xE7/7xmDnt2O2NEhG0+qlDXjldIQ4uuUAFEia2eQ==
S84BDVKNH5AGDSI7F5J0O3NPRHU0G7JQ.com. 86400 IN NSEC3 1 1 0 - S84CDVS9VPREADFD6KK7PDADH0M6IO8H NS DS RRSIG
S84BDVKNH5AGDSI7F5J0O3NPRHU0G7JQ.com. 86400 IN RRSIG NSEC3 8 2 86400 20200603044553 20200527033553 39844 com. HsP3w9+t2VkMhtbIPXbZIodkSYKGnhaGahxdKz1oF3tYiHF80j/rZKQJ pbdDpHdQJ4ucc4IzUs2+Hfs9vJLZjLwGzt7LvWyq0hEfpPElWnkf+St8 Mf/vqhr99ji17WQR9LHoPympEdod4+FUOC25eITgKfK+KXXYCzs1sWs4 KbguhA6wV2YCZp0oUeQb2h+kDb9OqucJzdgtJnlcuOUVxA==
;; Received 836 bytes from 192.41.162.30#53(l.gtld-servers.net) in 88 ms

google.com.     300 IN  A   172.217.17.110
;; Received 55 bytes from 216.239.38.10#53(ns4.google.com) in 16 ms

dig @1.1.1.1 google.com +trace  0,01s user 0,02s system 0% cpu 4,214 total
Improve this question
5
  • I see no replies from ipv6 addresses. Try dig -4 ...
    – LL3
    Jun 4, 2020 at 14:31
  • 1
    What I could figure out: Might be your nameserver that tries to resolve the different gtld-servers. If you run it several times, the speed seems ok (because the nameserver cached it). So the time are just DNS lookups for g.root-servers.net, l.gtld-servers.net and ns4.google.com.
    – stoney
    Jun 4, 2020 at 15:21
  • First run here with a cold dns-cache: real 0m11,748s second run: real 0m0,205s
    – stoney
    Jun 4, 2020 at 15:23
  • The +trace flag disables recursion and queries DNS servers following the path of delegation. So nothing is being cached locally. And in fact, the slow responses seem to happen randomly, also right after fast responses for the same query.
    – Ruurtjan Pul
    Jun 5, 2020 at 7:49
  • From the man-page: "If @server is also specified, it affects only the initial query for the root zone name servers." Further queries are done with the system DNS server.
    – stoney
    Jun 7, 2020 at 14:20

2 Answers 2

Reset to default
3
+50

The 4s come from bash time utility. It reports the total runtime of the dig binary.

The 12ms, 68ms, ... are the times dig itself reports. Documentation on dig is a bit sparse (which is probably what brought you here), but this is most likely the pure runtime of the requests. Around these, dig does something other that leads to the total runtime of 4s.

For more details and confirmation, we can look into the source code. In https://gitlab.isc.org/isc-projects/bind9/-/blob/master/bin/dig/dig.c#L387 , we can see that the printed times for the individual request is a diff between two timestamps, query->time_recv and query->time_sent. Where are they set? That is a bit more complicated. In https://gitlab.isc.org/isc-projects/bind9/-/blob/master/bin/dig/dighost.c#L2949, query->time_sent is set. In recv_done(), query->time_recv is set. However, recv_done() is called as a callback by an event: In line 2941, recv_done() is passed as a callback to isc_socket_recv(). This is triggered from line 2954.

Everything that happens before or after this section counts towards the 4s, but not the individual query times. This would be general things like starting threads, which takes surprisingly long. A cursory inspection of dig.c and https://gitlab.isc.org/isc-projects/bind9/-/blob/master/lib/isc/app.c#L194 seems to indicate that dig sets up quite an infrastructure, apparently the standard application infrastructure used for tools from the bind framework. This includes event handling, tasks (probably for concurrency). This will also take some time.

The next step would probably be to get a debug version of dig and profile it. But first: Why do you need to know? And is this discrepancy always there or only for certain hosts/on certain machine? (I'm also seeing a discrepancy on my machine, but only around factor 2-3, not factor 20 like you are seeing.)

Improve this answer
1
  • Yeah, I'm wondering what else dig is doing in between queries. Is it backing off to reduce pressure on DNS servers? Is it processing something? I'm trying to fetch authoritative, non-cached DNS responses and wrap them in an API. Frequent latency over a second is definitely an issue for that use case.
    – Ruurtjan Pul
    Jun 5, 2020 at 7:52
0

These are DNS-Lookups as ISC confirms in this article at ISC.org. Your own DNS lag counts to it (if not cached).

Improve this answer

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .