Slow DNS perf on benchmark

[eddie-LA]

Benchmark used: https://www.dnscheck.tools/

I get the following results:

DOT	967ms
DOH3	167ms
DOQ	498ms
DOH	142ms
DOT (dnsproxy)	104ms

Compared to dnsproxy, it's much slower.

I also get the following in the logs fairly often (DOQ connections closed with no error if I read correctly?):

{"level":"info","time":"2025-03-14T19:23:50Z.521","message":"[b7a062] REPLY: upstream.0 -> 127.0.0.1:46946 (OpenWrt): NOERROR"}
{"level":"info","time":"2025-03-14T19:23:50Z.540","message":"[04be3f] REPLY: upstream.0 -> 127.0.0.1:46936 (OpenWrt): NOERROR"}
{"level":"info","time":"2025-03-14T19:23:50Z.807","message":"[de5084] REPLY: upstream.0 -> 127.0.0.1:47036 (OpenWrt): NOERROR"}
{"level":"info","time":"2025-03-14T19:23:50Z.808","message":"[c4b87a] REPLY: upstream.0 -> 127.0.0.1:47042 (OpenWrt): NOERROR"}
{"level":"info","time":"2025-03-14T19:23:50Z.816","message":"[8021b6] REPLY: upstream.0 -> 127.0.0.1:47052 (OpenWrt): NOERROR"}
{"level":"info","time":"2025-03-14T19:23:50Z.816","message":"[54f33f] REPLY: upstream.0 -> 127.0.0.1:47066 (OpenWrt): NOERROR"}
{"level":"info","time":"2025-03-14T19:23:50Z.817","message":"[19247e] REPLY: upstream.0 -> 127.0.0.1:47080 (OpenWrt): NOERROR"}

The running config is OpenWRT 24.10 on a Qualcomm 4-core ASUS router.

[yegors]

Those logs show normal DNS responses.

As for the results, please provide debug logs with actual timings from the process itself. https://github.com/Control-D-Inc/ctrld/wiki/Troubleshooting-Guide#rule-matching

What upstream is being used, does change of upstream have an effect?

[eddie-LA]

Those logs show normal DNS responses.

As for the results, please provide debug logs with actual timings from the process itself. https://github.com/Control-D-Inc/ctrld/wiki/Troubleshooting-Guide#rule-matching

What upstream is being used, does change of upstream have an effect?

p2 - ads and tracking. I'll get debug logs tmrw.

[yegors]

I just personally tested DOH via ctrld and DOH directly configured in a Chrome browser, using the p2 resolver.

• via ctrld: 21ms
• via browser / no ctrld: 25ms

I'm not sure what that site does exactly, or how any of this is being measured, but actual non-ambiguous measurements show even smaller values.

PS C:\Users\Yegor> $domain = "verify.controld.com"
>> $timer = [System.Diagnostics.Stopwatch]::StartNew()
>> Resolve-DnsName -Name $domain
>> $timer.Stop()
>> Write-Host "Resolution took: $($timer.ElapsedMilliseconds) ms"

Name                           Type   TTL   Section    NameHost
----                           ----   ---   -------    --------
verify.controld.com            CNAME  20    Answer     api.controld.com

Name       : api.controld.com
QueryType  : AAAA
TTL        : 115
Section    : Answer
IP6Address : 2606:1a40:3::1


Name       : api.controld.com
QueryType  : A
TTL        : 102
Section    : Answer
IP4Address : 147.185.34.1

Resolution took: 18 ms

Actual query time from the process:

{"level":"info","time":"2025-03-14T20:11:00-04:00.111","message":"[517a3d] QUERY: 10.0.10.238:50608 (kubernetes) -> listener.0: A verify.controld.com"}
{"level":"debug","time":"2025-03-14T20:11:00-04:00.111","message":"[517a3d] no explicit policy matched, using default routing -> [upstream.0]"}
{"level":"debug","time":"2025-03-14T20:11:00-04:00.111","message":"[517a3d] including client info with the request"}
{"level":"debug","time":"2025-03-14T20:11:00-04:00.112","message":"[517a3d] sending query to upstream.0: "}
{"level":"debug","time":"2025-03-14T20:11:00-04:00.112","message":"[517a3d] sending request header: map[X-Cd-Host:[kubernetes] X-Cd-Ip:[10.0.10.238] X-Cd-Mac:[74:56:3c:44:eb:5e] X-Cd-Os:[1-1-6.2]]"}
{"level":"info","time":"2025-03-14T20:11:00-04:00.120","message":"[517a3d] REPLY: upstream.0 -> 10.0.10.238:50608 (kubernetes): NOERROR"}
{"level":"debug","time":"2025-03-14T20:11:00-04:00.120","message":"[517a3d] received response of 71 bytes in 8.4273ms"}

[eddie-LA]

For me it's quite different, with ctrld I get:

Resolution took: 761 ms

I found out I probably get into an OOM situation with DOQ - connections go dead for a while, then recover. Process virtual mem use is very high.
The router has 28MB available, I've set the rmem and wmem params to 7.5MB.

net.core.rmem_max=7500000
net.core.wmem_max=7500000

root@OpenWrt:~# cat /proc/meminfo
MemTotal:         117332 kB
MemFree:           41048 kB
MemAvailable:      23188 kB
Buffers:               0 kB
Mem: 71360K used, 45972K free, 1464K shrd, 0K buff, 12472K cached
CPU:   0% usr   0% sys   0% nic  98% idle   0% io   0% irq   0% sirq
Load average: 0.05 1.35 2.09 2/136 19374
  PID  PPID USER     STAT   VSZ %VSZ %CPU COMMAND
18542     1 root     S     539m 470%   1% /usr/sbin/ctrld run --homedir=/etc/controld --config=/etc/controld/ctrld.toml

I'm mainly interested in running DOH3 / DOQ. Classic DOH and DOT run fine with dnsproxy anyway.

Edit:
I found some more in the logs:

Sun Mar 16 03:10:16 2025 daemon.info ctrld[18542]: �[90mMar 16 01:10:16.820�[0m �[31mERR�[0m �[1m[e13c63] failed to resolve query�[0m �[36merror=�[0m�[31m�[1m"context deadline exceeded"�[0m�[0m
Sun Mar 16 03:10:16 2025 daemon.info ctrld[18542]: �[90mMar 16 01:10:16.821�[0m �[33mWRN�[0m �[1mupstream "upstream.0" marked as down immediately (failure count: 256)�[0m
Sun Mar 16 03:10:16 2025 daemon.info ctrld[18542]: �[90mMar 16 01:10:16.821�[0m �[31mERR�[0m �[1m[e13c63] all [upstream.0] endpoints failed�[0m
Sun Mar 16 03:10:17 2025 daemon.info ctrld[18542]: �[90mMar 16 01:10:17.136�[0m �[31mERR�[0m �[1m[a979d4] failed to resolve query�[0m �[36merror=�[0m�[31m�[1m"context deadline exceeded"�[0m�[0m
Sun Mar 16 03:10:17 2025 daemon.info ctrld[18542]: �[90mMar 16 01:10:17.136�[0m �[33mWRN�[0m �[1mupstream "upstream.0" marked as down immediately (failure count: 257)�[0m
Sun Mar 16 03:10:17 2025 daemon.info ctrld[18542]: �[90mMar 16 01:10:17.137�[0m �[31mERR�[0m �[1m[a979d4] all [upstream.0] endpoints failed�[0m
Sun Mar 16 03:10:17 2025 daemon.info ctrld[18542]: �[90mMar 16 01:10:17.312�[0m �[31mERR�[0m �[1m[fb1c91] failed to resolve query�[0m �[36merror=�[0m�[31m�[1m"context deadline exceeded"�[0m�[0m
Sun Mar 16 03:10:17 2025 daemon.info ctrld[18542]: �[90mMar 16 01:10:17.312�[0m �[33mWRN�[0m �[1mupstream "upstream.0" marked as down immediately (failure count: 258)�[0m
Sun Mar 16 03:10:17 2025 daemon.info ctrld[18542]: �[90mMar 16 01:10:17.313�[0m �[31mERR�[0m �[1m[fb1c91] all [upstream.0] endpoints failed�[0m
Sun Mar 16 03:10:17 2025 daemon.info ctrld[18542]: �[90mMar 16 01:10:17.421�[0m �[31mERR�[0m �[1m[2e2be3] failed to resolve query�[0m �[36merror=�[0m�[31m�[1m"deadline exceeded"�[0m�[0m
Sun Mar 16 03:10:17 2025 daemon.info ctrld[18542]: �[90mMar 16 01:10:17.421�[0m �[33mWRN�[0m �[1mupstream "upstream.0" marked as down immediately (failure count: 259)�[0m
Sun Mar 16 03:10:17 2025 daemon.info ctrld[18542]: �[90mMar 16 01:10:17.422�[0m �[31mERR�[0m �[1m[2e2be3] all [upstream.0] endpoints failed�[0m

[eddie-LA]

Upon restart of the ctrld service with debug logs I ran your script in Powershell, here's ctrld logs from the router at that time:

Sun Mar 16 03:26:00 2025 daemon.info ctrld[19916]: �[90mMar 16 01:26:00.004�[0m �[32mINF�[0m �[1m[996110] QUERY: [::1]:52785 (OpenWrt) -> listener.0: A verify.controld.com�[0m
Sun Mar 16 03:26:00 2025 daemon.info ctrld[19916]: �[90mMar 16 01:26:00.005�[0m DBG [996110] no explicit policy matched, using default routing -> [upstream.0]
Sun Mar 16 03:26:00 2025 daemon.info ctrld[19916]: �[90mMar 16 01:26:00.005�[0m DBG [996110] sending query to upstream.0: Control D - No Ads
Sun Mar 16 03:26:00 2025 daemon.info ctrld[19916]: �[90mMar 16 01:26:00.005�[0m �[32mINF�[0m �[1m[e1c835] QUERY: [::1]:33185 (OpenWrt) -> listener.0: AAAA verify.controld.com�[0m
Sun Mar 16 03:26:00 2025 daemon.info ctrld[19916]: �[90mMar 16 01:26:00.006�[0m DBG [e1c835] no explicit policy matched, using default routing -> [upstream.0]
Sun Mar 16 03:26:00 2025 daemon.info ctrld[19916]: �[90mMar 16 01:26:00.007�[0m DBG [e1c835] sending query to upstream.0: Control D - No Ads
Sun Mar 16 03:26:00 2025 daemon.info ctrld[19916]: �[90mMar 16 01:26:00.453�[0m DBG [996110] add cached response
Sun Mar 16 03:26:00 2025 daemon.info ctrld[19916]: �[90mMar 16 01:26:00.453�[0m DBG [e1c835] add cached response
Sun Mar 16 03:26:00 2025 daemon.info ctrld[19916]: �[90mMar 16 01:26:00.453�[0m �[32mINF�[0m �[1m[996110] REPLY: upstream.0 -> [::1]:52785 (OpenWrt): NOERROR�[0m
Sun Mar 16 03:26:00 2025 daemon.info ctrld[19916]: �[90mMar 16 01:26:00.453�[0m �[32mINF�[0m �[1m[e1c835] REPLY: upstream.0 -> [::1]:33185 (OpenWrt): NOERROR�[0m
Sun Mar 16 03:26:00 2025 daemon.info ctrld[19916]: �[90mMar 16 01:26:00.454�[0m DBG [996110] received response of 71 bytes in 449.423364ms
Sun Mar 16 03:26:00 2025 daemon.info ctrld[19916]: �[90mMar 16 01:26:00.454�[0m DBG [e1c835] received response of 83 bytes in 448.525ms

[yegors]

Hmm, that is indeed awfully high. That's approaching moon level latency.

Can you provide traceroute to freedns.controld.com

Thanks

[eddie-LA]

tracert freedns.controld.com

Tracing route to freedns.controld.com [76.76.2.11]
over a maximum of 30 hops:

  1    <1 ms    <1 ms    <1 ms  OpenWrt.lan [192.168.1.1] 
  2     1 ms     2 ms     2 ms  151.237.24.1 
  3     4 ms     4 ms     2 ms  185.46.161.130.ipacct.net [185.46.161.130] 
  4     3 ms     1 ms     2 ms  xe-0-0-2-1110.cr1-sof1.ip4.gtt.net [77.67.123.161] 
  5    10 ms    11 ms    10 ms  ae9.cr0-buc1.ip4.gtt.net [213.200.113.202] 
  6     *        *        *     Request timed out.
  7     *        *        *     Request timed out.
  8    11 ms    10 ms    10 ms  176.58.94.30 
  9    20 ms     *       10 ms  controld-edge1-otp.anycast.net [185.40.235.147] 
 10    10 ms     9 ms     9 ms  freedns.controld.com [76.76.2.11] 

Trace complete.

Here's the syslog during that:
syslog.log

[yegors]

Latency is good. Are you using DoQ here? #224 (comment)

If so, go back to normal DOH/2 or /3. There is honestly no reason to use DoQ.

[eddie-LA]

Yes, but DOH/3 also opens QUIC connections and you can see it's not ideal. I still have issues with it as you can see. Something internally seems to be wrong, RAM use for sure. A DNS client shouldn't take that much RAM.

Also, dnsproxy I believe is also based on quic-go and that has issues for me with DOQ and DOH/3 both. See here, same issue: AdguardTeam/dnsproxy#441

Finally, why have DOQ if you shouldn't use it. If I'm going back to classic protocols, I'd use DOT instead of DOH since my ISP doesn't have any DNS-based censorship and it's a bit faster.

Edit: I also am not exactly sure why I don't get connected to the node in my own city.

[yegors]

It doesn't use that much RAM, this is virtual memory (your OpenWRT doesn't have that much RAM). True resident memory usage is ~30MB.

[eddie-LA]

I know it's virtual, and it can't use any more even if it wanted to. Seems enough to cause an OOM tho... Anyway, I'll maybe do some more diagnostics in the future, I'll post if I find something out. The slowdowns have to happen somewhere. Probably connected to the context deadline exceeded error.

[yegors]

If you are very limited on RAM, you should use DOH/2 as that doesn't use the go-quic library, which is clearly not optimized for embedded devices.

[eddie-LA]

@yegors

ctrld/go.mod

Line 32 in e0d35d8

github.com/quic-go/quic-go v0.48.2

Looking at the changelog, perhaps upgrading the dependency would help?
https://github.com/quic-go/quic-go/releases/tag/v0.50.0