OpenWrt/LEDE Project

  • Status Unconfirmed
  • Percent Complete
    0%
  • Task Type Bug Report
  • Category Base system
  • Assigned To No-one
  • Operating System All
  • Severity Low
  • Priority Very Low
  • Reported Version Trunk
  • Due in Version Undecided
  • Due Date Undecided
  • Private
Attached to Project: OpenWrt/LEDE Project
Opened by Etienne CHAMPETIER - 17.11.2019

FS#2613 - Keeping luci overview page leads to loadaverage > 1

I’m reporting this bug against openwrt-19.07, haven’t looked at master, I think it was also happening on 18.06 but never took time to investigate
My test router is “MikroTik RouterBOARD wAP G-5HacT2HnD” running “OpenWrt 19.07-SNAPSHOT r10700-960de44fa9 / LuCI openwrt-19.07 branch git-19.320.62787-2390e72”

When open, the overview page is doing 2 calls to ‘/cgi-bin/luci/admin/ubus’ every X seconds
Each call is taking ~270ms (according to firefox debugger)

Doing a smaller test call (from my laptop, connected over ethernet)

$ curl 'http://192.168.1.1/cgi-bin/luci/admin/ubus' -H 'Content-Type: application/json' --data '[{"jsonrpc":"2.0","id":130,"method":"call","params":["d385054a42004fcb49bd866fc8008843","file","read",{"path":"/proc/sys/net/netfilter/nf_conntrack_count"}]}]' -s -w '\n%{time_starttransfer} %{time_total}\n'
[{"id":130,"jsonrpc":"2.0","result":[0,{"data":"15\n"}]}]
0,137934 0,147648

Similar command line call

time -v ubus call file read '{"path":"/proc/sys/net/netfilter/nf_conntrack_count"}'
{
	"data": "5\n"
}
 Command being timed: "ubus call file read {"path":"/proc/sys/net/netfilter/nf_conntrack_count"}"
 User time (seconds): 0.00
 System time (seconds): 0.00
 Percent of CPU this job got: 66%
 Elapsed (wall clock) time (h:mm:ss or m:ss): 0m 0.00s

So basically requests via ‘/cgi-bin/luci/admin/ubus’ are at least 15 time slower

Playing with strace (even if it has a big impact on performance)
# strace -f -ttr -p 418 -p 1 -p 1306 -p 1058
where
1 == procd
418 == ubusd
1058 == rpcd
1306 == uhttpd
5554 == uhttpd child
I see (full trace attached)
[pid 1306] 05:33:12.627708 (+ 0.001768) accept(3, {sa_family=AF_INET, sin_port=htons(43820), sin_addr=inet_addr(”192.168.1.2”)}, [28→16]) = 8
[pid 1306] 05:33:12.661205 (+ 0.002565) fork() = 5554
[pid 1306] 05:33:12.696731 (+ 0.001535) write(12, “[{\”jsonrpc\”:\”2.0\”,\”id\”:130,\”meth”..., 158 <unfinished ...>
[pid 5554] 05:33:12.762596 (+ 0.002187) execve(”/www/cgi-bin/luci”, [”/www/cgi-bin/luci”], 0x77f03380 /* 25 vars */) = 0
[pid 5554] 05:33:15.206711 (+ 0.002222) readv(0, [{iov_base=”[{\”jsonrpc\”:\”2.0\”,\”id\”:130,\”meth”..., iov_len=157}, {iov_base=”]”, iov_len=1024}], 2) = 158
[pid 1306] 05:33:15.600031 (+ 0.002791) write(8, “\r\n”, 2) = 2

2.972323 from accept to last write
2.444115 from execve to readv
80%+ of the time is spent loading luci interface, where we “just” want to call ubus

Etienne CHAMPETIER commented on 17.11.2019 23:33

Adding strace capture

Etienne CHAMPETIER commented on 18.11.2019 00:47

Title should read
"Keeping luci overview page open leads to loadaverage > 1"

Admin
Jo-Philipp Wich commented on 18.11.2019 08:53

Install `uhttpd-mod-ubus`, restart uhttpd, close and reopen your LuCI browser tab. That should use an optimized code path bypassing LuCI entirely for ubus calls.

The extreme overhead you observe might be due to installed LuCI apps. Please provide the output of `opkg list_installed | grep luci-app`

Etienne CHAMPETIER commented on 18.11.2019 15:56

Thanks!
uhttpd-mod-ubus did the trick, and force refresh was indeed not enough, closing the tab and reopening was needed
The 2 calls now use 88 and 127ms

My luci apps:
root@OpenWrt:~# opkg list_installed | grep luci-app
luci-app-commands - git-19.320.62787-2390e72-1
luci-app-diag-core - git-19.320.62787-2390e72-1
luci-app-firewall - git-19.320.62787-2390e72-1
luci-app-opkg - git-19.320.62787-2390e72-1

2 questions:
would you accept a PR for master to add uhttpd-mod-ubus to luci dependencies ? (6.5K)
what's the purpose of uhttpd-mod-lua ?

Loading...

Available keyboard shortcuts

Tasklist

Task Details

Task Editing