Constant CPU load/Spikes

[waffshappen]

As in previous Thread:

2. Constant CPU load -- I don't understand where it comes from; Try to repro with the @waffshappen's configuration.

Originally posted by @ameshkov in #2041 (comment)

[waffshappen]

Well, turns out the source is straight in main.go:
memoryUsage()
The constant GC runs cause a significant constant load on the application. with that disabled it runs far better overall but of course at a high memory cost.

[ameshkov]

Yeah, GC in Go is not ideal at all. Anyways, that much overhead is unexpected, I see nothing like that with the default config. I guess the overhead depends on the number of alive objects, and with your config it is significantly higher

[ameshkov]

memoryUsage()

@waffshappen could you please do one more test?

What's interesting to me is which part of memoryUsage causes this. I suspect that periodic calls to debug.FreeOSMemory() is the reason, but it'd better to get a confirmation. Could you please try commenting it out and see if this solves the issue?

[waffshappen]

memoryUsage()

@waffshappen could you please do one more test?

What's interesting to me is which part of memoryUsage causes this. I suspect that periodic calls to debug.FreeOSMemory() is the reason, but it'd better to get a confirmation. Could you please try commenting it out and see if this solves the issue?

Can confirm it solves the issue.

[ameshkov]

@szolin I'd still like to keep it, but we can call it less often for instance.

Also, I don't understand why it causes that much overhead, I don't observe this on my instance.

Also, this:
https://groups.google.com/g/golang-nuts/c/Qq1coj750ZI

[szolin]

My performance results table using your filtering lists on rpi:

    -----------------------------------------------
                      filtering  RSS    RSS after
                      init time         reinit
    -----------------------------------------------
    SetGCPercent(10)  3:11       293mb
    SetGCPercent(50)  2:00       397mb  742mb
     +free/init
    SetGCPercent(50)  2:00       397mb  736mb
     +madv,free/init
    SetGCPercent(50)  2:07       380mb  715mb
     +madv,free/init,                   (+30s CPU)
      free/15s)

Where:

• madv = madvdontneed=1
• free/init = FreeOSMemory() after filters initialization
• free/15s = FreeOSMemory() every 15s

So:

• We have much better performance results if we use GC=50% instead of 10% which is the current value.
• But we also have much higher RSS
• To be able to find the right balance between CPU and mem usage we're implementing a new configuration setting to allow the user to easily set GC percentage

About FreeOSMemory:

• Periodic calls to FreeOSMemory() (every 15s currently) waste CPU resources with no reason
• At the same time they don't do much good - 715mb vs 736mb but consuming +30s CPU during reinitialization
• So I suggest we just stop calling FreeOSMemory() periodically

About madvdontneed=1:
I don't see any real improvement that this option provides.

[ameshkov]

Well, let's make it configurable then.

[ameshkov]

1. Changed default GC percent to 50% and increased the period for calling FreeOSMemory to 5 minutes
2. Added --no-mem-optimization flag that can completely disable it. In order to use it just specify it when you install the service: sudo ./AdGuardHome -s install --no-mem-optimization. If you already have it installed, you may need to first run sudo ./AdGuardHome -s uninstall and then run install to re-register the service.

[pipip]

Hmm, running v0.103.3-SNAPSHOT-a22db5f3 (ARMv5 32bit, 1.2 GHz CPU and 512 MB RAM), I still have this problem.
I tried both options (new standard and with the no-mem-optimization as described above)... both result in 100% CPU spikes:

[ameshkov]

Please record the verbose-level log and check what happens when you see this spike.

[pipip]

`2020/09/12 20:00:22 25967#559 [debug] GET /control/safesearch/status
2020/09/12 20:00:27 25967#559 [debug] GET /control/status
2020/09/12 20:00:28 25967#559 [debug] GET /control/filtering/status
2020/09/12 20:00:28 25967#559 [debug] GET /control/parental/status
2020/09/12 20:00:29 25967#559 [debug] GET /control/safebrowsing/status
2020/09/12 20:00:29 25967#559 [debug] GET /control/safesearch/status
2020/09/12 20:00:37 25967#559 [debug] GET /control/status
2020/09/12 20:00:37 25967#559 [debug] GET /control/filtering/status
2020/09/12 20:00:38 25967#559 [debug] GET /control/parental/status
2020/09/12 20:00:38 25967#559 [debug] GET /control/safebrowsing/status
2020/09/12 20:00:38 25967#559 [debug] GET /control/safesearch/status
2020/09/12 20:00:47 25967#559 [debug] GET /control/status
2020/09/12 20:00:47 25967#559 [debug] GET /control/filtering/status
2020/09/12 20:00:48 25967#559 [debug] GET /control/parental/status
2020/09/12 20:00:48 25967#559 [debug] GET /control/safebrowsing/status
2020/09/12 20:00:48 25967#559 [debug] GET /control/safesearch/status
2020/09/12 20:00:57 25967#559 [debug] GET /control/status
2020/09/12 20:00:57 25967#559 [debug] GET /control/filtering/status
2020/09/12 20:00:58 25967#559 [debug] GET /control/parental/status
2020/09/12 20:00:58 25967#559 [debug] GET /control/safebrowsing/status
2020/09/12 20:00:58 25967#559 [debug] GET /control/safesearch/status
2020/09/12 20:01:07 25967#559 [debug] GET /control/status
2020/09/12 20:01:07 25967#613 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).udpHandlePack$
2020/09/12 20:01:07 25967#613 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage$
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

...

2020/09/12 20:15:19 25967#1636 [debug] 176.103.130.130:53: response: ok
2020/09/12 20:15:19 25967#1569 [debug] GET /control/filtering/status
2020/09/12 20:15:20 25967#1569 [debug] GET /control/parental/status
2020/09/12 20:15:21 25967#1569 [debug] GET /control/safebrowsing/status
2020/09/12 20:15:22 25967#1569 [debug] GET /control/safesearch/status
2020/09/12 20:15:27 25967#1641 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).udpHandlePac$
2020/09/12 20:15:27 25967#1641 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessag$
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

2020/09/12 20:15:27 25967#1644 [debug] 1.1.1.1:53: response: ok
2020/09/12 20:15:27 25967#1569 [debug] GET /control/status
2020/09/12 20:15:28 25967#1569 [debug] GET /control/filtering/status
2020/09/12 20:15:28 25967#1569 [debug] GET /control/parental/status
2020/09/12 20:15:29 25967#1569 [debug] GET /control/safebrowsing/status
2020/09/12 20:15:29 25967#1569 [debug] GET /control/safesearch/status
2020/09/12 20:15:34 25967#1650 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).udpHandlePac$
2020/09/12 20:15:34 25967#1650 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessag$
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0`

[ameshkov]

Do all these spikes correspond to the time when you were using the web interface to check settings?

[pipip]

@ameshkov I will do some further investigation. I had those peaks last night as well without interacting with the web interface. I am not sure they are caused by AdGuard at all. I am sorry. I will do further analysis and will open a new bug report once I am certain whats causing this...