Bug #3628
100% cpu usage when streaming on Armel
100%
Description
System¶
Debian Jessie, running latest git master (4.1.1672) on my NSA310A NAS 256MB
processor : 0 model name : Feroceon 88FR131 rev 1 (v5l) BogoMIPS : 1196.85 Features : swp half thumb fastmult edsp CPU implementer : 0x56 CPU architecture: 5TE CPU variant : 0x2 CPU part : 0x131 CPU revision : 1 Hardware : Marvell Kirkwood (Flattened Device Tree) Revision : 0000 Serial : 0000000000000000
Problem¶
Tvheadend uses near 100% cpu when streaming via http. tvh:tcp-start seems to be the cause.
Affected¶
Git master 4.1.1670+ and maybe lower. builds =< 4.1.1429 aren't affected.
Tests and debugging done¶
Unfortunately because the box isn't very fast I'm unable to get gdb to play nice thus I'm unable to produce logs, below are some screenshots of what I could get..
Further debugging.¶
I'm now going to go through commits 1429-1670..
I've now gone through the commits and the commit causing the issue is: commit:a6a23e10/On Github.
My log of testing each commit..
78507afcfaee39f2366cca6c4ddf45f1a4859261 = FAIL b8492e02f5dc507b31140df3bcb6d3e009810c00 = FAIL 74db86c89607b431a05bc30ffe3249bfbf49a065 = FAIL aa4e7f0bff63dfa9503cbea182c457343f635311 = FAIL 6e51fac75e715436edcad7cd15d846f5231ce59a = FAIL 9cf1bc7a6ac1307204cb1e6a6946f9ceef23e0b2 = FAIL 718d29903c97506a552ff1bd25242a7e7ffc72a7 = OK 055be40c0c3dffae117f1be2ce22885eb819f02c = OK 6ff670943ce70a8f279e99306a1d49a78c6b6949 = OK a6a23e100967e35618424a8125d2d85abb6ea72c = FAIL - Build Error.. a6a23e100967e35618424a8125d2d85abb6ea72c = FAIL - **** Retrying build by manually fixing using patch https://github.com/tvheadend/tvheadend/commit/dfbd6325302d39fcd5fca5a6425e9a28d50605ef.patch f4c42ab11fc4a993716c87edff3b06ba4382822b = FAIL - Built with above patch. FAIL = High CPU usage in tvh:tcp-start. OK = Streams fine no excessive usage. **** = This commit is causing the issue..
History
Updated by
Updated by Jaroslav Kysela over 7 years ago
Updated by It seems that pthread_cond_timedwait() behaves really badly for monotonic clocks on your platform. Could you try this patch?
iff --git a/src/wrappers.c b/src/wrappers.c
index e1caa3d..3eba0ea 100644
--- a/src/wrappers.c
+++ b/src/wrappers.c
@@ -263,6 +263,9 @@ tvh_cond_timedwait
( tvh_cond_t *cond, pthread_mutex_t *mutex, int64_t monoclock )
{
struct timespec ts;
+ if (mclk() >= monoclock)
+ return ETIMEDOUT;
+ tvh_safe_usleep(10000);
ts.tv_sec = monoclock / MONOCLOCK_RESOLUTION;
ts.tv_nsec = (monoclock % MONOCLOCK_RESOLUTION) *
(1000000000ULL/MONOCLOCK_RESOLUTION);
Updated by Mark Clarkstone over 7 years ago
Jaroslav Kysela wrote:
It seems that pthread_cond_timedwait() behaves really badly for monotonic clocks on your platform. Could you try this patch?
[...]
Build error:
CC src/wrappers.o src/wrappers.c: In function ‘tvh_cond_timedwait’: src/wrappers.c:266:3: error: implicit declaration of function ‘mclk’ [-Werror=implicit-function-declaration] if (mclk() >= monoclock) ^ src/wrappers.c:268:3: error: implicit declaration of function ‘tvh_safe_usleep’ [-Werror=implicit-function-declaration] tvh_safe_usleep(10000); ^ cc1: all warnings being treated as errors Makefile:573: recipe for target '/home/mark/build/tvheadend/master/build.linux/src/wrappers.o' failed make: *** [/home/mark/build/tvheadend/master/build.linux/src/wrappers.o] Error 1
Updated by Jaroslav Kysela over 7 years ago
Add also this:
diff --git a/src/wrappers.c b/src/wrappers.c index e1caa3d..9fc20be 100644 --- a/src/wrappers.c +++ b/src/wrappers.c @@ -18,6 +18,8 @@ #include <pthread_np.h> #endif +#include "clock.h" + /* * filedescriptor routines */
Updated by Mark Clarkstone over 7 years ago
Jaroslav Kysela wrote:
Add also this:
[...]
Still the same:
mark@nsa310a:~/build/tvheadend/master$ patch -p1 < ../tvh2.patch patching file src/wrappers.c Hunk #1 succeeded at 18 with fuzz 1. mark@nsa310a:~/build/tvheadend/master$ make make -f Makefile.webui LANGUAGES="bg cs da de en_US en_GB es et fa fi fr he hr hu it lv nl pl pt ru sv uk" all make[1]: Entering directory '/home/mark/build/tvheadend/master' make -f Makefile.webui WEBUI=std compile-std make[2]: Entering directory '/home/mark/build/tvheadend/master' WEBUI std finished make[2]: Leaving directory '/home/mark/build/tvheadend/master' make -f Makefile.webui WEBUI=debug compile-debug make[2]: Entering directory '/home/mark/build/tvheadend/master' WEBUI debug finished make[2]: Leaving directory '/home/mark/build/tvheadend/master' make[1]: Leaving directory '/home/mark/build/tvheadend/master' CC src/wrappers.o src/wrappers.c: In function ‘tvh_cond_timedwait’: src/wrappers.c:268:3: error: implicit declaration of function ‘mclk’ [-Werror=implicit-function-declaration] if (mclk() >= monoclock) ^ src/wrappers.c:270:3: error: implicit declaration of function ‘tvh_safe_usleep’ [-Werror=implicit-function-declaration] tvh_safe_usleep(10000); ^ cc1: all warnings being treated as errors Makefile:573: recipe for target '/home/mark/build/tvheadend/master/build.linux/src/wrappers.o' failed make: *** [/home/mark/build/tvheadend/master/build.linux/src/wrappers.o] Error 1
Double checked to see if the include was added and it's there..
Updated by Jaroslav Kysela over 7 years ago
This works here:
diff --git a/src/wrappers.c b/src/wrappers.c
index e1caa3d..1d1b4ae 100644
--- a/src/wrappers.c
+++ b/src/wrappers.c
@@ -18,6 +18,8 @@
#include <pthread_np.h>
#endif
+#include "clock.h"
+
/*
* filedescriptor routines
*/
@@ -263,6 +265,8 @@ tvh_cond_timedwait
( tvh_cond_t *cond, pthread_mutex_t *mutex, int64_t monoclock )
{
struct timespec ts;
+ if (mclk() >= monoclock)
+ return ETIMEDOUT;
ts.tv_sec = monoclock / MONOCLOCK_RESOLUTION;
ts.tv_nsec = (monoclock % MONOCLOCK_RESOLUTION) *
(1000000000ULL/MONOCLOCK_RESOLUTION);
Updated by Mark Clarkstone over 7 years ago
Jaroslav Kysela wrote:
This works here:
[...]
No change I'm afraid..
Threads: 34 total, 1 running, 33 sleeping, 0 stopped, 0 zombie %Cpu(s): 28.2 us, 47.5 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 24.3 si, 0.0 st KiB Mem: 250264 total, 242924 used, 7340 free, 9844 buffers KiB Swap: 975868 total, 9796 used, 966072 free. 156536 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 3333 hts 20 0 313036 22728 5288 R 73.5 9.1 0:21.55 tvh:tcp-start 3287 hts 20 0 313036 22728 5288 S 10.9 9.1 0:14.52 tvh:mi-main 3286 hts 20 0 313036 22728 5288 S 7.3 9.1 0:38.33 tvh:mi-table 3334 hts 20 0 313036 22728 5288 S 3.3 9.1 0:01.30 tvh:lnxdvb-fron 3264 hts 20 0 313036 22728 5288 S 3.0 9.1 0:24.91 tvh:log 3298 hts 20 0 313036 22728 5288 S 0.7 9.1 0:01.28 tvh:tcp-start 3263 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.11 tvheadend 3265 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:notify 3266 hts 35 15 313036 22728 5288 S 0.0 9.1 0:00.17 tvh:save 3267 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.03 tvheadend 3268 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.12 tvh:mtick 3269 hts 39 19 313036 22728 5288 S 0.0 9.1 0:03.13 tvh:tasklet 3270 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:fsmonitor 3271 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:imagecache 3272 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:httpc 3273 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:service 3274 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:iptv 3278 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:tshift-reap 3279 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:tcp-loop 3280 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.08 tvh:upnp 3281 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:svcmap 3282 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:epggrabi 3283 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:dvr-inotify 3284 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.07 tvh:satip-rtcp 3285 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.33 tvh:mtimer 3288 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:mi-table 3289 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:mi-main 3290 hts 20 0 313036 22728 5288 S 0.0 9.1 0:00.00 tvh:mi-table
Updated by Jaroslav Kysela over 7 years ago
Sorry, 'tvh_safe_usleep(10000);' line is missing in my patch in comment 6.
Updated by Mark Clarkstone over 7 years ago
Jaroslav Kysela wrote:
Sorry, 'tvh_safe_usleep(10000);' line is missing in my patch in comment 6.
OK I added that in but still no change 
Updated by Jaroslav Kysela over 7 years ago
OK, revert the patch (go back to normal code) and try this:
iff --git a/src/webui/webui.c b/src/webui/webui.c
index 5c2d3ed..a0070ba 100644
--- a/src/webui/webui.c
+++ b/src/webui/webui.c
@@ -345,6 +345,7 @@ http_stream_run(http_connection_t *hc, profile_chain_t *prch,
mono = mclk() + sec2mono(1);
do {
r = tvh_cond_timedwait(&sq->sq_cond, &sq->sq_mutex, mono);
+ tvhdebug("webui", "timedwait: r = %d, expected = %"PRId64", now = %"PRId64, r, mono, getmonoclock());
if (r == ETIMEDOUT) {
/* Check socket status */
if (tcp_socket_dead(hc->hc_fd)) {
I need the log..
Updated by Mark Clarkstone over 7 years ago
debug line:
2016-03-14 17:17:49.960 webui: timedwait: r = 0, expected = 245638747433, now = 245638459914
Full debug paste http://pastebin.com/raw/PXUw00c2
Updated by Jaroslav Kysela over 7 years ago
Could you pull from my debug1 branch: https://github.com/perexg/tvheadend/tree/debug1 and test? Replace /tmp/tvh.txt with a file where's disk space on the line with fopen: https://github.com/perexg/tvheadend/commit/13e2e19490dac4875fb5303208c20725874b65bc . I need the contents of the file.
Updated by Mark Clarkstone over 7 years ago
Jaroslav Kysela wrote:
Could you pull from my debug1 branch: https://github.com/perexg/tvheadend/tree/debug1 and test? Replace /tmp/tvh.txt with a file where's disk space on the line with fopen: https://github.com/perexg/tvheadend/commit/13e2e19490dac4875fb5303208c20725874b65bc . I need the contents of the file.
Link to log: https://clbin.com/PgbmC 
Updated by Jaroslav Kysela over 7 years ago
- Status changed from New to Fixed
- % Done changed from 0 to 100
Applied in changeset commit:tvheadend|13646b0f71402f8c0c67810d6587cbe15093835e.