Tvheadend

It just happened again:

[110148.675391] tvh:tcp-start invoked oom-killer: gfp_mask=0x24201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD), nodemask=0, order=0, oom_score_adj=0
[110148.675393] tvh:tcp-start cpuset=/ mems_allowed=0
[110148.675401] CPU: 0 PID: 1452 Comm: tvh:tcp-start Not tainted 4.9.0-3-amd64 #1 Debian 4.9.30-2+deb9u3
[110148.675402] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 09/21/2015
[110148.675405]  0000000000000000 ffffffff9a928574 ffffb8aa42173c38 ffff9bbb9f41a040
[110148.675407]  ffffffff9a7fe050 0000000000000000 0000000000000000 0000000c024213ca
[110148.675408]  ffffffff9a7844e7 000000429c9ad000 0000000000000000 f5688d9f446e9a94
[110148.675409] Call Trace:
[110148.675437]  [<ffffffff9a928574>] ? dump_stack+0x5c/0x78
[110148.675444]  [<ffffffff9a7fe050>] ? dump_header+0x78/0x1fd
[110148.675450]  [<ffffffff9a7844e7>] ? get_page_from_freelist+0x3f7/0xb40
[110148.675454]  [<ffffffff9a78047a>] ? oom_kill_process+0x21a/0x3e0
[110148.675455]  [<ffffffff9a7800fd>] ? oom_badness+0xed/0x170
[110148.675456]  [<ffffffff9a780911>] ? out_of_memory+0x111/0x470
[110148.675457]  [<ffffffff9a785b4f>] ? __alloc_pages_slowpath+0xb7f/0xbc0
[110148.675458]  [<ffffffff9a785d8e>] ? __alloc_pages_nodemask+0x1fe/0x260
[110148.675463]  [<ffffffff9a7d5ec1>] ? alloc_pages_current+0x91/0x140
[110148.675464]  [<ffffffff9a77e940>] ? filemap_fault+0x300/0x5a0
[110148.675511]  [<ffffffffc02ee791>] ? ext4_filemap_fault+0x31/0x50 [ext4]
[110148.675514]  [<ffffffff9a7aeef1>] ? __do_fault+0x81/0x170
[110148.675516]  [<ffffffff9a7b3671>] ? handle_mm_fault+0xdd1/0x1350
[110148.675524]  [<ffffffff9a65fd84>] ? __do_page_fault+0x2a4/0x510
[110148.675531]  [<ffffffff9ac07658>] ? page_fault+0x28/0x30
[110148.675558] Mem-Info:
[110148.675564] active_anon:55464 inactive_anon:55480 isolated_anon:0
                 active_file:153 inactive_file:189 isolated_file:0
                 unevictable:0 dirty:0 writeback:2 unstable:9
                 slab_reclaimable:2203 slab_unreclaimable:3226
                 mapped:160 shmem:258 pagetables:1099 bounce:0
                 free:1121 free_pcp:169 free_cma:0
[110148.675567] Node 0 active_anon:221856kB inactive_anon:221920kB active_file:612kB inactive_file:756kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:640kB dirty:0kB writeback:8kB shmem:1032kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:36kB pages_scanned:2993 all_unreclaimable? yes
[110148.675568] Node 0 DMA free:1908kB min:88kB low:108kB high:128kB active_anon:7740kB inactive_anon:5376kB active_file:0kB inactive_file:12kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB slab_reclaimable:20kB slab_unreclaimable:8kB kernel_stack:0kB pagetables:80kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[110148.675570] lowmem_reserve[]: 0 455 455 455 455
[110148.675572] Node 0 DMA32 free:2576kB min:2684kB low:3352kB high:4020kB active_anon:214116kB inactive_anon:216544kB active_file:612kB inactive_file:744kB unevictable:0kB writepending:8kB present:507840kB managed:488500kB mlocked:0kB slab_reclaimable:8792kB slab_unreclaimable:12896kB kernel_stack:1680kB pagetables:4316kB bounce:0kB free_pcp:676kB local_pcp:676kB free_cma:0kB
[110148.675574] lowmem_reserve[]: 0 0 0 0 0
[110148.675575] Node 0 DMA: 3*4kB (U) 41*8kB (UM) 30*16kB (UME) 6*32kB (UME) 6*64kB (UME) 2*128kB (ME) 1*256kB (M) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1908kB
[110148.675580] Node 0 DMA32: 644*4kB (U) 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2576kB
[110148.675583] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[110148.675584] 1863 total pagecache pages
[110148.675584] 1254 pages in swap cache
[110148.675585] Swap cache stats: add 225647, delete 224393, find 21067/37197
[110148.675585] Free swap  = 0kB
[110148.675585] Total swap = 731132kB
[110148.675586] 130958 pages RAM
[110148.675586] 0 pages HighMem/MovableOnly
[110148.675586] 4856 pages reserved
[110148.675586] 0 pages hwpoisoned
[110148.675587] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
[110148.675590] [  201]     0   201    33443       84      58       3      261             0 vmtoolsd
[110148.675591] [  204]     0   204    13731       68      22       3       84             0 systemd-journal
[110148.675592] [  240]     0   240    11973       11      25       3      757         -1000 systemd-udevd
[110148.675593] [  268]     0   268    12468       15      29       3      114             0 rpcbind
[110148.675594] [  317]     0   317    38372        1      65       3      866             0 VGAuthService
[110148.675595] [  319]     0   319     7409       18      19       3       44             0 cron
[110148.675596] [  320]     0   320     1054        0       8       3       37             0 acpid
[110148.675597] [  321]   106   321    11283       47      26       3       71          -900 dbus-daemon
[110148.675598] [  328]     0   328    11630       33      27       3      111             0 systemd-logind
[110148.675598] [  329]     0   329    62529       43      29       4      186             0 rsyslogd
[110148.675599] [  458]     0   458    17486        0      38       3      198         -1000 sshd
[110148.675600] [  475]   108   475     8858        0      22       3      201             0 rpc.statd
[110148.675601] [  500]     0   500     3634        0      12       3       38             0 agetty
[110148.675602] [  512]   107   512   442457   108792     667       4   178529             0 tvheadend
[110148.675603] [  514]   105   514    24463       65      22       4       99             0 ntpd
[110148.675605] Out of memory: Kill process 512 (tvheadend) score 932 or sacrifice child
[110148.675687] Killed process 512 (tvheadend) total-vm:1769828kB, anon-rss:435168kB, file-rss:0kB, shmem-rss:0kB
[110148.706219] oom_reaper: reaped process 512 (tvheadend), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB

Is there anything I can do to gather more informtation? Any log file or error message you are interested in? Anything else I can do, or should not do?

The easiest thing I could is probably reinstall everything with Debian 8. That would maybe solve my problems, but if this is a bug then that won't help anyone.

I am prepared to assist as much as I can with testing, log files etc...
However, I cannot afford to just sit and wait and have my TVHeadend crashing while no progress is being made.

If there is no time or no interest to invest time in this issue, please let me know and I'll revert back to Debian 8 and see how it goes from there.

Gert Jansen wrote:

I am prepared to assist as much as I can with testing, log files etc...
However, I cannot afford to just sit and wait and have my TVHeadend crashing while no progress is being made.

I completely understand, if possible could you collect debugging information? See Debugging & Traces for info.

If there is no time or no interest to invest time in this issue, please let me know and I'll revert back to Debian 8 and see how it goes from there.

It's not that there is no interest, it's lack of man power, there is currently mostly only one person working on tvheadend, with a few others helping where possible.

Out of interest, have you tried the stable-4.2 release and/or the latest 4.3.488? I personally have been running 4.3.x for a while with very few issues on Debian 9 (but not in a VM). If you're able keep a snap shot of the failing VM & go back to a working one for now.

Mark Clarkstone wrote:

Out of interest, have you tried the stable-4.2 release and/or the latest 4.3.488? I personally have been running 4.3.x for a while with very few issues on Debian 9 (but not in a VM). If you're able keep a snap shot of the failing VM & go back to a working one for now.

No, I haven't tried 4.3.488 yet.
As you can see, I have lots of different versions running at the moment, and after a while I gave up on the upgrading since that was not providing a solution.

For now, I have concentrated on VM#1.
I have stopped the TVH service, copied the tvheadend directory to my user profiles, and started tvheadend manually from there.

I have used the ulimit -c unlimited command, and started TVH with the ./build.linux/tvheadend -l /tmp/tvheadend.log --trace htsp,subscription,pat,pmt,bat command.
However, I got a message that pat, pmt, bat were unknown subsystem options (or something similar)

I get the same message when I try to add them to one of the other TVH machines.

2017-09-23 11:53:49.088 config: uknown subsystem 'pat'
2017-09-23 11:53:49.088 config: uknown subsystem 'pmt'
2017-09-23 11:53:49.088 config: uknown subsystem 'bat'

One thing I noticed is that TVH seems to be using a lot more memory than it did before.
Top show a %Mem of 33.6 for VM#1 (after roughly 2 hours), while that is only 6.5 on the VM#5 (the Debian 8 machine) and 2.8 on the RPi.
It was as high as 87.8 before I stopped it to enable the tracing/debugging things...

Gert Jansen wrote:

No, I haven't tried 4.3.488 yet.

I can try 4.3.488 or the then-current (latest) version if/when this one crashes and we have some useful logs and trace files

Could you look to 'Configuration / Debugging / Memory information entries' and compare values after process start and after awhile ? (VM#1) - install debug version of tvh, if you don't have such tab in the Debugging.

Also, it may help to know, how the tvh is used (HTTP streaming only, DVR, etc.).

Gert Jansen wrote:

Jaroslav Kysela wrote:

Could you look to 'Configuration / Debugging / Memory information entries' and compare values after process start and after awhile ? (VM#1) - install debug version of tvh, if you don't have such tab in the Debugging.

Do you mean like the attached file? (tvh_01.png)
This is the current situation, about 3 hours after I started TVH manually.
Since then, no recordings have been made.

Is there an easier way to get all the values apart from making a screenshot?

wget -O a.txt http://localhost:9981/api/memoryinfo/grid

Shall I stop and restart TVH and create a new overview just after the start, and a new after half an hour?

Yes, probably.

Jaroslav Kysela wrote:

Also, it may help to know, how the tvh is used (HTTP streaming only, DVR, etc.).

I only use it to record programs. No streaming, no live watching.

OK. We had another report and the culprit was the slow disk I/O. TVH tries to buffer everything to memory in this case (I have to probably implement a buffer threshold to drop data to avoid such situations).

Jaroslav Kysela wrote:

Gert Jansen wrote:

Shall I stop and restart TVH and create a new overview just after the start, and a new after half an hour?

Yes, probably.

OK, will do so in about 30 minutes.

Jaroslav Kysela wrote:

Also, it may help to know, how the tvh is used (HTTP streaming only, DVR, etc.).

I only use it to record programs. No streaming, no live watching.

OK. We had another report and the culprit was the slow disk I/O. TVH tries to buffer everything to memory in this case (I have to probably implement a buffer threshold to drop data to avoid such situations).

The disk the VMs record to is on the same ESXi host, so it is 'local' (no actual network connection needed) for all the VMs (not for the RPi).
I have a cronjob which moves the recordings from that disk to my NAS during the night.

The contents is identical. RSS/RES (memory used by the tvh process) increases?

Jaroslav Kysela wrote:

The contents is identical. RSS/RES (memory used by the tvh process) increases?

And it is still exactly the same at this moment.

The memory usage had increased, but just a bit.
I only know the %MEM, sorry. That was 31.3 when it started, and now it is:

top - 20:26:47 up 2 days,  2:15,  2 users,  load average: 0.00, 0.00, 0.00
Threads: 111 total,   1 running, 110 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.0 us,  0.7 sy,  0.0 ni, 99.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :   504408 total,    20068 free,   268068 used,   216272 buff/cache
KiB Swap:   731132 total,   715156 free,    15976 used.   218364 avail Mem

PID   USER     PR  NI  VIRT    RES    SHR    S %CPU %MEM TIME+     COMMAND
3169  gert     20  0   844692  227284 11332  S 0.3  45.1 0:11.88   tvheadend

I seem not to be able to edit my post once it is submitted?

Anyhow, I have 2 recordings coming up soon. Both on the same channel.
I'll see what happens there.

The 'RES' column in top is RSS. You can obtain RSS also through ps like:

ps -aly | grep -E "(RSS|tvheadend)" 

If tvh process is using over 200MB of memory, but the memory entries shows than only few MB are allocated, then something is really wrong and it might not be easy to determine what's going on in the tvh process.

VM#1 - currently recording

ps -aly | grep -E "(RSS|tvheadend)" 
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S  1000  3169   576  2  80   0 236316 211173 -    pts/0    00:07:16 tvheadend

VM#2 - currently recording

ps -aly -u hts | grep -E "(RSS|tvheadend)" 
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S   107   540     1  0  80   0 168620 213580 -    ?        17:14:42 tvheadend

VM#3 - currently idle

 ps -aly -u hts | grep -E "(RSS|tvheadend)" 
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S   107   553     1  0  80   0 380296 245332 -    ?        00:45:43 tvheadend

VM#4 - currently idle

 ps -aly -u hts | grep -E "(RSS|tvheadend)" 
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S   107   561     1  0  80   0 29172 179061 -     ?        01:02:23 tvheadend

VM#5 - currently recording

ps -aly -u tvheadend | grep -E "(RSS|tvheadend)" 
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S  1001   478     1  0  80   0 31676 222397 -     ?        06:39:01 tvheadend

RPi - currently idle

ps -aly -u tvheadend | grep -E "(RSS|tvheadend)" 
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S  1001   757     1  3  80   0 25524 79940 -      ?        04:47:00 tvheadend

What is in 'Memory information entries' for VM#1 now ? (Don't forget to refresh the contents if you have already open the page in browser - the auto-refresh does not work).

Which streaming profile do you use for DVR? (matroska? pass?)

Jaroslav Kysela wrote:

Which streaming profile do you use for DVR? (matroska? pass?)

I use pass for stream profile. I have set cache scheme to "Don't Keep" and adapted the pre- and post-recording padding times. Apart from that I think most values in my recording profile are still at the default values.

Eventually, it (VM #1) did crash.

The last few messages in the session where I started TVHeadend from:

2017-09-25 23:38:54.034 [WARNING] TS: LNB2 = Diseqc B = Astra 3/12187H/Veronica/DisneyXD HD: H264 @ #517 Continuity counter error (total 2)
2017-09-25 23:42:45.361 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:42:55.373 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:43:05.360 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:43:15.359 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:43:25.383 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:43:35.377 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:43:45.374 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:43:55.389 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:44:05.398 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:44:15.404 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:44:25.405 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:44:35.409 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:44:45.419 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:44:55.461 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
2017-09-25 23:45:05.557 [WARNING] mpegts: too much queued table input data (over 2MB), discarding new
Killed

At 23:38 it was recording a movie (start time 20:21:30, scheduled end time: 23:42:00). There was no other recording going on on that VM at the same time.

On VM#5, there was a recording from 22:41:30 until 23:52 and another one from 23:26:30 until 00:42:00. Both are absolutely fine. No errors, no warnings. Just perfect.

All other VMs and the RPi were idle.

I have not yet restarted the VM.
Is there any information I need to get from it before I can safely restart it?
Where can I find the logs/traces that are interesting?

You may try valgrind https://tvheadend.org/projects/tvheadend/wiki/Debugging#Memory-leaks-or-corruption to detect the memory leak. Note that it's slow, so I suggest to do a test recording (5 minutes or so) and then terminate tvh. Run tvh binary from command line (not in background).

May try that later today. Can't do that while working, sadly.
I may try to sneak it in during a break later today.

Is there anything useful like logfiles or traces that I have to save before I reboot the VM or restart TVH ?

The valgrind does not show any memory leaks which can explain the behaviour. Could you observe, when RES/RSS is being increased exactly? Try to split activities like DVR, HTTP access, EPG grab etc...

Despite all the time that went on, I have been unable to exactly pinpoint why or when it goes wrong.

• added a second ESXi server
• split the TVHeadend clients across the 2 hosts: each host has a client with a DVBSky and a Terratec adapter. The TBS adapter stayed where it was
• upgraded all TVHeadend clients to newer versions (except the TBS one)
• reinstalled a VM from scratch for one of the DVBSky clients.

The crashes seem to occur less frequently but have not gone away.

As far as I can tell, they only happen on the VMs with DVBSky adapters.

• something in TVHeadend
• Debian 9 - or more precisely: something in kernel 4.9.x
• the drivers of the DVBSky adapters.

Previously, the DVBSky VMs were running Debian 8 (Kernel 3.16.x) and drivers compiled from the sources provided by DVBSky.
Nowadays the DVBSky is included in the kernel (since 3.18.x IIRC), and doesn't need a driver anymore.

Yesterday I have created 2 new VMs with Debian 8, and again drivers compiled from the sources provided by DVBSky.
I have built the latest TVHeadend (4.3-861~g715a4a8) for both of them.

I'll see how it goes from here.