mirror of
https://github.com/AdguardTeam/AdGuardHome.git
synced 2026-03-04 00:01:12 -05:00
Web services (browsing security and parental control) are too slow #472
Labels
No labels
P1: Critical
P2: High
P3: Medium
P4: Low
UI
bug
cannot reproduce
compatibility
dependencies
docker
documentation
duplicate
enhancement
enhancement
external libs
feature request
good first issue
help wanted
infrastructure
invalid
localization
needs investigation
performance
potential-duplicate
question
recurrent
research
snap
waiting for data
wontfix
No milestone
No project
No assignees
1 participant
Notifications
Due date
No due date set.
Dependencies
No dependencies set.
Reference
starred/AdGuardHome#472
Loading…
Add table
Add a link
Reference in a new issue
No description provided.
Delete branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Originally created by @zeus10000 on GitHub (Jan 4, 2019).
Originally assigned to: @ameshkov, @szolin on GitHub.
UPDATE by @ameshkov: See the implementation details: https://github.com/AdguardTeam/AdGuardHome/issues/525#issuecomment-520482071
Hello,
I am running Adguard-home on RHEL7.6 on AWS with 1vCPU and 1GB ram. Although initially, the DNS was resolving quickly, after 24 hours, I started noticing some delays in resolving DNS (upstream being the default cloudflare). The VM seems to be pretty quite.
I tried the same using Ubuntu 16.04 with similar behavior.
Any suggestions?
Environment
| Version of AdGuard Home server:| - v0.92
| How did you setup DNS configuration:| - AWS t2.micro
| Operating system and version:| RHEL 7.6, Ubuntu 16.04.
@hmage commented on GitHub (Jan 4, 2019):
Hi!
Can you post the configuration file? I'm interested whether you changed the ratelimit settings.
Taking a guess, I think this is because you ran out of vCPU credits (https://docs.aws.amazon.com/AWSEC2/latest/UserGuide/burstable-credits-baseline-concepts.html). Can you make sure this isn't the case?
Also try running
time dig google.com @your.machine.ip.address.@zeus10000 commented on GitHub (Jan 4, 2019):
I did not make any changes to the default config apart from adding additional filter lists & blocklist. Also, The CPU is pretty much staying idle
=============================
CPU Util:
=============================
cat /root/AdGuardHome/AdGuardHome.yaml
bind_host: 0.0.0.0
bind_port: 3000
auth_name: ####
auth_pass: ####
language: ""
dns:
port: 53
protection_enabled: true
filtering_enabled: true
blocked_response_ttl: 10
querylog_enabled: true
ratelimit: 20
ratelimit_whitelist: []
refuse_any: true
bootstrap_dns: 8.8.8.8:53
parental_sensitivity: 0
parental_enabled: false
safesearch_enabled: true
safebrowsing_enabled: true
upstream_dns:
filters:
url: https://adguardteam.github.io/AdGuardSDNSFilter/Filters/filter.txt
name: AdGuard Simplified Domain Names filter
last_updated: 2019-01-04T17:10:02.343014154Z
id: 1
url: https://adaway.org/hosts.txt
name: AdAway
last_updated: 2019-01-04T17:05:02.342998035Z
id: 2
url: https://hosts-file.net/ad_servers.txt
name: hpHosts - Ad and Tracking servers only
last_updated: 2019-01-04T17:05:02.502039031Z
id: 3
url: http://www.malwaredomainlist.com/hostslist/hosts.txt
name: MalwareDomainList.com Hosts List
last_updated: 2019-01-04T17:05:03.476695873Z
id: 4
url: https://easylist.to/easylist/easylist.txt
name: EasyList
last_updated: 2019-01-04T17:05:03.590343788Z
id: 1546390427
url: https://filters.adtidy.org/extension/chromium/filters/2.txt
name: AdGuard Base filter
last_updated: 2019-01-04T17:05:03.765327115Z
id: 1546391142
url: https://filters.adtidy.org/extension/chromium/filters/3.txt
name: AdGuard Spyware filter
last_updated: 2019-01-04T17:05:03.996492533Z
id: 1546391143
url: https://filters.adtidy.org/extension/chromium/filters/4.txt
name: AdGuard Social Media filter
last_updated: 2019-01-04T17:05:04.01762709Z
id: 1546391144
url: https://filters.adtidy.org/extension/chromium/filters/14.txt
name: AdGuard Annoyances filter
last_updated: 2019-01-04T17:05:04.048278364Z
id: 1546391145
url: https://filters.adtidy.org/extension/chromium/filters/1.txt
name: AdGuard Russian filter
last_updated: 2019-01-04T17:05:04.082829061Z
id: 1546391146
url: https://filters.adtidy.org/extension/chromium/filters/6.txt
name: AdGuard German filter
last_updated: 2019-01-04T17:05:04.114680066Z
id: 1546391147
url: https://filters.adtidy.org/extension/chromium/filters/16.txt
name: AdGuard French filter
last_updated: 2019-01-04T17:05:04.145451466Z
id: 1546391148
url: https://filters.adtidy.org/extension/chromium/filters/7.txt
name: AdGuard Japanese filter
last_updated: 2019-01-04T17:05:04.175168718Z
id: 1546391149
url: https://filters.adtidy.org/extension/chromium/filters/8.txt
name: AdGuard Dutch filter
last_updated: 2019-01-04T17:05:04.196042982Z
id: 1546391150
url: https://filters.adtidy.org/extension/chromium/filters/9.txt
name: AdGuard Spanish/Portuguese filter
last_updated: 2019-01-04T17:05:04.228637536Z
id: 1546391151
url: https://filters.adtidy.org/extension/chromium/filters/13.txt
name: AdGuard Turkish filter
last_updated: 2019-01-04T17:05:04.251836078Z
id: 1546391152
url: https://filters.adtidy.org/extension/chromium/filters/238.txt
name: Polish Anti Adblock Filters
last_updated: 2019-01-04T17:05:04.27531768Z
id: 1546391153
url: https://filters.adtidy.org/extension/chromium/filters/11.txt
name: AdGuard Mobile Ads filter
last_updated: 2019-01-04T17:05:04.298238361Z
id: 1546391154
url: https://filters.adtidy.org/extension/chromium/filters/12.txt
name: AdGuard Safari filter
last_updated: 2019-01-04T17:05:04.317671846Z
id: 1546391155
user_rules:
dhcp:
enabled: false
interface_name: ""
gateway_ip: ""
subnet_mask: ""
range_start: ""
range_end: ""
lease_duration: 0
schema_version: 2
=============================
time dig google.com @x.x.x.x
; <<>> DiG 9.11.3-1ubuntu1.3-Ubuntu <<>> google.com @x.x.x.x
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 22291
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;google.com. IN A
;; Query time: 321 msec
;; SERVER: x.x.x.x#53(x.x.x.x)
;; WHEN: Fri Jan 04 17:18:04 EST 2019
;; MSG SIZE rcvd: 28
real 0m0.336s
user 0m0.008s
sys 0m0.004s
@AnthonyBe commented on GitHub (Jan 4, 2019):
I've seen the same thing in AGH since the first 0.9 release and am wondering whether it is a scalability issue.
I've run AGH on 2 environments with same results:
Massive amounts of headroom in both CPU and RAM on both devices.
I have about 50 devices on my home network.
In general operation, I've never seen the General Processing time get under 100ms, and it is usually around 130ms.
The ONLY time I saw it lower was when I was migrating from environment 1 (Linux image on Win10) to environment 2 (Windows image on Win Server 2012) and had both of them running concurrently and let devices migrate to the new one as they renewed the DHCP IP info to pick up the new DNS server.
In the first 24 horus where the new environment only had a handful of devices using it, the general processing time was in the 20-40ms range. Within a couple of days when all of my devices had migrated over, it was back up to the 100+ms average.
I've just upgraded from v0.92 to v0.92-hotfix1 in the last hour so I'll give that 24 hours to get current stats given v0.92 had a couple of DNS bugs that might cause bad results.
My config, for reference:
bind_host: 0.0.0.0
bind_port: 3000
auth_name: ####
auth_pass: ####
language: ""
dns:
port: 53
protection_enabled: true
filtering_enabled: true
blocked_response_ttl: 10
querylog_enabled: true
ratelimit: 20
ratelimit_whitelist: []
refuse_any: true
bootstrap_dns: 8.8.8.8:53
parental_sensitivity: 0
parental_enabled: false
safesearch_enabled: false
safebrowsing_enabled: true
upstream_dns:
filters:
url: https://adguardteam.github.io/AdGuardSDNSFilter/Filters/filter.txt
name: AdGuard Simplified Domain Names filter
last_updated: 2019-01-05T13:11:55.9815204+11:00
id: 1
url: https://adaway.org/hosts.txt
name: AdAway
id: 2
url: https://hosts-file.net/ad_servers.txt
name: hpHosts - Ad and Tracking servers only
last_updated: 2019-01-05T13:11:56.2391441+11:00
id: 3
url: http://www.malwaredomainlist.com/hostslist/hosts.txt
name: MalwareDomainList.com Hosts List
last_updated: 2019-01-05T13:11:58.7861454+11:00
id: 4
user_rules:
dhcp:
enabled: false
interface_name: ""
gateway_ip: ""
subnet_mask: ""
range_start: ""
range_end: ""
lease_duration: 0
schema_version: 2
@ameshkov commented on GitHub (Jan 5, 2019):
When a DOT upstream is under load, it operates on open connections so things go fast.
When night comes and there is no more activity, every new DNS request requires establishing a new TLS connection, it has to go through TLS handshake every time, and this slows things down considerably.
Just in case, try using a plain DNS upstream instead, do you see any difference?
@zeus10000 commented on GitHub (Jan 5, 2019):
I upgraded to v0.92-hotfix1 and for last 10 hours, the response time as reported on web gui went up to 70ms. I changed the upstream to use UDP instead of TLS, restarted the ADH service. After few hours, the DIG response time is now 263 ms vs the 321ms on using tls.
; <<>> DiG 9.11.3-1ubuntu1.3-Ubuntu <<>> google.com @XXXX
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 7194
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1452
;; QUESTION SECTION:
;google.com. IN A
;; ANSWER SECTION:
google.com. 145 IN A 172.217.7.174
;; Query time: 263 msec
;; SERVER: XXXX#53(XXXX)
;; WHEN: Sat Jan 05 13:20:52 EST 2019
;; MSG SIZE rcvd: 65
real 0m0.279s
user 0m0.016s
sys 0m0.000s
@ameshkov commented on GitHub (Jan 5, 2019):
@jimitsalvi it'd help if AGH was running with
-vargument so that we could see what takes so long in the stdout.@ameshkov commented on GitHub (Jan 5, 2019):
Hm, on the other hand, we'd better extend the verbose logging before proceeding. In the current implementation, we won't see how much time does every operation take.
We should get back to this issue once https://github.com/AdguardTeam/AdGuardHome/issues/531 is done.
@zeus10000 commented on GitHub (Jan 5, 2019):
just for the reference -- Not sure, how many logs you wanted but here is a few. Looks like the upstream DNS resolver takes no more than 14 ms. Is there some implementation where we could see the RTT downstream from the ADG to clients?
2019/01/05 18:52:12 AdGuard Home web interface backend, version v0.92-hotfix1
2019/01/05 18:52:12 Current working directory is /root/AdGuardHome
2019/01/05 18:52:12 main.upgradeConfig(): got schema version 2
2019/01/05 18:52:12 Reading YAML file: /root/AdGuardHome/AdGuardHome.yaml
2019/01/05 18:52:12 Loading filter 1 contents to: /root/AdGuardHome/data/filters/1.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1.txt, id 1, length 502656
2019/01/05 18:52:12 Loading filter 2 contents to: /root/AdGuardHome/data/filters/2.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/2.txt, id 2, length 13722
2019/01/05 18:52:12 Loading filter 3 contents to: /root/AdGuardHome/data/filters/3.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/3.txt, id 3, length 1772576
2019/01/05 18:52:12 Loading filter 4 contents to: /root/AdGuardHome/data/filters/4.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/4.txt, id 4, length 35737
2019/01/05 18:52:12 Loading filter 1546390427 contents to: /root/AdGuardHome/data/filters/1546390427.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546390427.txt, id 1546390427, length 2793130
2019/01/05 18:52:12 Loading filter 1546391142 contents to: /root/AdGuardHome/data/filters/1546391142.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391142.txt, id 1546391142, length 4270317
2019/01/05 18:52:12 Loading filter 1546391143 contents to: /root/AdGuardHome/data/filters/1546391143.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391143.txt, id 1546391143, length 315593
2019/01/05 18:52:12 Loading filter 1546391144 contents to: /root/AdGuardHome/data/filters/1546391144.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391144.txt, id 1546391144, length 265463
2019/01/05 18:52:12 Loading filter 1546391145 contents to: /root/AdGuardHome/data/filters/1546391145.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391145.txt, id 1546391145, length 607189
2019/01/05 18:52:12 Loading filter 1546391146 contents to: /root/AdGuardHome/data/filters/1546391146.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391146.txt, id 1546391146, length 819775
2019/01/05 18:52:12 Loading filter 1546391147 contents to: /root/AdGuardHome/data/filters/1546391147.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391147.txt, id 1546391147, length 660066
2019/01/05 18:52:12 Loading filter 1546391148 contents to: /root/AdGuardHome/data/filters/1546391148.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391148.txt, id 1546391148, length 706906
2019/01/05 18:52:12 Loading filter 1546391149 contents to: /root/AdGuardHome/data/filters/1546391149.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391149.txt, id 1546391149, length 47359
2019/01/05 18:52:12 Loading filter 1546391150 contents to: /root/AdGuardHome/data/filters/1546391150.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391150.txt, id 1546391150, length 69002
2019/01/05 18:52:12 Loading filter 1546391151 contents to: /root/AdGuardHome/data/filters/1546391151.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391151.txt, id 1546391151, length 133826
2019/01/05 18:52:12 Loading filter 1546391152 contents to: /root/AdGuardHome/data/filters/1546391152.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391152.txt, id 1546391152, length 270867
2019/01/05 18:52:12 Loading filter 1546391153 contents to: /root/AdGuardHome/data/filters/1546391153.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391153.txt, id 1546391153, length 21736
2019/01/05 18:52:12 Loading filter 1546391154 contents to: /root/AdGuardHome/data/filters/1546391154.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391154.txt, id 1546391154, length 140598
2019/01/05 18:52:12 Loading filter 1546391155 contents to: /root/AdGuardHome/data/filters/1546391155.txt
2019/01/05 18:52:12 File /root/AdGuardHome/data/filters/1546391155.txt, id 1546391155, length 101313
2019/01/05 18:52:12 Writing YAML file: /root/AdGuardHome/AdGuardHome.yaml
2019/01/05 18:52:12 Creating dnsfilter
2019/01/05 18:52:12 Downloading update for filter 1 from https://adguardteam.github.io/AdGuardSDNSFilter/Filters/filter.txt
2019/01/05 18:52:12 Filter #1 at URL https://adguardteam.github.io/AdGuardSDNSFilter/Filters/filter.txt hasn't changed, not updating it
2019/01/05 18:52:12 Downloading update for filter 2 from https://adaway.org/hosts.txt
2019/01/05 18:52:12 Loading stats from querylog
2019/01/05 18:52:12 Filter #2 at URL https://adaway.org/hosts.txt hasn't changed, not updating it
2019/01/05 18:52:12 Downloading update for filter 3 from https://hosts-file.net/ad_servers.txt
2019/01/05 18:52:13 file "querylog.json": read 3176 entries in 83.560685ms, 26.31µs/entry, 0 over 2h46m40s, 95.804795ms avg
2019/01/05 18:52:13 Starting the DNS proxy server
2019/01/05 18:52:13 Ratelimit is enabled and set to 20 rps
2019/01/05 18:52:13 The server is configured to refuse ANY requests
2019/01/05 18:52:13 DNS cache is enabled
2019/01/05 18:52:13 Creating the UDP server socket
2019/01/05 18:52:13 Listening to udp://[::]:53
2019/01/05 18:52:13 Go to http://0.0.0.0:3000
2019/01/05 18:52:13 Entering the UDP listener loop on [::]:53
2019/01/05 18:52:13 Filter #3 at URL https://hosts-file.net/ad_servers.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 4 from http://www.malwaredomainlist.com/hostslist/hosts.txt
2019/01/05 18:52:13 Filter #4 at URL http://www.malwaredomainlist.com/hostslist/hosts.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546390427 from https://easylist.to/easylist/easylist.txt
2019/01/05 18:52:13 Filter 1546390427 has been updated: 2793130 bytes, 73671 rules
2019/01/05 18:52:13 Saving filter 1546390427 contents to: /root/AdGuardHome/data/filters/1546390427.txt
2019/01/05 18:52:13 Downloading update for filter 1546391142 from https://filters.adtidy.org/extension/chromium/filters/2.txt
2019/01/05 18:52:13 Filter #1546391142 at URL https://filters.adtidy.org/extension/chromium/filters/2.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546391143 from https://filters.adtidy.org/extension/chromium/filters/3.txt
2019/01/05 18:52:13 Filter #1546391143 at URL https://filters.adtidy.org/extension/chromium/filters/3.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546391144 from https://filters.adtidy.org/extension/chromium/filters/4.txt
2019/01/05 18:52:13 Filter #1546391144 at URL https://filters.adtidy.org/extension/chromium/filters/4.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546391145 from https://filters.adtidy.org/extension/chromium/filters/14.txt
2019/01/05 18:52:13 Filter #1546391145 at URL https://filters.adtidy.org/extension/chromium/filters/14.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546391146 from https://filters.adtidy.org/extension/chromium/filters/1.txt
2019/01/05 18:52:13 Filter #1546391146 at URL https://filters.adtidy.org/extension/chromium/filters/1.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546391147 from https://filters.adtidy.org/extension/chromium/filters/6.txt
2019/01/05 18:52:13 Filter #1546391147 at URL https://filters.adtidy.org/extension/chromium/filters/6.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546391148 from https://filters.adtidy.org/extension/chromium/filters/16.txt
2019/01/05 18:52:13 Filter #1546391148 at URL https://filters.adtidy.org/extension/chromium/filters/16.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546391149 from https://filters.adtidy.org/extension/chromium/filters/7.txt
2019/01/05 18:52:13 Filter #1546391149 at URL https://filters.adtidy.org/extension/chromium/filters/7.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546391150 from https://filters.adtidy.org/extension/chromium/filters/8.txt
2019/01/05 18:52:13 Filter #1546391150 at URL https://filters.adtidy.org/extension/chromium/filters/8.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546391151 from https://filters.adtidy.org/extension/chromium/filters/9.txt
2019/01/05 18:52:13 Filter #1546391151 at URL https://filters.adtidy.org/extension/chromium/filters/9.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546391152 from https://filters.adtidy.org/extension/chromium/filters/13.txt
2019/01/05 18:52:13 Filter #1546391152 at URL https://filters.adtidy.org/extension/chromium/filters/13.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546391153 from https://filters.adtidy.org/extension/chromium/filters/238.txt
2019/01/05 18:52:13 Filter #1546391153 at URL https://filters.adtidy.org/extension/chromium/filters/238.txt hasn't changed, not updating it
2019/01/05 18:52:13 Downloading update for filter 1546391154 from https://filters.adtidy.org/extension/chromium/filters/11.txt
2019/01/05 18:52:14 Filter #1546391154 at URL https://filters.adtidy.org/extension/chromium/filters/11.txt hasn't changed, not updating it
2019/01/05 18:52:14 Downloading update for filter 1546391155 from https://filters.adtidy.org/extension/chromium/filters/12.txt
2019/01/05 18:52:14 Filter #1546391155 at URL https://filters.adtidy.org/extension/chromium/filters/12.txt hasn't changed, not updating it
2019/01/05 18:52:14 Start reconfiguring the server
2019/01/05 18:52:14 Stopping the DNS proxy server
2019/01/05 18:52:14 udpListen.ReadFrom() returned because we're reading from a closed connection, exiting loop
2019/01/05 18:52:14 Stopped the DNS proxy server
2019/01/05 18:52:14 Creating dnsfilter
2019/01/05 18:52:14 Loading stats from querylog
2019/01/05 18:52:14 Starting the DNS proxy server
2019/01/05 18:52:14 Ratelimit is enabled and set to 20 rps
2019/01/05 18:52:14 The server is configured to refuse ANY requests
2019/01/05 18:52:14 DNS cache is enabled
2019/01/05 18:52:14 Creating the UDP server socket
2019/01/05 18:52:14 Listening to udp://[::]:53
2019/01/05 18:52:14 Writing YAML file: /root/AdGuardHome/AdGuardHome.yaml
2019/01/05 18:52:14 Entering the UDP listener loop on [::]:53
proxy.(*Proxy).handleUDPPacket(): Start handling new UDP packet from xx.xx.xx.xx:33795
proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 47187
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;www.google.com. IN A
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 876
proxy.(*Proxy).handleDNSRequest(): Upstream is 1.0.0.1:53 (1)
proxy.(*Proxy).handleUDPPacket(): Start handling new UDP packet from xx.xx.xx.xx:33795
proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 47187
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;www.google.com. IN A
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 876
proxy.(*Proxy).handleDNSRequest(): Upstream is 1.0.0.1:53 (1)
proxy.(*Proxy).handleUDPPacket(): Start handling new UDP packet from xx.xx.xx.xx:47030
proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 31493
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;www.google.com. IN AAAA
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 876
proxy.(*Proxy).handleDNSRequest(): Upstream is 1.1.1.1:53 (0)
proxy.(*Proxy).Resolve(): RTT: 11 ms
proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 31493
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;www.google.com. IN AAAA
;; ANSWER SECTION:
www.google.com. 228 IN AAAA 2607:f8b0:4004:804::2004
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 1452
proxy.(*Proxy).Resolve(): RTT: 11 ms
proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 47187
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;www.google.com. IN A
;; ANSWER SECTION:
www.google.com. 199 IN A 172.217.8.4
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 1452
proxy.(*Proxy).Resolve(): RTT: 11 ms
proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 47187
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;www.google.com. IN A
;; ANSWER SECTION:
www.google.com. 199 IN A 172.217.8.4
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 1452
proxy.(*Proxy).handleUDPPacket(): Start handling new UDP packet from xx.xx.xx.xx:14811
proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 1445
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;google.com. IN A
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 876
proxy.(*Proxy).handleDNSRequest(): Upstream is 1.1.1.1:53 (0)
proxy.(*Proxy).handleUDPPacket(): Start handling new UDP packet from xx.xx.xx.xx:20136
proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 48101
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;google.com. IN AAAA
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 876
proxy.(*Proxy).handleDNSRequest(): Upstream is 1.1.1.1:53 (0)
proxy.(*Proxy).Resolve(): RTT: 11 ms
proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 48101
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;google.com. IN AAAA
;; ANSWER SECTION:
google.com. 106 IN AAAA 2607:f8b0:4004:800::200e
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 1452
proxy.(*Proxy).Resolve(): RTT: 14 ms
proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 1445
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;google.com. IN A
;; ANSWER SECTION:
google.com. 51 IN A 172.217.7.238
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 1452
proxy.(*Proxy).handleUDPPacket(): Start handling new UDP packet from xx.xx.xx.xx:38722
proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 17146
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;ssl.gstatic.com. IN A
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 876
proxy.(*Proxy).handleDNSRequest(): Upstream is 1.1.1.1:53 (0)
proxy.(*Proxy).handleUDPPacket(): Start handling new UDP packet from xx.xx.xx.xx:61425
proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 26755
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;ssl.gstatic.com. IN AAAA
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 876
proxy.(*Proxy).handleDNSRequest(): Upstream is 1.1.1.1:53 (0)
proxy.(*Proxy).Resolve(): RTT: 11 ms
proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 17146
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;ssl.gstatic.com. IN A
;; ANSWER SECTION:
ssl.gstatic.com. 143 IN A 172.217.15.99
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 1452
proxy.(*Proxy).Resolve(): RTT: 12 ms
proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 26755
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;ssl.gstatic.com. IN AAAA
;; ANSWER SECTION:
ssl.gstatic.com. 142 IN AAAA 2607:f8b0:4004:801::2003
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 1452
proxy.(*Proxy).handleUDPPacket(): Start handling new UDP packet from xx.xx.xx.xx:23616
proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 8786
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;www.gstatic.com. IN A
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 876
proxy.(*Proxy).handleDNSRequest(): Upstream is 1.0.0.1:53 (1)
proxy.(*Proxy).Resolve(): RTT: 11 ms
proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 8786
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;www.gstatic.com. IN A
;; ANSWER SECTION:
www.gstatic.com. 200 IN A 172.217.197.94
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 1452
proxy.(*Proxy).handleUDPPacket(): Start handling new UDP packet from xx.xx.xx.xx:11646
proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 50361
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;apis.google.com. IN A
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 876
proxy.(*Proxy).handleDNSRequest(): Upstream is 1.1.1.1:53 (0)
proxy.(*Proxy).handleUDPPacket(): Start handling new UDP packet from xx.xx.xx.xx:18577
proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 48737
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;apis.google.com. IN AAAA
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 876
proxy.(*Proxy).handleDNSRequest(): Upstream is 1.0.0.1:53 (1)
proxy.(*Proxy).Resolve(): RTT: 12 ms
proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 50361
;; flags: qr rd ra; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;apis.google.com. IN A
;; ANSWER SECTION:
apis.google.com. 9281 IN CNAME plus.l.google.com.
plus.l.google.com. 38 IN A 172.217.7.174
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 1452
proxy.(*Proxy).Resolve(): RTT: 12 ms
proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 48737
;; flags: qr rd ra; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
;apis.google.com. IN AAAA
;; ANSWER SECTION:
apis.google.com. 9281 IN CNAME plus.l.google.com.
plus.l.google.com. 46 IN AAAA 2607:f8b0:4004:802::200e
;; ADDITIONAL SECTION:
;; OPT PSEUDOSECTION:
; EDNS: version 0; flags: ; udp: 1452
@ameshkov commented on GitHub (Jan 5, 2019):
It's unclear how much we spend inside
dnsfilter(we need #531 for that)Also, you can check
pingvalues to your server to see what's the network's overhead.@zeus10000 commented on GitHub (Jan 5, 2019):
Sure, will wait for that feature. Ping & traceroute values to the server come to somewhere around 30~34 secs.
64 bytes from xx.xx.xx.xx: icmp_seq=1 ttl=42 time=32.9 ms
64 bytes from xx.xx.xx.xx: icmp_seq=2 ttl=42 time=30.9 ms
64 bytes from xx.xx.xx.xx: icmp_seq=3 ttl=42 time=28.2 ms
64 bytes from xx.xx.xx.xx: icmp_seq=4 ttl=42 time=30.1 ms
64 bytes from xx.xx.xx.xx: icmp_seq=5 ttl=42 time=29.5 ms
64 bytes from xx.xx.xx.xx: icmp_seq=6 ttl=42 time=28.8 ms
64 bytes from xx.xx.xx.xx: icmp_seq=7 ttl=42 time=30.9 ms
64 bytes from xx.xx.xx.xx: icmp_seq=8 ttl=42 time=27.7 ms
^C
--- xx.xx.xx.xx ping statistics ---
8 packets transmitted, 8 received, 0% packet loss, time 7009ms
rtt min/avg/max/mdev = 27.754/29.927/32.918/1.579 ms
28: ec2-xx-xx-xx-xx.us-east-2.compute.amazonaws.com 33.675ms reached
@AnthonyBe commented on GitHub (Jan 6, 2019):
I tried adding a TCP upstream DNS (tcp://1.1.1.1) to see if it would improve performance but if anything I've seen average processing times start exceeding 200ms (prev ~130ms).
Also, for comparison, GRC.com DNS Benchmark results below. Cached results are obviously going to be in AGH's favour, but for uncached and dom.com results, AGH is 4-5 times slower.
@rashidjehangir commented on GitHub (Jan 13, 2019):
Hi Guys. All too technical for me ;( - however, after lettingAdGuard run for a few days my Average Processing Time is at 400! It starts out at 3 and keeps rising.
@dany20mh commented on GitHub (Jan 16, 2019):
I would say benchmark can be misleading too, because you run that benchmark on some specific domain for short period.
But your AdGaurd Home is running for 24 hours and that's the time you can see there.
I would say it should be an option in the Query to see what is the query that is taking long time to run and provide the result in the query log, so we can see what's running slowly.
@hmage commented on GitHub (Jan 16, 2019):
@dany20mh we already have that info in querylog -- click 'download log' in querylog page and then use json parser to show only long queries
@dany20mh commented on GitHub (Jan 16, 2019):
@hmage but we don't have that in the query log view (in dashboard) and that's what I meant.
@ameshkov commented on GitHub (Feb 25, 2019):
Sorry for the huge delay, guys.
We've just pushed the new release with extended logging which should be enough to figure if there's any issue: https://github.com/AdguardTeam/AdGuardHome/releases/tag/v0.93
Also, it uses a newer version of
dnsproxyunder the hood that might also help.@AnthonyBe commented on GitHub (Feb 27, 2019):
I've been running v0.93 for about 12 hours now and my average processing time is 403.11ms
17,658 DNS Queries
1,277 blocked.
I'll turn on verbose logging to capture some data.
@ameshkov commented on GitHub (Feb 28, 2019):
Interesting, and in my case avg time dropped to about 15ms.
@AnthonyBe commented on GitHub (Feb 28, 2019):
About 24 hours on and average processing time is 414.92ms
31,208 DNS Queries
2,424 blocked (7.77%)
Ran verbose logging for about 45 mins. Zipped log attached
AGH - Copy.zip
@ameshkov commented on GitHub (Mar 1, 2019):
You know, the log seems more or less okay.
There are 765 requests in the log, the avg processing time of them is 110ms.
There were five slow requests (2159ms, 3221ms, 7408ms, 11093ms, 16272ms), if you don't count them, the avg time would be around 57ms.
One thing that I forgot to ask -- do you have "malware protection" or "parental control" services enabled. They both use a remote web service, and might slow things down.
@AnthonyBe commented on GitHub (Mar 1, 2019):
I do have "Use AdGuard browsing security web service" enabled
I do not have "Use AdGuard parental control web service" enabled
I had wondered if maybe a couple of really slow queries were skewing the average processing time. When I first started v0.93 for the first hour the average processing time was around 50ms. It just seems that in that sustained 24 hour period there are enough slow responses to really skew the averages.
If I check my AGH now, the average processing time is 278.74ms
28,447 DNS queries
2,210 blocked by filters (7.77%)
@ameshkov commented on GitHub (Mar 1, 2019):
Uh, we should add it's timing to the log as well, I don't know why we ignored it:(
@admitrevskiy could you please extend logging of the dnsFilter module?
@ameshkov commented on GitHub (Mar 22, 2019):
We just released v0.94 and added more logging there, I think now we'll be able to figure what's wrong with the browsing security/parental control web services.
@AnthonyBe commented on GitHub (Mar 22, 2019):
Thanks! Logs definitely show a clearer picture now.
AGH - Copy.zip
"SafeBrowsing HTTP" is adding a minimum of 300ms to each DNS lookup based on my logs.
There are a handful of 0ms entries which must be invalid. After that they are constantly 329ms, 343ms, 372ms, etc.
@ameshkov commented on GitHub (Mar 25, 2019):
@admitrevskiy plz check the logs. 300ms might be okay, but the local cache should help with it, and following queries should be fast.
@AnthonyBe commented on GitHub (Mar 25, 2019):
I'm guessing then that entries that show 0ms are cached responses?
@ameshkov commented on GitHub (Mar 25, 2019):
Yeah, so the initial lookup is so slow that even with the cache, it hurts the average time.
So our options are:
Tbh, I like the second option more.
@admitrevskiy commented on GitHub (Mar 25, 2019):
Yes, you're right. For example for hub2.corp.adobe.com
2019/03/23 14:20:54 4032#40 [debug] github.com/AdguardTeam/AdGuardHome/dnsfilter.(*Dnsfilter).checkSafeBrowsing(): SafeBrowsing HTTP lookup for hub2.corp.adobe.com; Elapsed time: 331ms
The next time you were looking for this host the following log message appeared:
2019/03/23 14:21:02 4032#85 [debug] github.com/AdguardTeam/AdGuardHome/dnsfilter.(*Dnsfilter).lookupCommon(): hub2.corp.adobe.com: found in the lookup cache
2019/03/23 14:21:02 4032#85 [debug] github.com/AdguardTeam/AdGuardHome/dnsfilter.(*Dnsfilter).checkSafeBrowsing(): SafeBrowsing HTTP lookup for hub2.corp.adobe.com; Elapsed time: 0ms
@ameshkov commented on GitHub (Mar 29, 2019):
Reassigned to v0.96, the task is too complicated:
https://github.com/AdguardTeam/AdGuardHome/issues/525#issuecomment-476374978
Priority is set to medium because both of these options are disabled by default.
@AnthonyBe commented on GitHub (Apr 1, 2019):
So I turned off 'browsing security' yesterday and now my Average Processing time is 47ms
That is a pretty significant impact!
@ameshkov commented on GitHub (Aug 12, 2019):
Here's what we are going to do: