High RAM consumption during filter updates

[cjom]

Prerequisites

• I have checked the Wiki and Discussions and found no answer

• I have searched other issues and found no duplicates

• I want to report a bug and not ask a question

Operating system type

Linux, OpenWrt

CPU architecture

AMD64

Installation

GitHub releases or script from README

Setup

On a router, DHCP is handled by the router

AdGuard Home version

v0.108.0-a.466+9f7a582d

Description

What did you do?

Installed AGH on router and set filters to update every 24h.
Filters are saved in /opt (not RAM) trying to use less RAM, also logs are reduced to spare RAM.

Expected result

While using around 250MB of RAM for AdGuardHome only, the router usually still has more than 70 MB of free RAM.
AdGuardHome should manage the available RAM to update filters without crashing.

Actual result

"top" command shows that AGH is reserving 932 MB when there are 406 MB usable (229% of VSZ).
When comes the time to update filters, AGH tries to allocate 932 MB and then it invokes oom-killer on itself due to lack of free RAM.

Screenshots (if applicable)

[   61.700658] AdGuardHome invoked oom-killer: gfp_mask=0x1100dca(GFP_HIGHUSER_MOVABLE|__GFP_ZERO), order=0, oom_score_adj=0
[   61.700723] CPU: 0 PID: 5074 Comm: AdGuardHome Not tainted 5.15.98 #0
[   61.710610] Hardware name: Xiaomi AX3600 (DT)
[   61.717031] Call trace:
[   61.721365]  dump_backtrace+0x0/0x180
[   61.723627]  show_stack+0x18/0x30
[   61.727445]  dump_stack_lvl+0x6c/0x88
[   61.730743]  dump_stack+0x18/0x34
[   61.734389]  dump_header+0x44/0x180
[   61.737687]  oom_kill_process+0x1e0/0x1e4
[   61.740987]  out_of_memory+0x1c8/0x2fc
[   61.745153]  __alloc_pages_slowpath.constprop.0+0x82c/0xa44
[   61.748803]  __alloc_pages+0x210/0x25c
[   61.754268]  alloc_zeroed_user_highpage_movable+0x24/0x30
[   61.758091]  wp_page_copy+0x378/0x88c
[   61.763556]  do_wp_page+0xa0/0x434
[   61.767200]  __handle_mm_fault+0x69c/0xa70
[   61.770500]  handle_mm_fault+0x148/0x1f0
[   61.774580]  do_page_fault+0x14c/0x3e0
[   61.778660]  do_mem_abort+0x44/0xb0
[   61.782218]  el0_da+0x24/0x60
[   61.785603]  el0t_64_sync_handler+0xac/0x114
[   61.788731]  el0t_64_sync+0x184/0x188
[   61.793138] Mem-Info:
[   61.796632] active_anon:67573 inactive_anon:42 isolated_anon:0
[   61.796632]  active_file:170 inactive_file:28 isolated_file:0
[   61.796632]  unevictable:0 dirty:0 writeback:0
[   61.796632]  slab_reclaimable:1701 slab_unreclaimable:9055
[   61.796632]  mapped:25 shmem:20 pagetables:362 bounce:0
[   61.796632]  kernel_misc_reclaimable:0
[   61.796632]  free:4878 free_pcp:146 free_cma:0
[   61.811694] Node 0 active_anon:270292kB inactive_anon:168kB active_file:680kB inactive_file:112kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:100kB dirty:0kB writeback:0kB shmem:80kB writeback_tmp:0kB kernel_stack:2160kB pagetables:1448kB all_unreclaimable? yes
[   61.835988] DMA free:19512kB min:16384kB low:20480kB high:24576kB reserved_highatomic:0KB active_anon:270276kB inactive_anon:168kB active_file:72kB inactive_file:472kB unevictable:0kB writepending:0kB present:524288kB managed:416628kB mlocked:0kB bounce:0kB free_pcp:584kB local_pcp:256kB free_cma:0kB
[   61.862645] lowmem_reserve[]: 0 0 0 0
[   61.884844] DMA: 647*4kB (UME) 421*8kB (UME) 265*16kB (UME) 66*32kB (UME) 19*64kB (UME) 8*128kB (UM) 6*256kB (UME) 2*512kB (UM) 2*1024kB (M) 0*2048kB 0*4096kB = 19156kB
[   61.888502] 215 total pagecache pages
[   61.903598] 0 pages in swap cache
[   61.907176] Swap cache stats: add 0, delete 0, find 0/0
[   61.910458] Free swap  = 0kB
[   61.915474] Total swap = 0kB
[   61.918628] 131072 pages RAM
[   61.921475] 0 pages HighMem/MovableOnly
[   61.924330] 26915 pages reserved
[   61.927889] Tasks state (memory values in pages):
[   61.931372] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
[   61.936003] [    732]    81   732      344       30    32768        0             0 ubusd
[   61.944523] [    733]     0   733      226        9    32768        0             0 askfirst
[   61.952762] [    768]     0   768      263       16    28672        0             0 urngd
[   61.961248] [   1285]   514  1285      332       21    32768        0             0 logd
[   61.969307] [   1345]     0  1345      941      131    32768        0             0 rpcd
[   61.977477] [   1802]     0  1802      690       26    40960        0             0 hostapd
[   61.985547] [   1803]     0  1803      690       26    40960        0             0 wpa_supplicant
[   61.993620] [   1817]   101  1817      780       52    40960        0             0 hostapd
[   62.002646] [   1818]   101  1818      760       32    40960        0             0 wpa_supplicant
[   62.010895] [   1867]     0  1867      515       52    32768        0             0 netifd
[   62.019913] [   2148]     0  2148      405       29    32768        0             0 odhcpd
[   62.028190] [   2207]     0  2207      328       13    28672        0             0 crond
[   62.036421] [   2273]     0  2273      688       35    32768        0             0 uhttpd
[   62.044691] [   3439]     0  3439      276       16    32768        0             0 dropbear
[   62.052853] [   3835]     0  3835      690       28    36864        0             0 dnsmasq
[   62.061444] [   3845]   453  3845     1179       97    40960        0             0 dnsmasq
[   62.069628] [   4645]     0  4645   255774    66712   692224        0             0 AdGuardHome
[   62.077846] [   4791]     0  4791      341       24    28672        0             0 sh
[   62.086503] [   4915]     0  4915      690       28    40960        0             0 ntpd
[   62.094493] [   4937]   123  4937      327       14    32768        0             0 ntpd
[   62.102745] [   5095]     0  5095      341       28    28672        0             0 sh
[   62.110844] [   5096]     0  5096      327       13    32768        0             0 logger
[   62.118545] [   5113]     0  5113      327        9    28672        0             0 sleep
[   62.126806] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/,task=AdGuardHome,pid=4645,uid=0
[   62.135075] Out of memory: Killed process 4645 (AdGuardHome) total-vm:1023096kB, anon-rss:266848kB, file-rss:0kB, shmem-rss:0kB, UID:0 pgtables:676kB oom_score_adj:0
[   95.885732] IPv6: ADDRCONF(NETDEV_CHANGE): phy1-ap0: link becomes ready
[   95.885960] br-lan: port 5(phy1-ap0) entered blocking state

  PID  PPID USER     STAT   VSZ %VSZ %CPU COMMAND
 7479     1 root     S     932m 229%   0% /usr/bin/AdGuardHome -c /etc/adguardhome.yaml -w /opt/AdGuardHome -s run --no-check-update

Additional information

Right now it's running edge build, but it also happens with beta build and with v107.

The problem seems to be AGH trying to blindly allocate 930 MB of RAM when it should instead check how much free RAM there is (more than 70 MB) and manage to update the filters with it.
I suppose 70 MB should be plenty RAM to update any lists.

[fixsssator]

Confirm. Have the same problem. With all functions disabled as DHCP, optimistic caching and all disabled filters i got killed process and "out of memory" too.
Use adguard v107 for AX3600

[ainar-g]

Hello.

Filters are saved in /opt (not RAM) trying to use less RAM, also logs are reduced to spare RAM.

Just to clarify, are you using the file paths instead of URIs in your filtering settings?

Also, how large are the rule files exactly?

[cjom]

TL;DR
AGH allocates a lot of RAM when settings are changed, like "Filter update interval" or even deactivating a filter list.
Even with 80 MB of free RAM it crashes with "Out of memory" error.

Just to clarify, are you using the file paths instead of URIs in your filtering settings?

I am using the URI, all from AdGuard:
https://adguardteam.github.io/HostlistsRegistry/assets/filter_*.txt

What I meant to say is the working folder is /opt and not /var or /tmp, trying to save some RAM.

Also, how large are the rule files exactly?

Getting details for this question, I found more data that I hope is useful.

For some reason, AGH allocates a lot of memory when changing settings, like "Filter update interval" (even if disabling). Also, simply disabling lists can make it crash too, because it seems to also allocate a lot of memory when a list is disabled...

• ALL LISTS DISABLED = 151~164 MB of free RAM, no crashes changing settings.

Free RAM values are a loose reference, as I noticed they float a lot as I change settings in AGH for testing.

• 1 list (The NoTracking blocklist = 9540026 bytes, 452712 rules) and free RAM drops to 83~86 MB
  Just clicking "update filters" made the free RAM drop to 51 MB

With only this list (9.5 MB) any changes to settings, like "filter update interval", makes AGH crash...

• 1 list (OISD Blocklist Full = 6681559 bytes, 282087 rules) and free RAM drops to 130~135 MB
  Just clicking "update filters" made the free RAM drop to 110 MB

No crash when changing settings...

• 16 lists (8.2 MB, 349026 rules) and free RAM drops to 126~132 MB
  Just clicking "update filters" made the free RAM drop to 108 MB

No crash when changing settings, but free RAM drops to around 40 MB for a moment.

I think something is wrong with how much RAM is allocated just to change one setting (like filter update interval)...
Also, it seems that updating the filters lists also requires a lot of RAM, and if somehow it could use the RAM more efficiently, then it could not crash...

[ainar-g]

Thanks for the details. There may be a few issues with how settings are applied, but it would be hard to diagnose without collecting memory profiles by setting debug_pprof: true and saving the contents of http://127.0.0.1:6060/debug/pprof/heap?debug=1.

Some other things that you can try:

1. Using local copies of the filters and their file paths as URLs. This will force AGH to use the file system for scanning rules, so that could reduce the amount of RAM consumed at the cost of extra i/o operations.

2. Set the GOMEMLIMIT environment variable for the AdGuard Home service, which sets a soft RAM limit. This might make the garbage collector work more actively and reduce RAM at the cost of CPU time.

[cjom]

OK, when I have some time I will collect the debug data and also test the GOMEMLIMIT variable, then report here.

EDIT:
Today had little free time but a short test got very promising results...
with GOGC=40 and GOMEMLIMIT=100MiB seems capable of handling 9 lists with total 826000 rules :)
Almost twice the rules tested yesterday!

EDIT:
Nearly 10 seconds after I change "Filter update interval", free RAM drops to little more than 20 MB and CPU usage reaches 89% but at least never crashed.

[cjom]

log1.txt
log2.txt
log3.txt

log1 had GOGC=40 and GOMEMLIMIT=100MiB and changed update interval to see free RAM dropping;
log2 no variables set, "small" filters lists, changed update interval and disabled one filter to see free RAM dropping;
log3 no variables set, "big" filters lists, changed update interval and tried to grab before crash but I don't know if succeed to grab "just before crash".

[ainar-g]

Thanks for testing our the environment variables and attaching the profiles! Unfortunately, the profiles show that most memory is consumed by the filtering engine, so there probably won't be a way to decrease that without a proper rewrite/optimization of the urlfilter module. (@ameshkov, you might be interested in the profiles.)

In the meantime, if the env solution works for you, it's probably the best you can do, along with the filepath-based filters.

[cjom]

I guess, without looking into code, it makes sense that updating filters list temporarily use a lot of memory building a new rules list before replacing the old one, but I don't see why just changing the update interval would require so much memory to be allocated... That's what I tried to log.

On the filepath-based filters, it seems that it still makes copies of local filters lists. I even made it with the exact name and local it is saved, and refreshing makes it overwrite the list with itself. Prabably that could be improved, not making copies of local lists, because it causes unnecessary writing to the router flash...

Thu Mar 23 18:41:17 2023 daemon.err AdGuardHome[4640]: 2023/03/23 18:41:17.783850 [info] saving filter 1679514854 contents to: /opt/AdGuardHome/data/filters/1679514854.txt

[ainar-g]

I've created #5629 to see if we can remove the copying. Thanks for pointing that out.