Is prefetch broken? #6103

jonatiao · 2023-05-19T13:33:37Z

jonatiao
May 19, 2023

Hello,
First, thx for your work on coreDNS!
Here's my question. I'm trying to avoid long queries towards a IBM service that sits on another country.
I was trying to understand prefetch, but I feel dumb reading it's documentation. I'm trying to avoid slow queries, and, by reading the documentation I believe cache { prefetch } is the way to go.. I'm open for other suggestions. ^^

I'm using minikube on windows 10. CoreDNS version is 1.9.3, I tested as well 1.10.1
16GB mem + 4 cores and 8 processors.

My config is the following:

apiVersion: v1
data:
  Corefile: |
    .:53 {
        log
        errors
        health {
           lameduck 5s
        }
        ready
        kubernetes cluster.local in-addr.arpa ip6.arpa {
           pods insecure
           fallthrough in-addr.arpa ip6.arpa
           ttl 30
        }
        prometheus :9153
        hosts {
           192.168.65.254 host.minikube.internal
           fallthrough
        }
        forward . /etc/resolv.conf {
           max_concurrent 1000
        }
        cache 60 {
           prefetch 1 30s 50%
        }
        loop
        reload
        loadbalance
    }

I know the config is being hit because if I set "cache 30", the TTL changes to 30 when I use dig, as well the log format.

Here's the command and the logs:

A) Test 1:

$ while true; do kubectl exec -i -t -n default dnsutils -- dig bla.us-south.containers.appdomain.cloud; sleep 5; done | grep -i "Query time"

;; Query time: 911 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 645 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 494 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 586 msec


A) coredns logs:
$ kubectl logs deployment/coredns -f
.:53
[INFO] plugin/reload: Running configuration SHA512 = f869070685748660180df1b7a47d58cdafcf2f368266578c062d1151dc2c900964aecc5975e8882e6de6fdfb6460463e30ebfaad2ec8f0c3c6436f80225b3b5b
CoreDNS-1.9.3
linux/amd64, go1.18.2, 45b0a11
[INFO] 127.0.0.1:36422 - 40150 "HINFO IN 8887628758601364406.1917446938294670497. udp 57 false 512" NXDOMAIN qr,rd,ra 57 0.0774389s
[INFO] 10.244.0.21:43584 - 12361 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,rd,ra 383 0.9109703s
[INFO] 10.244.0.21:35525 - 31151 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001492s
[INFO] 10.244.0.21:55736 - 38608 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001604s
[INFO] 10.244.0.21:46547 - 39129 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001369s
[INFO] 10.244.0.21:59195 - 60985 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0002295s
[INFO] 10.244.0.21:36202 - 63444 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001645s
[INFO] 10.244.0.21:48974 - 6260 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0002211s
[INFO] 10.244.0.21:35313 - 64505 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 549 0.0002098s
[INFO] 10.244.0.21:40862 - 18545 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 549 0.0001935s
[INFO] 10.244.0.21:53456 - 55532 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 549 0.000241s
[INFO] 10.244.0.21:55512 - 32092 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 549 0.000199s
[INFO] 10.244.0.21:41259 - 53840 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,rd,ra 383 0.64486s
[INFO] 10.244.0.21:37827 - 10803 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.000169s
[INFO] 10.244.0.21:49151 - 31864 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001755s
[INFO] 10.244.0.21:57596 - 34 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001266s
[INFO] 10.244.0.21:41092 - 31550 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001526s
[INFO] 10.244.0.21:54409 - 41026 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001718s
[INFO] 10.244.0.21:58604 - 31157 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0002125s
[INFO] 10.244.0.21:36101 - 29069 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001524s
[INFO] 10.244.0.21:40854 - 19562 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001316s
[INFO] 10.244.0.21:49165 - 43468 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001902s
[INFO] 10.244.0.21:40312 - 52077 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0002326s
[INFO] 10.244.0.21:52620 - 37021 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001678s
[INFO] 10.244.0.21:49465 - 8327 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001431s
[INFO] 10.244.0.21:35206 - 3613 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001503s
[INFO] 10.244.0.21:40135 - 46262 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001447s
[INFO] 10.244.0.21:58368 - 38072 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001443s
[INFO] 10.244.0.21:54676 - 62408 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001803s
[INFO] 10.244.0.21:56391 - 23430 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001624s
[INFO] 10.244.0.21:52558 - 3032 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001671s
[INFO] 10.244.0.21:56611 - 627 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001566s
[INFO] 10.244.0.21:56880 - 9802 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0002375s
[INFO] 10.244.0.21:38025 - 49596 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,rd,ra 383 0.4938179s
[INFO] 10.244.0.21:46612 - 42548 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001999s
[INFO] 10.244.0.21:48675 - 11010 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001547s
[INFO] 10.244.0.21:42245 - 50316 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001528s
[INFO] 10.244.0.21:60242 - 15964 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001346s
[INFO] 10.244.0.21:46067 - 11007 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001819s
[INFO] 10.244.0.21:57459 - 50917 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,aa,rd,ra 383 0.0001907s
[INFO] 10.244.0.21:37593 - 54995 "A IN bla.us-south.containers.appdomain.cloud. udp 88 false 4096" NOERROR qr,rd,ra 383 0.5858409s

I'm running a dig every 5s, so the prefetch would be triggered. right?
I gave more memory and cpu to coreDNS, but I have the same behavior.
I tried as well a specific config for the host, trying different approachs for the prefetch, like:

bla.us-south.containers.appdomain.cloud:53 {
        log . "{remote}:{port} NEW {>id} {type} {class} {name} {proto} {size} {>do} {>bufsize} {rcode} {>rflags} {rsize} {duration}"
        errors
        health {
           lameduck 5s
        }
        ready
        prometheus :9153
        hosts {
           192.168.65.254 host.minikube.internal
           fallthrough
        }
        forward . /etc/resolv.conf {
           max_concurrent 1000
        }
        cache 60 {
           prefetch 1 15s 80%
           # prefetch 2 10m 80%
        }
        loop
        reload
        loadbalance
    }

The CPU usage is below 20% and memory usabe below 50%.(yeah.. docker on windows XD)

I was expecting to have always a good query time using the local cache while prefetching when needed.
Am I'm not understanding how this feature works?
Do you guys have any other suggestion?

oh, the whole dig response:

May be important[redacted]:

; <<>> DiG 9.9.5-9+deb8u19-Debian <<>> bla.us-south.containers.appdomain.cloud
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 20483
;; flags: qr rd ra; QUERY: 1, ANSWER: 3, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
bla.us-south.containers.appdomain.cloud. IN        A

;; ANSWER SECTION:
bla.us-south.containers.appdomain.cloud. 60 IN CNAME bla.0d4002ea1f2f4e91aded48ceaeca54xx.akadns.net.
bla.0d4002ea1f2f4e91aded48ceaeca54xx.akadns.net. 60 IN A 16X.63.X.XX
bla.0d4002ea1f2f4e91aded48ceaeca54xx.akadns.net. 60 IN A 16X.46.10X.XX

;; Query time: 695 msec
;; SERVER: 10.96.0.10#53(10.96.0.10)
;; WHEN: Fri May 19 13:34:15 UTC 2023
;; MSG SIZE  rcvd: 394

thx!!

chrisohaver · 2023-05-19T14:45:21Z

chrisohaver
May 19, 2023
Maintainer

Seems broken? Although, a prefetch AMOUNT of 1 is kind of meaningless per the README description, since there is nothing "between" a single query. I don't know how the code handles a value of 1. Maybe it does something awkward in this case?

0 replies

johnbelamaric · 2023-05-19T15:32:18Z

johnbelamaric
May 19, 2023
Maintainer

Agree it seems broken. "1" is a fine value for AMOUNT, it should basically force it to prefetch almost all the time, I think. IIRC, the code basically does this: - For each incoming query, if the last time the query was seen is less than DURATION ago, bump a counter. - As we get close to the TTL if the counter is greater than AMOUNT, prefetch. So, AMOUNT of 1 basically saying if we saw 2 queries inside of DURATION, we will prefetch it.

…

On Fri, May 19, 2023 at 7:45 AM chrisohaver ***@***.***> wrote: Seems broken? Although, a prefetch AMOUNT of 1 is kind of meaningless per the README description, since there is nothing "between" a single query. I don't know how the code handles a value of 1. Maybe it does something awkward in this case? — Reply to this email directly, view it on GitHub <#6103 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ACIHRM5EVL5WKMY6PZ25ZXLXG6BRDANCNFSM6AAAAAAYHZOTHQ> . You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

3 replies

chrisohaver May 19, 2023
Maintainer

OK. So the README fibs a little bit ... "Popular means AMOUNT queries have been seen with no gaps of DURATION or more between them."

Strictly, should be "Popular means AMOUNT queries have been seen after an initial query within the DURATION"

chrisohaver May 19, 2023
Maintainer

Strictly, should be "Popular means AMOUNT queries have been seen after an initial query within the DURATION"

not quite... rather...

"Popular means AMOUNT queries have been seen after an initial query each with DURATION or less between them."

chrisohaver May 19, 2023
Maintainer

... the robot in me wants to just add a +1 to AMOUNT ... "Popular means AMOUNT+1 queries have been seen with no gaps of DURATION or more between them."

johnbelamaric · 2023-05-19T16:03:05Z

johnbelamaric
May 19, 2023
Maintainer

We should check the code and not take my faulty memory as fact…

…

On Fri, May 19, 2023 at 8:44 AM chrisohaver ***@***.***> wrote: ... the robot in me want to just add a +1 to AMOUNT ... "Popular means AMOUNT+1 queries have been seen with no gaps of DURATION or more between them." — Reply to this email directly, view it on GitHub <#6103 (reply in thread)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ACIHRMZXTQIJCX4HSYU627LXG6IMDANCNFSM6AAAAAAYHZOTHQ> . You are receiving this because you commented.Message ID: ***@***.***>

0 replies

jonatiao · 2023-05-19T16:44:56Z

jonatiao
May 19, 2023
Author

Hello everyone,
Thx for your prompt response! Sorry for saying "Is prefetch broken?" as like I was pointing fingers Mr. @chrisohaver I did not mean to offend your guys work.

I played around with the prefetch values before, I spent the whole day, and I did it again now for ~ 1h.
I tried to increase the cache TTL, prefetch amount, duration and percentage, playing with success, denial and so on.. I don't even remember everything I tried. Which is fine by me, I really want to help.
I as well read several documents, some examples in the internet and I did not found any working setup.

If you guys need more tests or debug, please let me know. I'm glad to help or give more information.
Btw, I see the same behavior in all Openshift instances we have.

OH, more info:

minikube version: v1.30.1
commit: 08896fd1dc362c097c925146c4a0d0dac715ace0
kubernetes-version=v1.26.3

thx again!

0 replies

chrisohaver · 2023-05-19T16:48:02Z

chrisohaver
May 19, 2023
Maintainer

Ok. I didn’t take offense. Not sure what I said to imply I was offended.

(FWIW, Im also not offended by you thinking I was offended :) )

2 replies

johnbelamaric May 19, 2023
Maintainer

Yeah, I don't think we're so easily offended :) - if it's broken, say it! It looks like it probably is

jonatiao May 22, 2023
Author

Sorry for the confusion! : )

@chrisohaver @johnbelamaric
Are you guys transferring this discussion to the BUG section or should I open a new thread there?

thx again!

ADV-R · 2024-02-29T15:02:08Z

ADV-R
Feb 29, 2024

Any news? It's still broken.

0 replies

chrisohaver · 2024-02-29T15:14:34Z

chrisohaver
Feb 29, 2024
Maintainer

Actually looks like a bug was already opened and then closed after a maintainer confirmed that prefetch is working as expected. #6111

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Is prefetch broken? #6103

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 7 comments 5 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Select a reply

Is prefetch broken? #6103

jonatiao May 19, 2023

Replies: 7 comments · 5 replies

chrisohaver May 19, 2023 Maintainer

johnbelamaric May 19, 2023 Maintainer

chrisohaver May 19, 2023 Maintainer

chrisohaver May 19, 2023 Maintainer

chrisohaver May 19, 2023 Maintainer

johnbelamaric May 19, 2023 Maintainer

jonatiao May 19, 2023 Author

chrisohaver May 19, 2023 Maintainer

johnbelamaric May 19, 2023 Maintainer

jonatiao May 22, 2023 Author

ADV-R Feb 29, 2024

chrisohaver Feb 29, 2024 Maintainer

jonatiao
May 19, 2023

Replies: 7 comments 5 replies

chrisohaver
May 19, 2023
Maintainer

johnbelamaric
May 19, 2023
Maintainer

chrisohaver May 19, 2023
Maintainer

chrisohaver May 19, 2023
Maintainer

chrisohaver May 19, 2023
Maintainer

johnbelamaric
May 19, 2023
Maintainer

jonatiao
May 19, 2023
Author

chrisohaver
May 19, 2023
Maintainer

johnbelamaric May 19, 2023
Maintainer

jonatiao May 22, 2023
Author

ADV-R
Feb 29, 2024

chrisohaver
Feb 29, 2024
Maintainer