Diversion Diversion/Dnsmaq logging hangs, slowdowns

[Saus]

Hi all,

Since my new router, I have a completely reproducible issue with Diversion with logging enabled. If I have logging enabled, the CPU usages on at least 3 of 4 cores spikes to 100% intermittedly, load goes to >3 and dnsmasq hagns -- that is, devices do not get any DNS queries resolved from the router and thus, no working internet connection. Here's all the details:

1. GT-AXE16000
2. Merlin 388.1
3. AMTM, Diversion, entware... all latest versions (3.4 / 4.3.2/...) to note, before latest update, it was the same
4. Blocking list large
5. Dnsmasq cache 5000
6. 32gb USB stick
7. 5gb swap

Things I have tried:

• replace USB stick
• reduce, remove swap
• smaller blocking list
• log async on; with various parameters (up to 100........)
• ...

Now, I am out of options. The behaviour is completely consistent and reproducible. If I turn logging on, Router will hang (not all the time, but often) with the cpu usage above. Turn logging off, all fine and great.

Whelp? When I ran this setup on my RC-AT86, all was great, with great logs and Diversion stats etc.

 

[dave14305]

Is this with only Diversion, or do you also install the related addon uiDivStats? uiDivStats can be CPU intensive trying to process the dnsmasq logs.

 

[Saus]

Is this with only Diversion, or do you also install the related addon uiDivStats? uiDivStats can be CPU intensive trying to process the dnsmasq logs.

Thanks Dave. I DO have uidivstats installed.

Will try with it disabled/uninstalled and report back.

 

[Saus]

Preliminary results...... this seems to be it.

- uiDivStats removed (completely): Diversion with logging works like a charm
- uiDivStats installed, enabled: Diversion with logging renders router unusable

@thelonelycoder -- it this something worth investigating as it seems a structural issue, preventing me (and I guess others) from using uiDivStats altogether, which makes me sad!

More than willing to help if I can, let me know.

 

[thelonelycoder]

Preliminary results...... this seems to be it.

- uiDivStats removed (completely): Diversion with logging works like a charm
- uiDivStats installed, enabled: Diversion with logging renders router unusable

@thelonelycoder -- it this something worth investigating as it seems a structural issue, preventing me (and I guess others) from using uiDivStats altogether, which makes me sad!

More than willing to help if I can, let me know.

Not from my side, Diversion works fine. UiDivStats is a project by @Jack Yaz , hope he can be awakened from his slumber and offer help and perhaps a solution.

 

[Saus]

Ah sorry @thelonelycoder - I was not aware. Thanks for your attention and reply. If @Jack Yaz does awaken… I would love to help make uiDivStats great (again) it’s a great addition if it works.

 

[Jack Yaz]

uiDivStats does most of its processing overnight, normal runtime use should be minimal - all it does in normal use is pipe log entries from text file to an sqlite database
it would be useful if you could share screenshots of what htop and atop look like, so we can see the exact commands being executed by uiDivStats (htop) and whether your USB is particularly slow (atop)

 

[Saus]

@Jack Yaz Thanks! I will soon reinstall and do these tests, and post the result.

 

[Saus]

@Jack Yaz Ok, here we go. I see high loads; and the following outputs from htop. None of this happens when uiDivStats is not installed.

rvds@RoutingBakkie:/tmp/home/root# htop

0[|||||| 4.7%] Tasks: 89, 24 thr, 83 kthr; 1 running
1[||||||| 5.3%] Load average: 2.11 1.45 1.16
2[|||||| 4.6%] Uptime: 3 days, 01:33:23
3[|||||| 4.6%]
Mem[|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| 662M/1.95G]
Swp[ 0K/5.00G]

[Main] [I/O]
PID USER PRI NI VIRT RES SHR S CPU%-MEM% TIME+ Command
14702 rvds 35 15 3328 1316 1224 S 0.7 0.1 4:16.16 /bin/sh /jffs/addons/uiDivStats.d/taildns.d/taildnstotal-cache
2343 rvds 20 0 8256 4300 2588 R 2.0 0.2 0:00.52 htop
2693 rvds 20 0 13076 2860 2356 S 0.0 0.1 12:49.45 sw_devled
2774 rvds 20 0 15884 4972 4092 S 0.7 0.2 20:00.93 cfg_server
14700 rvds 35 15 3328 644 576 S 0.7 0.0 0:40.98 awk -v blockingIP=192.168.1.99 -f /jffs/addons/uiDivStats.d/taildns.d/dnsmasqtotal.awk
842 nobody 20 0 69608 68968 1696 S 1.3 3.4 9:54.69 dnsmasq --log-async
2692 rvds 20 0 13076 2892 2384 S 0.0 0.1 5:42.87 alt_watchdog
2902 rvds 20 0 15884 4972 4092 S 0.0 0.2 14:02.83 cfg_server
2989 rvds 20 0 11964 6228 5200 S 0.0 0.3 0:20.52 asd
3498 rvds 20 0 15124 8800 3524 S 1.3 0.4 14:23.29 networkmap
17473 rvds 20 0 18204 4312 3776 S 0.7 0.2 18:33.73 amas_portstatus
17872 rvds 20 0 2520 1640 1516 S 0.7 0.1 0:00.12 dropbear -p 192.168.1.1:222 -j -k
23942 rvds 20 0 3776 1840 1504 S 0.0 0.1 0:52.20 /usr/sbin/acsd2
1 rvds 20 0 15632 9788 6832 S 0.0 0.5 0:26.52 /sbin/init
535 rvds 20 0 1600 56 0 S 0.0 0.0 0:00.69 wdtd
539 rvds 20 0 1740 1056 976 S 0.0 0.1 0:00.05 hotplug2 --persistent --no-coldplug
591 rvds 20 0 2052 1180 1076 S 0.0 0.1 0:00.00 /usr/sbin/envrams
843 rvds 20 0 2936 2072 1492 S 0.0 0.1 0:00.27 dnsmasq --log-async
1604 rvds 20 0 13076 2872 2364 S 0.0 0.1 0:00.00 console
1693 rvds 20 0 13076 3960 3440 S 0.0 0.2 0:16.41 /sbin/PS_pod
1695 rvds 20 0 3328 84 0 S 0.0 0.0 0:00.63 /sbin/syslogd -m 0 -S -O /jffs/syslog.log -s 256 -l 7
1697 rvds 20 0 3328 80 0 S 0.0 0.0 0:00.04 /sbin/klogd -c 5
1778 rvds 20 0 13076 4484 3912 S 0.0 0.2 1:07.03 /sbin/wanduck
2449 rvds 20 0 2396 1576 1012 S 0.0 0.1 0:14.89 /usr/sbin/haveged -r 0 -w 1024 -d 32 -i 32
2450 rvds 20 0 11964 6228 5200 S 0.0 0.3 0:22.41 asd
2455 rvds 20 0 13964 2188 1796 S 0.0 0.1 2:42.84 nt_monitor
2456 rvds 20 0 7012 2008 1792 S 0.0 0.1 0:08.22 protect_srv
2457 rvds 20 0 15128 4096 3572 S 0.0 0.2 0:00.00 /sbin/netool
2463 rvds 20 0 15128 4096 3572 S 0.0 0.2 0:00.00 /sbin/netool
2475 rvds 20 0 7012 2008 1792 S 0.0 0.1 0:00.00 protect_srv
2490 rvds 20 0 13964 2188 1796 S 0.0 0.1 1:20.06 nt_monitor
2494 rvds 20 0 13988 3680 3104 S 0.0 0.2 0:30.83 nt_center
2504 rvds 20 0 13988 3680 3104 S 0.0 0.2 0:07.26 nt_center
2619 rvds 20 0 13076 2844 2336 S 0.0 0.1 0:00.00 wpsaide
2620 rvds 20 0 4976 2164 1940 S 0.0 0.1 2:54.06 /usr/sbin/wlc_nt
2621 rvds 20 0 4972 2228 2004 S 0.0 0.1 3:26.34 /usr/sbin/wlc_monitor
2624 rvds 20 0 7688 2164 1864 S 0.0 0.1 0:00.74 /usr/sbin/awsiot
2632 rvds 20 0 3328 408 352 S 0.0 0.0 0:00.00 sh -c ATE Get_WanLanStatus > /tmp/ERP/ERP_GPHY
2633 rvds 20 0 3124 1736 1556 S 0.0 0.1 0:14.21 /bin/ceventd
2634 rvds 20 0 13076 2744 2240 S 0.0 0.1 0:00.00 ATE Get_WanLanStatus
2640 rvds 20 0 5708 1032 876 S 0.0 0.1 0:00.00 AiProtectionMonitor -e
2641 rvds 20 0 13076 2884 2376 S 0.0 0.1 0:00.00 /sbin/ntpd_synced periodic
2642 rvds 20 0 13076 2796 2288 S 0.0 0.1 0:00.01 dhcpc_lease arp-del 00:11:32:7b:bf:86 192.168.1.4
2669 rvds 20 0 13964 2188 1796 S 0.0 0.1 1:19.81 nt_monitor
2671 rvds 20 0 5028 692 604 S 0.0 0.0 0:00.70 nt_actMail
2672 rvds 20 0 5028 692 604 S 0.0 0.0 0:00.00 nt_actMail
2674 nobody 20 0 3324 2360 1992 S 0.0 0.1 0:46.65 avahi-daemon: running [RoutingBakkie.local]
2680 rvds 20 0 3328 100 0 S 0.0 0.0 0:01.11 crond -l 9
2681 rvds 20 0 12296 8900 6824 S 2.6 0.4 2:27.74 httpd -i br0
2683 rvds 20 0 6104 2916 2536 S 0.0 0.1 0:00.00 vis-dcon
2685 rvds 20 0 9180 2944 2436 S 0.0 0.1 0:41.36 vis-dcon
2686 rvds 20 0 4916 1680 1488 S 0.0 0.1 0:31.36 vis-datacollector
F1Help F2Setup F3SearchF4FilterF5Tree F6SortByF7Nice -F8Nice +F9Kill F10Quit

Atop in next message due to character limit.

 

[Saus]

Atop I do not really know how to read, but here we go:

1/2

rvds@RoutingBakkie:/tmp/home/root# atop
ATOP - RoutingBakkie 2023/03/22 15:41:08 ----------------- 3d1h36m53s elapsed
PRC | sys 2h28m | user 74m38s | | | #proc 173 | #trun 1 | | #tslpi 162 | #tslpu 33 | | #zombie 1 | clones 554e4 | | | no procacct |
CPU | sys 5% | user 3% | | irq 0% | | | idle 364% | wait 28% | | steal 0% | guest 0% | | | ? | |
cpu | sys 2% | user 0% | | irq 0% | | | idle 91% | cpu000 w 6% | | steal 0% | guest 0% | | | ? | |
cpu | sys 1% | user 1% | | irq 0% | | | idle 91% | cpu001 w 7% | | steal 0% | guest 0% | | | ? | |
cpu | sys 1% | user 1% | | irq 0% | | | idle 91% | cpu003 w 8% | | steal 0% | guest 0% | | | ? | |
cpu | sys 1% | user 1% | | irq 0% | | | idle 92% | cpu002 w 7% | | steal 0% | guest 0% | | | ? | |
CPL | avg1 1.21 | | avg5 1.32 | | avg15 1.13 | | | csw 101505e4 | | intr 63030e4 | | | | numcpu 4 | |
MEM | tot 2.0G | free 597.5M | cache 574.8M | dirty 0.0M | buff 137.5M | slab 193.6M | slrec 27.0M | | shmem 3.4M | shrss 0.8M | shswp 0.0M | | | | numnode 0 |
SWP | tot 5.0G | | free 5.0G | | swcac 0.0M | | | | | | | vmcom 238.7M | | vmlim 6.0G | |
DSK | sda | busy 14% | read 1872 | | write 217271 | discrd 0 | KiB/r 41 | KiB/w 19 | | KiB/d 0 | MBr/s 0.0 | MBw/s 0.0 | avq 94.66 | | avio |
NET | transport | tcpi 1309468 | tcpo 1244200 | | udpi 10471e3 | udpo 7847437 | tcpao 55366 | tcppo 174975 | | tcprs 1588 | tcpie 1 | tcpor 409 | udpnp 1344e3 | | udpie 573 |
NET | network | ipi 35790672 | | ipo 32470671 | ipfrw 2244e4 | | deliv 1299e4 | | | | | | icmpi 452111 | icmpo 21 | |
NET | bcmsw ---- | | pcki 85284e3 | pcko 70054e3 | | sp 0 Mbps | si 1982 Kbps | so 1636 Kbps | | coll 0 | mlti 2087501 | erri 114 | erro 0 | drpi 114 | drpo 0 |
NET | eth0 ---- | | pcki 62142e3 | pcko 25575e3 | | sp 0 Mbps | si 1809 Kbps | so 289 Kbps | | coll 0 | mlti 53883 | erri 0 | erro 0 | drpi 0 | drpo 0 |
NET | br0 ---- | | pcki 24729e3 | pcko 52246e3 | | sp 0 Mbps | si 169 Kbps | so 1656 Kbps | | coll 0 | mlti 2029718 | erri 0 | erro 0 | drpi 306 | drpo 0 |
NET | eth5 ---- | | pcki 23142e3 | pcko 44479e3 | | sp 0 Mbps | si 172 Kbps | so 1346 Kbps | | coll 0 | mlti 2033618 | erri 114 | erro 0 | drpi 79571 | drpo 0 |
NET | eth8 ---- | | pcki 1409371 | pcko 10276e3 | | sp 0 Mbps | si 11 Kbps | so 343 Kbps | | coll 0 | mlti 73676 | erri 0 | erro 0 | drpi 22 | drpo 24410 |
NET | tun21 ---- | | pcki 4086209 | pcko 2545212 | | sp 0 Mbps | si 84 Kbps | so 69 Kbps | | coll 0 | mlti 0 | erri 0 | erro 0 | drpi 0 | drpo 0 |
NET | eth7 ---- | | pcki 115404 | pcko 2522220 | | sp 0 Mbps | si 1 Kbps | so 37 Kbps | | coll 0 | mlti 8774 | erri 0 | erro 0 | drpi 22 | drpo 23879 |
NET | eth10 ---- | | pcki 198938 | pcko 2509091 | | sp 0 Mbps | si 0 Kbps | so 33 Kbps | | coll 0 | mlti 11402 | erri 0 | erro 0 | drpi 23 | drpo 24732 |
NET | eth9 ---- | | pcki 0 | pcko 2326239 | | sp 0 Mbps | si 0 Kbps | so 31 Kbps | | coll 0 | mlti 0 | erri 0 | erro 0 | drpi 22 | drpo 23833 |
NET | lo ---- | | pcki 1575153 | pcko 1575153 | | sp 0 Mbps | si 10 Kbps | so 10 Kbps | | coll 0 | mlti 0 | erri 0 | erro 0 | drpi 0 | drpo 0 |
NET | wl3.1 ---- | | pcki 75946 | pcko 1078830 | | sp 0 Mbps | si 0 Kbps | so 15 Kbps | | coll 0 | mlti 451 | erri 0 | erro 0 | drpi 1 | drpo 4091 |
*** System and Process Activity since Boot *** Unrestricted view (privileged)

 

[Saus]

Atop 2/2

PID SYSCPU USRCPU RDELAY VGROW RGROW RUID EUID ST EXC THR S CPUNR CPU CMD 1/5
410 48m23s 0.00s 0.00s 0B 0B rvds rvds N- - 1 S 0 1% bcmsw_rx
2774 11m16s 8m47s 0.00s 15.5M 4.9M rvds rvds N- - 3 S 1 0% cfg_server
3439 20.31s 19m19s 0.00s 54.8M 12.6M nobody nobody N- - 2 S 3 0% pixelserv-tls
17473 13m11s 5m24s 0.00s 17.8M 4.2M rvds rvds N- - 3 S 3 0% amas_portstatu
2690 13m20s 5m05s 0.00s 12.8M 4.7M rvds rvds N- - 1 S 2 0% watchdog
3498 2m49s 11m36s 0.00s 14.8M 8.6M rvds rvds N- - 1 S 3 0% networkmap
2693 11m03s 1m47s 0.00s 12.8M 2.8M rvds rvds N- - 1 S 2 0% sw_devled
842 1m55s 8m00s 0.00s 68.0M 67.4M nobody nobody N- - 1 S 3 0% dnsmasq
2692 4m23s 79.93s 0.00s 12.8M 2.8M rvds rvds N- - 1 S 1 0% alt_watchdog
16711 3m43s 82.39s 0.00s 9.3M 7.7M rvds rvds N- - 1 S 1 0% vpnserver1
14702 3m43s 35.51s 0.00s 3.2M 1.3M rvds rvds N- - 1 S 3 0% taildnstotal-c
2621 1m49s 97.48s 0.00s 4.9M 2.2M rvds rvds N- - 1 S 0 0% wlc_monitor
401 3m20s 0.00s 0.00s 0B 0B rvds rvds N- - 1 S 2 0% fc_timer
2689 2m25s 30.04s 0.00s 10.5M 8.8M rvds rvds N- - 1 S 2 0% sysstate
2620 13.98s 2m40s 0.00s 4.9M 2.1M rvds rvds N- - 1 S 2 0% wlc_nt
2455 2m04s 39.13s 0.00s 13.6M 2.1M rvds rvds N- - 3 S 1 0% nt_monitor
2681 83.07s 67.05s 0.00s 12.0M 8.7M rvds rvds N- - 1 S 1 0% httpd
42 1m46s 0.00s 0.00s 0B 0B rvds rvds N- - 1 I 2 0% kworker/2:1-ev
23768 94.29s 8.36s 0.00s 17.8M 4.1M rvds rvds N- - 3 S 0 0% roamast
40 97.00s 3.51s 0.00s 0B 0B rvds rvds N- - 1 S 1 0% skb_free_task
10 97.31s 0.02s 0.00s 0B 0B rvds rvds N- - 1 I 1 0% rcu_preempt
967 85.17s 0.00s 0.00s 0B 0B rvds rvds N- - 1 S 3 0% dhd_watchdog_t
958 84.41s 0.00s 0.00s 0B 0B rvds rvds N- - 1 S 2 0% dhd_watchdog_t
983 84.00s 0.00s 0.00s 0B 0B rvds rvds N- - 1 S 2 0% dhd_watchdog_t
975 83.45s 0.00s 0.00s 0B 0B rvds rvds N- - 1 S 2 0% dhd_watchdog_t
1778 39.71s 27.38s 0.00s 12.8M 4.4M rvds rvds N- - 1 S 1 0% wanduck
394 61.00s 0.00s 0.00s 0B 0B rvds rvds N- - 1 S 3 0% recycle_sysb
23942 48.24s 4.07s 0.00s 3.7M 1.8M rvds rvds N- - 1 S 1 0% acsd2
2674 14.59s 32.09s 0.00s 3.2M 2.3M nobody nobody N- - 1 S 2 0% avahi-daemon
2685 13.19s 28.21s 0.00s 9.0M 2.9M rvds rvds N- - 1 S 1 0% vis-dcon
14700 0.97s 40.41s 0.00s 3.2M 644.0K rvds rvds N- - 1 S 0 0% awk
25426 21.09s 13.10s 0.00s 4.4M 3.4M rvds rvds N- - 1 S 3 0% rstats
16659 24.17s 8.99s 0.00s 2.1M 144.0K rvds rvds N- - 1 S 2 0% miniupnpd
2686 18.40s 12.99s 0.00s 4.8M 1.6M rvds rvds N- - 1 S 1 0% vis-datacollec
2494 15.47s 15.39s 0.00s 13.7M 3.6M rvds rvds N- - 2 S 3 0% nt_center
259 28.75s 0.00s 0.00s 0B 0B rvds rvds N- - 1 S 2 0% ubifs_bgt0_13
1 21.18s 5.36s 0.00s 15.3M 9.6M rvds rvds N- - 1 S 3 0% init

 

[Jack Yaz]

Screenshots would be much easier to read please

 

[jjones7791]

For what it's worth, I believe I'm having the same issue with my RT-AX86U Pro running Merlin 388.1 with only Skynet, Diversion and uidivstats installed. Load hitting 5 every few minutes after being up for over a week, after uninstalling uidivstats hovers around 1.25 and doesn't go over 2. Will post some stats when I get a chance.