Netgear R7800 exploration (IPQ8065, QCA9984)

#1538

There are no diffrences my R7800 device and other users. And testing environment is clean/reset state. So, there is no other factors to involve. (Also, I disconnected WAN connection. No diffs.)

Your screen: 87% idle, 6% kworker --> This is not normal. And same with me.

Can you try 'htop -d1'?

It's easy to test. Install: opkg update && opkg install htop
Run: htop -d1 or -d2

Then, Every 2sec. CPU 1 will touch 100%.

P.S.: 100% or 20% is NOT IMPORTANT. Important thing is something consumes processor power and this will make some slowdown. Furthermore, Only happens on OpenWRT.

0 Likes

#1539

I see what you mean yes. I guess one could try and find the issue with perf record command but I can't find it with opkg.

0 Likes

#1540

I ran it, here's the summary

Average:      UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
Average:        0         5    0.00    0.01    0.00    0.00    0.01     -  kworker/u4:0
Average:        0         7    0.00    0.05    0.00    0.00    0.05     -  ksoftirqd/0
Average:        0         8    0.00    0.08    0.00    0.00    0.08     -  rcu_preempt
Average:        0       810    0.01    0.02    0.00    0.00    0.03     -  netifd
Average:        0       921    0.00    0.01    0.00    0.00    0.01     -  odhcpd
Average:        0      1498    0.01    0.09    0.00    0.00    0.10     -  hostapd
Average:        0      1715    0.02    0.02    0.00    0.00    0.04     -  nlbwmon
Average:        0      1775    0.03    0.03    0.00    0.00    0.07     -  collectd
Average:        0      1918    0.02    0.11    0.00    0.00    0.13     -  hostapd
Average:        0      2256    0.01    0.01    0.00    0.00    0.02     -  irqbalance
Average:      453      3021    0.14    0.00    0.00    0.00    0.14     -  dnsmasq
Average:        0      3530    0.00   13.68    0.00    0.00   13.68     -  kworker/0:0
Average:        0      3549    0.03    0.07    0.00    0.00    0.10     -  dropbear
Average:        0      3572    0.00    0.01    0.00    0.00    0.01     -  kworker/u4:2
Average:        0      3736    0.00    0.09    0.00    0.00    0.09     -  kworker/1:1
Average:        0      3831    0.15    0.42    0.00    0.00    0.58     -  pidstat

here's the sysreq output, i seem to get the same every time:

[ 8530.210232] Sending NMI from CPU 1 to CPUs 0:
[ 8530.210365] NMI backtrace for cpu 0
[ 8530.210368] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.14.109 #0
[ 8530.210369] Hardware name: Generic DT based system
[ 8530.210371] task: c0b06cc0 task.stack: c0b00000
[ 8530.210372] PC is at arch_cpu_idle+0x38/0x44
[ 8530.210375] LR is at arch_cpu_idle+0x34/0x44
[ 8530.210376] pc : [<c0308930>]    lr : [<c030892c>]    psr: 60000013
[ 8530.210377] sp : c0b01f98  ip : c0b01f90  fp : 00000000
[ 8530.210379] r10: 00000000  r9 : c0a28a28  r8 : 00000000
[ 8530.210380] r7 : 00000000  r6 : c0b03c70  r5 : c0b03cbc  r4 : ffffe000
[ 8530.210382] r3 : c03152a0  r2 : 00000000  r1 : 00000000  r0 : 00000001
[ 8530.210383] Flags: nZCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment none
[ 8530.210385] Control: 10c5787d  Table: 5b7c806a  DAC: 00000051
[ 8530.210386] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.14.109 #0
[ 8530.210388] Hardware name: Generic DT based system
[ 8530.210389] [<c030f478>] (unwind_backtrace) from [<c030b644>] (show_stack+0x14/0x20)
[ 8530.210391] [<c030b644>] (show_stack) from [<c079e4b8>] (dump_stack+0x88/0x9c)
[ 8530.210394] [<c079e4b8>] (dump_stack) from [<c07a4644>] (nmi_cpu_backtrace+0xac/0xd8)
[ 8530.210395] [<c07a4644>] (nmi_cpu_backtrace) from [<c030e738>] (handle_IPI+0x154/0x194)
[ 8530.210397] [<c030e738>] (handle_IPI) from [<c03014b8>] (gic_handle_irq+0x9c/0xb8)
[ 8530.210398] [<c03014b8>] (gic_handle_irq) from [<c030c20c>] (__irq_svc+0x6c/0xa8)
[ 8530.210400] Exception stack(0xc0b01f48 to 0xc0b01f90)
[ 8530.210401] 1f40:                   00000001 00000000 00000000 c03152a0 ffffe000 c0b03cbc
[ 8530.210403] 1f60: c0b03c70 00000000 00000000 c0a28a28 00000000 00000000 c0b01f90 c0b01f98
[ 8530.210404] 1f80: c030892c c0308930 60000013 ffffffff
[ 8530.210406] [<c030c20c>] (__irq_svc) from [<c0308930>] (arch_cpu_idle+0x38/0x44)
[ 8530.210408] [<c0308930>] (arch_cpu_idle) from [<c0359a5c>] (do_idle+0xe8/0x1bc)
[ 8530.210409] [<c0359a5c>] (do_idle) from [<c0359dd4>] (cpu_startup_entry+0x1c/0x20)
[ 8530.210411] [<c0359dd4>] (cpu_startup_entry) from [<c0a00ce8>] (start_kernel+0x414/0x420)
1 Like

#1541

Apologies for posting about the r7500v2 in the r7800 thread, but I have noticed similar symptoms as well.

The elevated load average/spikiness was not present in 'OpenWrt SNAPSHOT r9545-9c216fbbde' (kernel 4.14.104) but I do observe it in OpenWrt SNAPSHOT r9739-b2152c8e6b (kernel 4.14.108).

output of pidstat -H 2:

root@OpenWrt:~/local# pidstat -H 2
Linux 4.14.108 (OpenWrt) 	04/06/19 	_armv7l_	(2 CPU)

1554550697    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550699      0      6139    0.00    0.49    0.00    0.00    0.49     1  kworker/1:2
1554550699      0      6884    0.00    1.48    0.00    0.00    1.48     0  pidstat
1554550699      0     30027    0.00   21.18    0.00    0.00   21.18     0  kworker/0:1

1554550699    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550701      0         8    0.00    0.50    0.00    0.00    0.50     1  rcu_sched
1554550701      0        14    0.00    0.50    0.00    0.00    0.50     1  ksoftirqd/1
1554550701      0      6139    0.00    0.50    0.00    0.00    0.50     1  kworker/1:2
1554550701      0      6621    0.00    0.50    0.00    0.00    0.50     1  dropbear
1554550701      0      6884    0.50    0.50    0.00    0.00    0.99     0  pidstat
1554550701      0     30027    0.00   20.79    0.00    0.00   20.79     0  kworker/0:1

1554550701    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550703      0         7    0.00    0.50    0.00    0.00    0.50     0  ksoftirqd/0
1554550703      0        14    0.00    1.00    0.00    0.00    1.00     1  ksoftirqd/1
1554550703      0      6139    0.00    0.50    0.00    0.00    0.50     1  kworker/1:2
1554550703      0      6884    1.49    0.50    0.00    0.00    1.99     0  pidstat
1554550703      0     30027    0.00   20.40    0.00    0.00   20.40     0  kworker/0:1

1554550703    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550705      0         8    0.00    0.50    0.00    0.00    0.50     1  rcu_sched
1554550705      0       667    0.00    1.00    0.00    0.00    1.00     1  logd
1554550705      0      3009    0.00    0.50    0.00    0.00    0.50     0  hostapd
1554550705      0      6139    0.00    0.50    0.00    0.00    0.50     1  kworker/1:2
1554550705      0      6884    0.50    0.50    0.00    0.00    1.00     1  pidstat
1554550705      0     30027    0.00   15.00    0.00    0.00   15.00     0  kworker/0:1

1554550705    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550707      0        14    0.00    0.98    0.00    0.00    0.98     1  ksoftirqd/1
1554550707      0      3273    0.00    0.49    0.00    0.00    0.49     1  hostapd
1554550707      0      6139    0.00    0.98    0.00    0.00    0.98     1  kworker/1:2
1554550707      0      6621    0.00    0.49    0.00    0.00    0.49     1  dropbear
1554550707      0      6884    0.98    0.98    0.00    0.00    1.96     1  pidstat
1554550707      0     30027    0.00    5.88    0.00    0.00    5.88     0  kworker/0:1

1554550707    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550709      0      3064    0.50    0.00    0.00    0.00    0.50     1  charon
1554550709      0      6621    0.50    0.00    0.00    0.00    0.50     1  dropbear
1554550709      0      6884    0.00    1.50    0.00    0.00    1.50     1  pidstat
1554550709      0     30027    0.00   21.00    0.00    0.00   21.00     0  kworker/0:1

1554550709    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550711      0         8    0.00    0.50    0.00    0.00    0.50     1  rcu_sched
1554550711      0        14    0.00    1.00    0.00    0.00    1.00     1  ksoftirqd/1
1554550711      0       696    0.00    0.50    0.00    0.00    0.50     1  irqbalance
1554550711      0      6139    0.00    0.50    0.00    0.00    0.50     1  kworker/1:2
1554550711      0      6884    0.50    1.00    0.00    0.00    1.50     1  pidstat
1554550711      0     30027    0.00   20.00    0.00    0.00   20.00     0  kworker/0:1

1554550711    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550713      0         7    0.00    0.50    0.00    0.00    0.50     0  ksoftirqd/0
1554550713      0        14    0.00    0.50    0.00    0.00    0.50     1  ksoftirqd/1
1554550713      0      2681    0.50    2.00    0.00    0.00    2.50     1  collectd
1554550713      0      6139    0.00    0.50    0.00    0.00    0.50     1  kworker/1:2
1554550713      0      6621    0.00    0.50    0.00    0.00    0.50     1  dropbear
1554550713      0      6884    0.50    0.50    0.00    0.00    1.00     1  pidstat
1554550713      0     29484    0.00    0.50    0.00    0.00    0.50     1  kworker/u4:0
1554550713      0     30027    0.00   20.50    0.00    0.00   20.50     0  kworker/0:1

1554550713    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550715      0        14    0.00    0.50    0.00    0.00    0.50     1  ksoftirqd/1
1554550715      0       667    0.50    0.50    0.00    0.00    1.00     0  logd
1554550715      0       841    0.00    0.50    0.00    0.00    0.50     1  netifd
1554550715      0      2572    0.00    0.50    0.00    0.00    0.50     0  odhcpd
1554550715      0      6139    0.00    0.50    0.00    0.00    0.50     1  kworker/1:2
1554550715      0      6621    0.00    0.50    0.00    0.00    0.50     1  dropbear
1554550715      0      6884    0.00    1.00    0.00    0.00    1.00     1  pidstat
1554550715      0     30027    0.00   21.00    0.00    0.00   21.00     0  kworker/0:1

1554550715    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550717      0         8    0.00    0.50    0.00    0.00    0.50     1  rcu_sched
1554550717      0        14    0.00    0.50    0.00    0.00    0.50     1  ksoftirqd/1
1554550717      0      6139    0.00    0.50    0.00    0.00    0.50     1  kworker/1:2
1554550717      0      6621    0.00    0.50    0.00    0.00    0.50     1  dropbear
1554550717      0      6884    0.50    1.00    0.00    0.00    1.50     1  pidstat

1554550717    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550719      0      3009    0.00    0.50    0.00    0.00    0.50     0  hostapd
1554550719      0      6139    0.00    0.50    0.00    0.00    0.50     1  kworker/1:2
1554550719      0      6621    0.00    0.50    0.00    0.00    0.50     1  dropbear
1554550719      0      6884    0.00    1.50    0.00    0.00    1.50     1  pidstat
1554550719      0     30027    0.00   21.00    0.00    0.00   21.00     0  kworker/0:1

1554550719    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550721      0         7    0.00    0.50    0.00    0.00    0.50     0  ksoftirqd/0
1554550721      0        14    0.00    1.00    0.00    0.00    1.00     1  ksoftirqd/1
1554550721      0      6139    0.00    0.50    0.00    0.00    0.50     1  kworker/1:2
1554550721      0      6621    0.00    0.50    0.00    0.00    0.50     1  dropbear
1554550721      0      6884    0.50    1.50    0.00    0.00    2.00     0  pidstat
1554550721      0     30027    0.00   21.00    0.00    0.00   21.00     0  kworker/0:1

1554550721    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550723      0         8    0.00    0.50    0.00    0.00    0.50     1  rcu_sched
1554550723      0        14    0.00    0.50    0.00    0.00    0.50     1  ksoftirqd/1
1554550723      0      6139    0.00    0.50    0.00    0.00    0.50     1  kworker/1:2
1554550723      0      6884    0.99    0.00    0.00    0.00    0.99     0  pidstat
1554550723      0     30027    0.00   20.79    0.00    0.00   20.79     0  kworker/0:1

1554550723    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550725      0         7    0.00    0.50    0.00    0.00    0.50     0  ksoftirqd/0
1554550725      0        14    0.00    1.00    0.00    0.00    1.00     1  ksoftirqd/1
1554550725      0       667    0.50    0.50    0.00    0.00    1.00     0  logd
1554550725    453      4680    0.00    0.50    0.00    0.00    0.50     1  dnsmasq
1554550725      0      6139    0.00    1.00    0.00    0.00    1.00     1  kworker/1:2
1554550725      0      6884    0.00    1.00    0.00    0.00    1.00     0  pidstat
1554550725      0     30027    0.00   19.00    0.00    0.00   19.00     0  kworker/0:1

1554550725    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554550727      0         8    0.00    0.50    0.00    0.00    0.50     1  rcu_sched
1554550727    453      4680    0.50    0.00    0.00    0.00    0.50     1  dnsmasq
1554550727      0      6884    0.00    1.00    0.00    0.00    1.00     1  pidstat
1554550727      0     29484    0.00    0.50    0.00    0.00    0.50     1  kworker/u4:0
1554550727      0     30027    0.00    5.50    0.00    0.00    5.50     0  kworker/0:1
^C

Average:      UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
Average:        0         7    0.00    0.13    0.00    0.00    0.13     -  ksoftirqd/0
Average:        0         8    0.00    0.20    0.00    0.00    0.20     -  rcu_sched
Average:        0        14    0.00    0.50    0.00    0.00    0.50     -  ksoftirqd/1
Average:        0       667    0.07    0.13    0.00    0.00    0.20     -  logd
Average:        0       696    0.00    0.03    0.00    0.00    0.03     -  irqbalance
Average:        0       841    0.00    0.03    0.00    0.00    0.03     -  netifd
Average:        0      2572    0.00    0.03    0.00    0.00    0.03     -  odhcpd
Average:        0      2681    0.03    0.13    0.00    0.00    0.17     -  collectd
Average:        0      3009    0.00    0.07    0.00    0.00    0.07     -  hostapd
Average:        0      3064    0.03    0.00    0.00    0.00    0.03     -  charon
Average:        0      3273    0.00    0.03    0.00    0.00    0.03     -  hostapd
Average:      453      4680    0.03    0.03    0.00    0.00    0.07     -  dnsmasq
Average:        0      6139    0.00    0.50    0.00    0.00    0.50     -  kworker/1:2
Average:        0      6621    0.03    0.23    0.00    0.00    0.27     -  dropbear
Average:        0      6884    0.43    0.93    0.00    0.00    1.36     -  pidstat
Average:        0     29484    0.00    0.07    0.00    0.00    0.07     -  kworker/u4:0
Average:        0     30027    0.00   16.87    0.00    0.00   16.87     -  kworker/0:100:

Suggestions to further help identify the root cause are welcome.

One note, I had 21+ days uptime on 9545 and only stopped to "upgrade." A few days before the update, I started using strongswan and cake/piece of cake. Still, the load average did not start spiking like it does on 9739. I also observed the following stack trace (once not long after boot - current uptime is 8+ days) in 9739 but I don't know if its related:

[94921.246407] ------------[ cut here ]------------
[94921.246484] WARNING: CPU: 1 PID: 2760 at backports-4.19.23-1/net/wireless/util.c:1146 cfg80211_calculate_bitrate+0x1cc/0x254 [cfg80211]
[94921.250209] invalid rate bw=0, mcs=15, nss=4
[94921.262068] Modules linked in: pppoe ppp_async ath10k_pci ath10k_core ath rndis_host pppox ppp_generic nf_conntrack_ipv6 mac80211 iptable_nat ipt_REJECT ipt_MASQUERADE cfg80211 cdc_ether xt_time xt_tcpudp xt_tcpmss xt_statistic xt_state xt_recent xt_policy xt_nat xt_multiport xt_mark xt_mac xt_limit xt_length xt_hl xt_helper xt_esp xt_ecn xt_dscp xt_conntrack xt_connmark xt_connlimit xt_connbytes xt_comment xt_TCPMSS xt_REDIRECT xt_LOG xt_HL xt_FLOWOFFLOAD xt_DSCP xt_CT xt_CLASSIFY usbnet ums_usbat ums_sddr55 ums_sddr09 ums_karma ums_jumpshot ums_isd200 ums_freecom ums_datafab ums_cypress ums_alauda slhc nf_reject_ipv4 nf_nat_redirect nf_nat_masquerade_ipv4 nf_conntrack_ipv4 nf_nat_ipv4 nf_nat nf_log_ipv4 nf_flow_table_hw nf_flow_table nf_defrag_ipv6 nf_defrag_ipv4 nf_conntrack_rtcache iptable_raw
[94921.314901]  iptable_mangle iptable_filter ipt_ah ipt_ECN ip_tables crc_itu_t crc_ccitt compat sch_cake nf_conntrack sch_tbf sch_ingress sch_htb sch_hfsc em_u32 cls_u32 cls_tcindex cls_route cls_matchall cls_fw cls_flow cls_basic act_skbedit act_mirred ledtrig_usbport nf_log_ipv6 nf_log_common ip6table_mangle ip6table_filter ip6_tables ip6t_REJECT x_tables nf_reject_ipv6 ifb xfrm6_mode_tunnel xfrm6_mode_transport xfrm6_mode_beet ipcomp6 xfrm6_tunnel esp6 ah6 xfrm4_tunnel xfrm4_mode_tunnel xfrm4_mode_transport xfrm4_mode_beet ipcomp esp4 ah4 tunnel6 tunnel4 tun xfrm_user xfrm_ipcomp af_key xfrm_algo vfat fat ntfs nls_utf8 nls_iso8859_1 nls_cp437 algif_skcipher algif_hash af_alg sha1_generic md5 echainiv authenc uas usb_storage leds_gpio xhci_plat_hcd xhci_pci xhci_hcd dwc3 dwc3_of_simple ohci_platform
[94921.385467]  ohci_hcd phy_qcom_dwc3 ahci ehci_platform sd_mod ahci_platform libahci_platform libahci libata scsi_mod ehci_hcd f2fs ext4 mbcache jbd2 crc32c_generic crc32_generic
[94921.407715] CPU: 1 PID: 2760 Comm: reader#0 Not tainted 4.14.108 #0
[94921.423612] Hardware name: Generic DT based system
[94921.429712] [<c030f2b4>] (unwind_backtrace) from [<c030b490>] (show_stack+0x14/0x20)
[94921.434564] [<c030b490>] (show_stack) from [<c07c0118>] (dump_stack+0x88/0x9c)
[94921.442464] [<c07c0118>] (dump_stack) from [<c0322be8>] (__warn+0xf0/0x11c)
[94921.449491] [<c0322be8>] (__warn) from [<c0322c48>] (warn_slowpath_fmt+0x34/0x4c)
[94921.456372] [<c0322c48>] (warn_slowpath_fmt) from [<bf653b40>] (cfg80211_calculate_bitrate+0x1cc/0x254 [cfg80211])
[94921.464082] [<bf653b40>] (cfg80211_calculate_bitrate [cfg80211]) from [<bf67eb7c>] (nl80211_put_sta_rate+0x48/0x2e8 [cfg80211])
[94921.474296] [<bf67eb7c>] (nl80211_put_sta_rate [cfg80211]) from [<bf666e94>] (nl80211_update_connect_params+0x7c4/0x1078 [cfg80211])
[94921.485649] [<bf666e94>] (nl80211_update_connect_params [cfg80211]) from [<bf66fe40>] (nl80211_dump_station+0xe8/0x134 [cfg80211])
[94921.497790] [<bf66fe40>] (nl80211_dump_station [cfg80211]) from [<c06e22a8>] (genl_lock_dumpit+0x3c/0x60)
[94921.509304] [<c06e22a8>] (genl_lock_dumpit) from [<c06df5f4>] (netlink_dump+0x114/0x2a4)
[94921.518934] [<c06df5f4>] (netlink_dump) from [<c06dfcec>] (__netlink_dump_start+0xe8/0x1b4)
[94921.527095] [<c06dfcec>] (__netlink_dump_start) from [<c06e2ddc>] (genl_rcv_msg+0x194/0x3a0)
[94921.535168] [<c06e2ddc>] (genl_rcv_msg) from [<c06e1f98>] (netlink_rcv_skb+0x94/0x110)
[94921.543849] [<c06e1f98>] (netlink_rcv_skb) from [<c06e2c2c>] (genl_rcv+0x2c/0x48)
[94921.551572] [<c06e2c2c>] (genl_rcv) from [<c06e16fc>] (netlink_unicast+0x164/0x224)
[94921.559124] [<c06e16fc>] (netlink_unicast) from [<c06e1bcc>] (netlink_sendmsg+0x334/0x390)
[94921.566600] [<c06e1bcc>] (netlink_sendmsg) from [<c068a8e0>] (sock_sendmsg+0x18/0x34)
[94921.574927] [<c068a8e0>] (sock_sendmsg) from [<c068ae88>] (___sys_sendmsg+0x214/0x250)
[94921.582824] [<c068ae88>] (___sys_sendmsg) from [<c068be08>] (__sys_sendmsg+0x48/0x78)
[94921.590637] [<c068be08>] (__sys_sendmsg) from [<c0307da0>] (ret_fast_syscall+0x0/0x54)
[94921.598620] ---[ end trace 0ea683e995b5dbc4 ]---
0 Likes

#1543

My Result, Below:

Linux 4.14.109 (OpenWrt_QCA9984)        04/06/19        _armv7l_        (2 CPU)

1554552409    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552412      0       981    0.00    0.50    0.00    0.00    0.50     1  kworker/1:3
1554552412      0      1375    0.50    0.00    0.00    0.00    0.50     0  hostapd
1554552412      0      1536    0.00   20.79    0.00    0.00   20.79     0  kworker/0:0
1554552412      0      4957    0.00    1.49    0.00    0.00    1.49     1  pidstat

1554552412    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552414      0         7    0.00    0.50    0.00    0.00    0.50     0  ksoftirqd/0
1554552414      0      1536    0.00   21.00    0.00    0.00   21.00     0  kworker/0:0
1554552414      0      3958    0.50    0.00    0.00    0.00    0.50     1  dropbear
1554552414      0      4957    0.00    1.00    0.00    0.00    1.00     1  pidstat

1554552414    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552416      0         8    0.00    0.50    0.00    0.00    0.50     0  rcu_sched
1554552416      0      1375    0.50    0.00    0.00    0.00    0.50     0  hostapd
1554552416      0      1536    0.00    4.98    0.00    0.00    4.98     0  kworker/0:0
1554552416      0      4957    0.00    1.00    0.00    0.00    1.00     1  pidstat

1554552416    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552418      0       548    0.00    0.50    0.00    0.00    0.50     0  netifd
1554552418      0       981    0.00    0.50    0.00    0.00    0.50     1  kworker/1:3
1554552418      0      1536    0.00   15.50    0.00    0.00   15.50     0  kworker/0:0
1554552418      0      4957    0.00    1.50    0.00    0.00    1.50     1  pidstat

1554552418    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552420      0      1031    0.50    0.00    0.00    0.00    0.50     0  udhcpc
1554552420      0      1536    0.00   20.50    0.00    0.00   20.50     0  kworker/0:0
1554552420      0      4957    0.50    0.50    0.00    0.00    1.00     1  pidstat

1554552420    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552422      0       981    0.00    0.50    0.00    0.00    0.50     1  kworker/1:3
1554552422      0      1375    0.00    0.50    0.00    0.00    0.50     0  hostapd
1554552422      0      1536    0.00   21.00    0.00    0.00   21.00     0  kworker/0:0
1554552422      0      4957    1.00    0.50    0.00    0.00    1.50     1  pidstat

1554552422    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552424      0      1536    0.00   21.00    0.00    0.00   21.00     0  kworker/0:0
1554552424      0      3958    0.00    0.50    0.00    0.00    0.50     1  dropbear
1554552424      0      4957    1.00    0.50    0.00    0.00    1.50     1  pidstat

1554552424    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552426      0      1375    0.00    0.50    0.00    0.00    0.50     0  hostapd
1554552426      0      1536    0.00   10.00    0.00    0.00   10.00     0  kworker/0:0
1554552426      0      4957    1.00    0.00    0.00    0.00    1.00     1  pidstat

1554552426    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552428      0         8    0.00    0.50    0.00    0.00    0.50     1  rcu_sched
1554552428      0       981    0.00    0.50    0.00    0.00    0.50     1  kworker/1:3
1554552428      0      1536    0.00   11.00    0.00    0.00   11.00     0  kworker/0:0
1554552428      0      3958    0.50    0.00    0.00    0.00    0.50     1  dropbear
1554552428      0      4957    0.50    0.50    0.00    0.00    1.00     1  pidstat

1554552428    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552430      0       192    0.00    0.50    0.00    0.00    0.50     1  kworker/u4:2
1554552430      0      1536    0.00   21.00    0.00    0.00   21.00     0  kworker/0:0
1554552430      0      4957    0.00    1.50    0.00    0.00    1.50     1  pidstat

1554552430    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552432      0       981    0.00    0.50    0.00    0.00    0.50     1  kworker/1:3
1554552432      0      1375    0.00    0.50    0.00    0.00    0.50     0  hostapd
1554552432      0      1536    0.00   20.40    0.00    0.00   20.40     0  kworker/0:0
1554552432      0      4957    0.00    1.00    0.00    0.00    1.00     1  pidstat

1554552432    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552434      0        14    0.00    0.50    0.00    0.00    0.50     1  ksoftirqd/1
1554552434      0      1375    0.00    0.50    0.00    0.00    0.50     0  hostapd
1554552434      0      1536    0.00   21.00    0.00    0.00   21.00     0  kworker/0:0
1554552434      0      3958    0.00    0.50    0.00    0.00    0.50     1  dropbear
1554552434      0      4957    0.50    1.00    0.00    0.00    1.50     1  pidstat

1554552434    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552436      0      1536    0.00   13.50    0.00    0.00   13.50     0  kworker/0:0
1554552436      0      4957    1.50    0.50    0.00    0.00    2.00     1  pidstat

1554552436    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552438      0       981    0.00    0.50    0.00    0.00    0.50     1  kworker/1:3
1554552438      0      1375    0.00    0.50    0.00    0.00    0.50     0  hostapd
1554552438      0      1536    0.00    7.00    0.00    0.00    7.00     0  kworker/0:0
1554552438      0      4957    0.00    1.00    0.00    0.00    1.00     1  pidstat

1554552438    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552440      0      1536    0.00   21.00    0.00    0.00   21.00     0  kworker/0:0
1554552440      0      3958    0.50    0.00    0.00    0.00    0.50     1  dropbear
1554552440      0      4957    1.00    0.50    0.00    0.00    1.50     1  pidstat

1554552440    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552442      0      1375    0.00    0.50    0.00    0.00    0.50     0  hostapd
1554552442      0      1536    0.00   20.90    0.00    0.00   20.90     0  kworker/0:0
1554552442      0      4957    0.00    1.49    0.00    0.00    1.49     1  pidstat

1554552442    UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
1554552444      0       981    0.00    0.50    0.00    0.00    0.50     1  kworker/1:3
1554552444      0      1031    0.50    0.00    0.00    0.00    0.50     1  udhcpc
1554552444      0      1375    0.00    0.50    0.00    0.00    0.50     0  hostapd
1554552444      0      1536    0.00   20.50    0.00    0.00   20.50     0  kworker/0:0
1554552444      0      4957    0.00    1.00    0.00    0.00    1.00     1  pidstat
^C

Average:      UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
Average:        0         7    0.00    0.03    0.00    0.00    0.03     -  ksoftirqd/0
Average:        0         8    0.00    0.06    0.00    0.00    0.06     -  rcu_sched
Average:        0        14    0.00    0.03    0.00    0.00    0.03     -  ksoftirqd/1
Average:        0       192    0.00    0.03    0.00    0.00    0.03     -  kworker/u4:2
Average:        0       548    0.00    0.03    0.00    0.00    0.03     -  netifd
Average:        0       981    0.00    0.21    0.00    0.00    0.21     -  kworker/1:3
Average:        0      1031    0.06    0.00    0.00    0.00    0.06     -  udhcpc
Average:        0      1375    0.06    0.21    0.00    0.00    0.26     -  hostapd
Average:        0      1536    0.00   17.12    0.00    0.00   17.12     -  kworker/0:0
Average:        0      3958    0.09    0.06    0.00    0.00    0.15     -  dropbear
Average:        0      4957    0.41    0.88    0.00    0.00    1.29     -  pidstat
0 Likes

#1544

@nmrh Yeah, I've seen it too, I think the warning is however unrelated to the spikes.

Btw, adding to this discussion, afaik kworker should normally be quite low in cpu usage. They are at 0% on my other running linux systems.

0 Likes

#1545

I suspect this commit changing MIB-counter behaviour has something to do with the CPU spikes: https://git.openwrt.org/?p=openwrt/openwrt.git;a=commit;h=d6366ce3665f010a7ae7061a557689643073040a

MIB-counters have caused some latency issues in the past on the R7800 per this post: Possible cause of R7800 latency issues

2 Likes

#1546

so i'm curios. does anyone know if the git bisect function (or just git checkout ) can be used with openwrt (i.e. is there something more I need to be concerned about related to feeds, updated toolchain, etc)? regardless i see a bunch of commits related to ar8216 and i'm assuming i'd want to bisect around all of them as a group...

0 Likes

#1547

Seems like they found the issue in the posts that @huaracheguarache mentioned.
Wonder why it's still exist in master...

0 Likes

#1548

At least the checkout can be used quite normally. But when going back to history, you may need to rebuild the tools & toolchain, so bisecting can be time-consuming, if you use the traditional midpoint-commit bisecting.

I usually do bisecting semi-manually by trying to identify from the commit logs the possible culprit commits and checkout just before them to get the baseline.

You should also checkout package & luci feeds from the same time in order to avoid any incompatible stuff. Add complexity. In practice, easiest may be to make just a base image with only minimal extra packages, so that you could avoid the special feed checkouts.

1 Like

#1549

some debugging info.... thermal / cooling will influence......

cat /sys/devices/system/cpu/cpufreq/policy1/scaling_governor
cat /sys/devices/system/cpu/cpufreq/policy1/stats/trans_table
cat /sys/devices/system/cpu/cpufreq/policy1/scaling_cur_freq

is 3%@maxFREQ = 17%@minFREQ?

#!/bin/sh
##################################################
PS1='[\u@\h \W]\$ '
##################################################
bash_prompt_command() {
    local pwdmaxlen=20
    local trunc_symbol=".."
    local dir=${PWD##*/}
    pwdmaxlen=$(( ( pwdmaxlen < ${#dir} ) ? ${#dir} : pwdmaxlen ))
    NEW_PWD=${PWD/#$HOME/\~}
    local pwdoffset=$(( ${#NEW_PWD} - pwdmaxlen ))
    if [ ${pwdoffset} -gt "0" ]
    then
        NEW_PWD=${NEW_PWD:$pwdoffset:$pwdmaxlen}
        NEW_PWD=${trunc_symbol}/${NEW_PWD#*/}
    fi
 
    TEMP="`cat /sys/devices/virtual/thermal/thermal_zone2/temp | cut -c 1,2``echo $'\xc2\xb0'`"
    NEW_PWD="${NEW_PWD} ${TEMP}"

}
#####################################################
bash_prompt() {
    case $TERM in
     xterm*|rxvt*)
         local TITLEBAR='\[\033]0;\u:${NEW_PWD}\007\]'
          ;;
     *)
        local TITLEBAR=""
          ;;
    esac
    local NONE="\[\033[0m\]"    # unsets color to term's fg color
    local K="\[\033[0;30m\]"    # black
    local R="\[\033[0;31m\]"    # red
    local G="\[\033[0;32m\]"    # green
    local Y="\[\033[0;33m\]"    # yellow
    local B="\[\033[0;34m\]"    # blue
    local M="\[\033[0;35m\]"    # magenta
    local C="\[\033[0;36m\]"    # cyan
    local W="\[\033[0;37m\]"    # white
    local EMK="\[\033[1;30m\]"
    local EMR="\[\033[1;31m\]"
    local EMG="\[\033[1;32m\]"
    local EMY="\[\033[1;33m\]"
    local EMB="\[\033[1;34m\]"
    local EMM="\[\033[1;35m\]"
    local EMC="\[\033[1;36m\]"
    local EMW="\[\033[1;37m\]"
    local BGK="\[\033[40m\]"
    local BGR="\[\033[41m\]"
    local BGG="\[\033[42m\]"
    local BGY="\[\033[43m\]"
    local BGB="\[\033[44m\]"
    local BGM="\[\033[45m\]"
    local BGC="\[\033[46m\]"
    local BGW="\[\033[47m\]"
    local UC=$G
    local VC=$Y
    [ $UID -eq "0" ] && VC=$R

    PS1="$TITLEBAR${G}[${UC}\u${VC}@${EMG}\h ${EMB}\${NEW_PWD}${G}]${UC}\\$ ${NONE}"
}

PROMPT_COMMAND=bash_prompt_command
bash_prompt
unset bash_prompt

0 Likes

#1550

I managed to get kworker to 0% ... did some very dirty hacks. But it's silent now. So it's indeed related to the MiB update stuff.

@fantom-x btw fyi doing this does not make kworker cpu usage go down, i thought it would at first.

const struct ar8xxx_chip ar8337_chip = {
-	.caps = AR8XXX_CAP_GIGE | AR8XXX_CAP_MIB_COUNTERS,
+ .caps = AR8XXX_CAP_GIGE /*| AR8XXX_CAP_MIB_COUNTERS*/,
2 Likes

#1551

I am surprised that this isn't incorporated in these builds because the fact is known since april 2018

0 Likes

#1552

i was going to build at current head but reverting all the commits titled "generic: ar8216: ..." from 03.24.2019 (instead of bisecting) but it seems like you have confirmed the cause.

unfortunately, i've also complicated it in my head by asking questions for which I'm not the best user to answer so i'm going to step back for a bit

0 Likes

#1553

I'm in no position to make a proper fix tho', I don't know C that good.
I guess this should be reported as a bug, are there any OpenWRT devs here that can take this further or should I make a case?

0 Likes

#1554

Do you mind sharing your findings?

0 Likes

#1555

stats ( my system was at 2.5 - 3.5 % bursts - so the percantages are subsets of that 3% )

54.00% kworker/1:0  raw_spin_unlock_irqrestore
15.93% kworker/1:0  msm_read_current_timer
9.30%  kworker/1:0  timer_delay
0 Likes

#1556

There should probably be some sort of option that disables MIB-counters, provided that they're not critical for system functionality. This topic is relevant: MIB Counters for QCA8337 (Netgear R7800)

0 Likes

#1557

Well reverted the first changes I did and I've got to the point that I commented out all AR8XXX_CAP_MIB_COUNTERS (just in case).
I also commented out this above next_attempt:
/for (i = 0; i < priv->dev.ports; i++)
ar8xxx_mib_fetch_port_stat(priv, i, false);
/

There's no excessive cpu usage in the kworker process now.

Since these changes makes a full kernel recompile for some reason I've stopped there for now.

0 Likes

#1558

However I think swconfig dev switch0 show gives a pretty odd output, it also hangs.
I'm not sure if it's because of my change.

Tho' it said in the old kworker forum thread the swconfig output differs from other routers, perhaps it needs investigation too.

0 Likes