SageTV / unraid server crashed today. Huge endless recording found.

[EnterNoEscape]

At 12:03, it looks like unraid ends up killing a java process (SageTV?) presumably to free memory. Is that right?

Aug 15 00:03:08 unraid kernel: Out of memory: Kill process 14906 (java) score 38 or sacrifice child
Aug 15 00:03:08 unraid kernel: Killed process 14906 (java) total-vm:6664500kB, anon-rss:1256272kB, file-rss:0kB, shmem-rss:0kB
Aug 15 00:03:08 unraid kernel: oom_reaper: reaped process 14906 (java), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB

What do you think? Looks like the mover and my 2 recordings all running at 12am is a problem...

That's what it looks like is happening. You might have a plugin running that affects filesystem performance. Are you using the directory caching plugin?

[glenner]

Originally Posted by EnterNoEscape

That's what it looks like is happening. You might have a plugin running that affects filesystem performance. Are you using the directory caching plugin?

Directory caching is a Sage plugin or an unraid one? I'm pretty light on plugins... but I have not installed anything related to directory caching on either Sage or unraid.

Does the memory utilization of the java process that unraid killed seem reasonable (6GB used?)? That is SageTV java process that unraid killed as best as I can tell.... Looking at my ps output now... the only other java processes I might have running are crashplan... but crashplan is mostly idle for me.

Is there a way for me to test the filesystem performance of my cache pool to ensure it is working properly?

[EnterNoEscape]

Originally Posted by glenner

Directory caching is a Sage plugin or an unraid one? I'm pretty light on plugins... but I have not installed anything related to directory caching on either Sage or unraid.

Does the memory utilization of the java process that unraid killed seem reasonable (6GB used?)? That is SageTV java process that unraid killed as best as I can tell.... Looking at my ps output now... the only other java processes I might have running are crashplan... but crashplan is mostly idle for me.

Is there a way for me to test the filesystem performance of my cache pool to ensure it is working properly?

It's an unRAID plugin.

I don't recall specifically how Linux weighs processes to find a good candidate to kill, but size is a factor and I'm sure that the Java process is the largest one on your server.

Maybe someone else can chime in on that one. I would try copying a few large files (like recordings) onto the cache drive, then run the mover manually to see if it crashes everything. If that causes the failure to happen again, then I might have some tips on what you could tweak to get that to stop happening.

[glenner]

Originally Posted by EnterNoEscape

It's an unRAID plugin.

I don't recall specifically how Linux weighs processes to find a good candidate to kill, but size is a factor and I'm sure that the Java process is the largest one on your server.

Maybe someone else can chime in on that one. I would try copying a few large files (like recordings) onto the cache drive, then run the mover manually to see if it crashes everything. If that causes the failure to happen again, then I might have some tips on what you could tweak to get that to stop happening.

It seems to dump the process list, and kill the one with the most memory utilization.... makes sense.

But so I was able to reproduce this issue... I think I can cause the crash manually with these steps:

1. manually record 2 shows from the program guide.
2. start mover process from dashboard scheduler UI. 20-30GB of recordings need to be moved...
3. watch results of top/htop and unraid dashboard.
4. cpu goes to 100% of all cores for me. did not notice memory going to 100%. crash occured within a few seconds... less than 1 minute for sure.
5. ultimately in the syslog, I see the same out of memory errors as before.
6. Sage java process is killed.
7. my placeshifter connection goes offline
8. mover then starts moving files (as per the log output)
9. restarted Sage
10. interestingly, mover and 2 recordings seem to be running now after the Sage restart... mover has since finished. So Sage did not crash after being restarted with the 2 ongoing recordings and the mover also going.

I guess I could repeat and try recording a single show with the mover going. Maybe a single show will also have an issue... But for now, it looks like if ever I'm recording 2 shows, and then the mover is invoked, my SageTV java process will be killed due to out of memory errors.

[glenner]

I think you must be talking about the Dynamic Cache Dirs plugin which I finally located within community apps... No, I don't have that installed. Do I need it?

I am currently trying to see if the cache tweaks suggested here will address the OOM issue:

https://forums.lime-technology.com/t...comment-577424

My cache is empty now... So I'll try the mover tomorrow with 2 recordings going and see what happens.

[EnterNoEscape]

Originally Posted by glenner

I think you must be talking about the Dynamic Cache Dirs plugin which I finally located within community apps... No, I don't have that installed. Do I need it?

I am currently trying to see if the cache tweaks suggested here will address the OOM issue:

https://forums.lime-technology.com/t...comment-577424

My cache is empty now... So I'll try the mover tomorrow with 2 recordings going and see what happens.

Those are related to what I did on mine. I changed vfs.cache_pressure from 10 (set by the plugin) to 300 because the OS default of 100 also would result in OOM when the mover needed to move a lot of recordings (> 14GB which was how much free RAM I had).

[glenner]

Originally Posted by EnterNoEscape

Those are related to what I did on mine. I changed vfs.cache_pressure from 10 (set by the plugin) to 300 because the OS default of 100 also would result in OOM when the mover needed to move a lot of recordings (> 14GB which was how much free RAM I had).

Yeah... in my case, I installed the "Tips and Tweaks" plugin and set the disk cache settings as follows:

vm.dirty_background_ratio = 1% (down from 10%)
vm.dirty_ratio = 2% (down from 20%)

I have 32GB of RAM. So 1 or 2% of that is still a big number... 20% of 32GB does not seem to make any sense. I'm not clear why that would be the default...

In any event, I have not had an OOM situation since then in the last week or so. Last night, the mover ran at 12am while recording 3 late night shows without incident. I'll continue checking for issues this week and report back if I see anything. ...But for now, I think the OOM issue is resolved.

Thanks again! -Glen.

PS: vfs.cache_pressure is a setting on the Dynamix cache dirs plugin? I need to figure out what that plugin does and whether it I need to install it.... Does this plugin help SageTV run more efficiently?

[EnterNoEscape]

Originally Posted by glenner

PS: vfs.cache_pressure is a setting on the Dynamix cache dirs plugin? I need to figure out what that plugin does and whether it I need to install it.... Does this plugin help SageTV run more efficiently?

Yes.

It attempts to keep a certain level of folders cached in memory. This helps if you allow your disks to spin down since it decreases the chances that you will needlessly spin up a disk that shares the folder you're in.

[Fuzzy]

I believe the upcoming 6.4 version of unRAID is changing the way Mover works, moving away from rsync, I believe. Not sure if this will change the errant behavior here, but it might do something good. I'm not sure on an expected release date for the new version though.

In any case, I think there is also a problem if your Sage process is actually using 6GB with just 4 clients.

[glenner]

Originally Posted by Fuzzy

I believe the upcoming 6.4 version of unRAID is changing the way Mover works, moving away from rsync, I believe. Not sure if this will change the errant behavior here, but it might do something good. I'm not sure on an expected release date for the new version though.

In any case, I think there is also a problem if your Sage process is actually using 6GB with just 4 clients.

Yeah.. not sure I was reading the memory usage correctly... or the mover errors I was seeing quoted 6GB (maybe virt?) in the syslog before killing the java process. My top output looks like this (sorted by %mem) :

top - 12:28:11 up 13 days, 22:02,  4 users,  load average: 0.44, 0.63, 0.65
Tasks: 410 total,   2 running, 408 sleeping,   0 stopped,   0 zombie
%Cpu(s):  7.0 us,  2.7 sy,  0.0 ni, 90.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem : 32878112 total,  2792252 free,  4515004 used, 25570856 buff/cache
KiB Swap:        0 total,        0 free,        0 used. 26493632 avail Mem
  scroll coordinates: y = 1/410 (tasks), x = 1/12 (fields)
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
22286 nobody    20   0 6853208 1.407g      0 S   6.3  4.5 233:25.37 java
14482 root      20   0 6800300 899468      0 S   0.3  2.7 198:20.87 java
12216 nobody    20   0  464156 324824      0 S   0.3  1.0  95:42.71 python
15270 root      20   0 4331800 297096   6092 S   0.0  0.9  31:07.81 java
16803 nobody    35  15 1778232 199624   2252 S   0.3  0.6  13:24.33 Plex Script Hos
15656 nobody    20   0  301880 178020   6424 S   1.0  0.5 187:07.28 squeezeboxserve
15430 nobody    20   0  332400 154520   2108 S   1.3  0.5 125:21.98 deluge-web
15406 nobody    20   0  462656 141688      0 S   1.0  0.4 117:41.16 deluged
13265 root      20   0 2402964 139512    680 S   8.0  0.4 765:13.88 shfs
27535 nobody    20   0  252408 117424   7164 R  15.9  0.4   7:32.98 comskip
20823 root      20   0  237396  85800  17132 S   0.7  0.3  11:47.73 php
16766 nobody    20   0  663668  80008  16132 S  21.3  0.2   1210:17 Plex Media Serv
16977 nobody    20   0  320272  43160   1592 S   0.0  0.1  11:01.24 Plex DLNA Serve
13532 root      20   0 1730528  42580  24048 S   0.0  0.1   7:51.38 dockerd
25031 nobody    20   0  884128  42332  11144 S   0.0  0.1   0:01.31 Plex Script Hos
24988 nobody    20   0  877616  35780  11112 S   0.0  0.1   0:00.74 Plex Script Hos

So the pid 22286 java process is SageTV. 14482 and 15270 are crashplan java processes. Memory utilization on 22286 is 4.5% of 32GB, or 1.4GB I guess? The total virtual memory for the process is 6GB. Is that how I read that? I have not tweaked any memory settings on anything... So this is all out of the box behaviour...