2023-06-24, 12:06 AM
(2023-06-21, 11:58 PM)joshuaboniface Wrote: Aah knowing that it's ProxMox definitely explains it. Because of how the KVM virtualization in ProxMox works, from ProxMox's perspective, the RAM is indeed "used" by the VM even though it's just page cache data inside the VM, because the hypervisor can't hand that RAM out to other VMs. Unlike inside the VM itself where that memory could easily be used by another application.
Best thing to do would just be to shrink the VM. If Jellyfin isn't using 16GB (and it isn't, not even close), the VM doesn't need to be 16GB and thus it won't steal 16GB of RAM from the hypervisor. Based on your usage a 4GB VM is probably plenty.
Ok, so today It was advised the server became unresponsive, slow, or not doing anything for playback request. I've grabbed logs when it was reported. I am seeing thread pool starvation logs here. It does not seem the RAM is to really blame as ps aux showed that around 27% only the systemctl showed 13.2G in use. I've attached logs. The only way to restore playback is by restarting the VM.
● jellyfin.service - Jellyfin Media Server
Loaded: loaded (/lib/systemd/system/jellyfin.service; enabled; vendor preset: enabled)
Drop-In: /etc/systemd/system/jellyfin.service.d
└─jellyfin.service.conf
Active: active (running) since Tue 2023-06-20 17:11:44 UTC; 3 days ago
Main PID: 2204 (jellyfin)
Tasks: 1893 (limit: 18652)
Memory: 13.2G
CPU: 7h 22min 50.748s
CGroup: /system.slice/jellyfin.service
└─2204 /usr/bin/jellyfin --webdir=/usr/share/jellyfin/web --restartpath=/usr/lib/jellyfin/restart.sh --ffmpeg=/usr/lib/jellyfin-ffmpeg/ffmpeg
Jun 23 23:50:20 jellyfin jellyfin[2204]: [23:50:20] [WRN] Slow HTTP Response from https://x.x.x.x/Sessions/Playing/Progress to 67.169.246.80 in 0:00:52.9345716 with Status Code 204
Jun 23 23:50:37 jellyfin jellyfin[2204]: [23:50:37] [WRN] As of "06/23/2023 23:50:27 +00:00", the heartbeat has been running for "00:00:10.0824389" which is longer than "00:00:01". This could be caused by thread pool starvatio>
Jun 23 23:50:43 jellyfin jellyfin[2204]: [23:50:43] [WRN] Slow HTTP Response from https://x.x.x.x/Sessions/Playing/Progress to 67.169.246.80 in 0:00:31.6790499 with Status Code 204
Jun 23 23:50:58 jellyfin jellyfin[2204]: [23:50:58] [WRN] Slow HTTP Response from https://x.x.x.x/Sessions/Playing/Progress to 67.169.246.80 in 0:01:01.8857423 with Status Code 204
Jun 23 23:51:10 jellyfin jellyfin[2204]: [23:51:10] [WRN] Slow HTTP Response from https://x.x.x.x/Sessions/Playing/Progress to 67.169.246.80 in 0:00:39.1877933 with Status Code 204
Jun 23 23:51:15 jellyfin jellyfin[2204]: [23:51:15] [WRN] Slow HTTP Response from https://x.x.x.x/Sessions/Playing/Progress to 67.169.246.80 in 0:01:33.2583702 with Status Code 204
Jun 23 23:51:20 jellyfin jellyfin[2204]: [23:51:20] [WRN] Slow HTTP Response from https://x.x.x.x/Sessions/Playing/Progress to 67.169.246.80 in 0:02:07.9183341 with Status Code 204
Jun 23 23:51:51 jellyfin jellyfin[2204]: [23:51:51] [WRN] Slow HTTP Response from https://x.x.x.x/Sessions/Playing/Progress to 67.169.246.80 in 0:01:09.2732972 with Status Code 204
Jun 23 23:52:17 jellyfin jellyfin[2204]: [23:52:17] [WRN] Slow HTTP Response from https://x.x.x.x/Sessions/Playing/Progress to 67.169.246.80 in 0:01:20.6886333 with Status Code 204
Jun 23 23:52:45 jellyfin jellyfin[2204]: [23:52:45] [WRN] As of "06/23/2023 23:52:41 +00:00", the heartbeat has been running for "00:00:03.8813143" which is longer than "00:00:01". This could be caused by thread pool starvatio>
Fri Jun 23 11:53:19 PM UTC 2023 (date) command
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1 0.0 0.0 167744 12208 ? Ss Jun20 0:13 /sbin/init
root 2 0.0 0.0 0 0 ? S Jun20 0:01 [kthreadd]
root 3 0.0 0.0 0 0 ? I< Jun20 0:00 [rcu_gp]
root 4 0.0 0.0 0 0 ? I< Jun20 0:00 [rcu_par_gp]
root 5 0.0 0.0 0 0 ? I< Jun20 0:00 [slub_flushwq]
root 6 0.0 0.0 0 0 ? I< Jun20 0:00 [netns]
root 8 0.0 0.0 0 0 ? I< Jun20 0:00 [kworker/0:0H-events_highpri]
root 10 0.0 0.0 0 0 ? I< Jun20 0:00 [mm_percpu_wq]
root 11 0.0 0.0 0 0 ? S Jun20 0:00 [rcu_tasks_rude_]
root 12 0.0 0.0 0 0 ? S Jun20 0:00 [rcu_tasks_trace]
root 13 0.0 0.0 0 0 ? S Jun20 0:00 [ksoftirqd/0]
root 14 0.0 0.0 0 0 ? I Jun20 0:53 [rcu_sched]
root 15 0.0 0.0 0 0 ? S Jun20 0:02 [migration/0]
root 16 0.0 0.0 0 0 ? S Jun20 0:00 [idle_inject/0]
root 18 0.0 0.0 0 0 ? S Jun20 0:00 [cpuhp/0]
root 19 0.0 0.0 0 0 ? S Jun20 0:00 [cpuhp/1]
root 20 0.0 0.0 0 0 ? S Jun20 0:00 [idle_inject/1]
root 21 0.0 0.0 0 0 ? S Jun20 0:02 [migration/1]
root 22 0.0 0.0 0 0 ? S Jun20 0:00 [ksoftirqd/1]
root 24 0.0 0.0 0 0 ? I< Jun20 0:00 [kworker/1:0H-events_highpri]
root 25 0.0 0.0 0 0 ? S Jun20 0:00 [cpuhp/2]
root 26 0.0 0.0 0 0 ? S Jun20 0:00 [idle_inject/2]
root 27 0.0 0.0 0 0 ? S Jun20 0:02 [migration/2]
root 28 0.0 0.0 0 0 ? S Jun20 0:00 [ksoftirqd/2]
root 30 0.0 0.0 0 0 ? I< Jun20 0:00 [kworker/2:0H-events_highpri]
root 31 0.0 0.0 0 0 ? S Jun20 0:00 [cpuhp/3]
root 32 0.0 0.0 0 0 ? S Jun20 0:00 [idle_inject/3]
root 33 0.0 0.0 0 0 ? S Jun20 0:02 [migration/3]
root 34 0.0 0.0 0 0 ? S Jun20 2:13 [ksoftirqd/3]
root 36 0.0 0.0 0 0 ? I< Jun20 0:00 [kworker/3:0H-events_highpri]
root 37 0.0 0.0 0 0 ? S Jun20 0:00 [cpuhp/4]
root 38 0.0 0.0 0 0 ? S Jun20 0:00 [idle_inject/4]
root 39 0.0 0.0 0 0 ? S Jun20 0:02 [migration/4]
root 40 0.0 0.0 0 0 ? S Jun20 0:00 [ksoftirqd/4]
root 42 0.0 0.0 0 0 ? I< Jun20 0:00 [kworker/4:0H-events_highpri]
root 43 0.0 0.0 0 0 ? S Jun20 0:00 [cpuhp/5]
root 44 0.0 0.0 0 0 ? S Jun20 0:00 [idle_inject/5]
root 45 0.0 0.0 0 0 ? S Jun20 0:02 [migration/5]
root 46 0.0 0.0 0 0 ? S Jun20 0:00 [ksoftirqd/5]
root 48 0.0 0.0 0 0 ? I< Jun20 0:00 [kworker/5:0H-events_highpri]
root 49 0.0 0.0 0 0 ? S Jun20 0:00 [cpuhp/6]
root 50 0.0 0.0 0 0 ? S Jun20 0:00 [idle_inject/6]
root 51 0.0 0.0 0 0 ? S Jun20 0:02 [migration/6]
root 52 0.0 0.0 0 0 ? S Jun20 0:00 [ksoftirqd/6]
root 54 0.0 0.0 0 0 ? I< Jun20 0:00 [kworker/6:0H-events_highpri]
root 55 0.0 0.0 0 0 ? S Jun20 0:00 [cpuhp/7]
root 56 0.0 0.0 0 0 ? S Jun20 0:00 [idle_inject/7]
root 57 0.0 0.0 0 0 ? S Jun20 0:02 [migration/7]
root 58 0.0 0.0 0 0 ? S Jun20 0:06 [ksoftirqd/7]
root 60 0.0 0.0 0 0 ? I< Jun20 0:00 [kworker/7:0H-events_highpri]
root 61 0.0 0.0 0 0 ? S Jun20 0:00 [kdevtmpfs]
root 62 0.0 0.0 0 0 ? I< Jun20 0:00 [inet_frag_wq]
root 63 0.0 0.0 0 0 ? S Jun20 0:00 [kauditd]
root 65 0.0 0.0 0 0 ? S Jun20 0:00 [khungtaskd]
root 66 0.0 0.0 0 0 ? S Jun20 0:00 [oom_reaper]
root 67 0.0 0.0 0 0 ? I< Jun20 0:00 [writeback]
root 68 0.0 0.0 0 0 ? S Jun20 0:55 [kcompactd0]
root 69 0.0 0.0 0 0 ? SN Jun20 0:00 [ksmd]
root 70 0.0 0.0 0 0 ? SN Jun20 0:04 [khugepaged]
root 116 0.0 0.0 0 0 ? I< Jun20 0:00 [kintegrityd]
root 117 0.0 0.0 0 0 ? I< Jun20 0:00 [kblockd]
root 118 0.0 0.0 0 0 ? I< Jun20 0:00 [blkcg_punt_bio]
root 120 0.0 0.0 0 0 ? I< Jun20 0:00 [tpm_dev_wq]
root 121 0.0 0.0 0 0 ? I< Jun20 0:00 [ata_sff]
root 122 0.0 0.0 0 0 ? I< Jun20 0:00 [md]
root 123 0.0 0.0 0 0 ? I< Jun20 0:00 [edac-poller]
root 124 0.0 0.0 0 0 ? I< Jun20 0:00 [devfreq_wq]
root 125 0.0 0.0 0 0 ? S Jun20 0:00 [watchdogd]
root 129 0.0 0.0 0 0 ? I< Jun20 0:38 [kworker/4:1H-kblockd]
root 134 0.0 0.0 0 0 ? S Jun20 0:42 [kswapd0]
root 135 0.0 0.0 0 0 ? S Jun20 0:00 [ecryptfs-kthrea]
root 137 0.0 0.0 0 0 ? I< Jun20 0:00 [kthrotld]
root 138 0.0 0.0 0 0 ? I< Jun20 0:00 [acpi_thermal_pm]
root 140 0.0 0.0 0 0 ? S Jun20 0:00 [scsi_eh_0]
root 141 0.0 0.0 0 0 ? I< Jun20 0:00 [scsi_tmf_0]
root 142 0.0 0.0 0 0 ? S Jun20 0:00 [scsi_eh_1]
root 143 0.0 0.0 0 0 ? I< Jun20 0:00 [scsi_tmf_1]
root 145 0.0 0.0 0 0 ? I< Jun20 0:00 [vfio-irqfd-clea]
root 146 0.0 0.0 0 0 ? I< Jun20 0:00 [mld]
root 147 0.0 0.0 0 0 ? I< Jun20 0:12 [kworker/6:1H-kblockd]
root 148 0.0 0.0 0 0 ? I< Jun20 0:00 [ipv6_addrconf]
root 158 0.0 0.0 0 0 ? I< Jun20 0:00 [kstrp]
root 161 0.0 0.0 0 0 ? I< Jun20 0:00 [zswap-shrink]
root 167 0.0 0.0 0 0 ? I< Jun20 0:00 [charger_manager]
root 204 0.0 0.0 0 0 ? I< Jun20 0:10 [kworker/0:1H-kblockd]
root 210 0.0 0.0 0 0 ? S Jun20 0:00 [scsi_eh_2]
root 211 0.0 0.0 0 0 ? I< Jun20 0:00 [scsi_tmf_2]
root 224 0.0 0.0 0 0 ? I< Jun20 0:00 [cryptd]
root 234 0.0 0.0 0 0 ? I< Jun20 0:09 [kworker/3:1H-kblockd]
root 235 0.0 0.0 0 0 ? I< Jun20 0:09 [kworker/1:1H-kblockd]
root 238 0.0 0.0 0 0 ? I< Jun20 0:14 [kworker/7:1H-kblockd]
root 239 0.0 0.0 0 0 ? I< Jun20 0:09 [kworker/2:1H-kblockd]
root 243 0.0 0.0 0 0 ? I< Jun20 0:15 [kworker/5:1H-kblockd]
root 305 0.0 0.0 0 0 ? I< Jun20 0:00 [raid5wq]
root 352 0.0 0.0 0 0 ? S Jun20 3:34 [jbd2/sda2-8]
root 353 0.0 0.0 0 0 ? I< Jun20 0:00 [ext4-rsv-conver]
root 429 0.0 0.1 72660 21188 ? S<s Jun20 1:56 /lib/systemd/systemd-journald
root 465 0.0 0.0 0 0 ? I< Jun20 0:00 [kaluad]
root 467 0.0 0.0 0 0 ? I< Jun20 0:00 [kmpath_rdacd]
root 468 0.0 0.0 0 0 ? I< Jun20 0:00 [kmpathd]
root 469 0.0 0.0 0 0 ? I< Jun20 0:00 [kmpath_handlerd]
root 473 0.0 0.1 289348 27100 ? SLsl Jun20 0:51 /sbin/multipathd -d -s
root 477 0.0 0.0 25876 5680 ? Ss Jun20 0:01 /lib/systemd/systemd-udevd
_rpc 547 0.0 0.0 8100 4128 ? Ss Jun20 0:00 /sbin/rpcbind -f -w
systemd+ 548 0.0 0.0 89352 6188 ? Ssl Jun20 0:01 /lib/systemd/systemd-timesyncd
root 553 0.0 0.0 0 0 ? I< Jun20 0:00 [rpciod]
root 554 0.0 0.0 0 0 ? I< Jun20 0:00 [xprtiod]
systemd+ 704 0.0 0.0 16116 7592 ? Ss Jun20 0:04 /lib/systemd/systemd-networkd
root 706 0.0 0.0 0 0 ? S Jun20 0:00 [nv_queue]
root 707 0.0 0.0 0 0 ? S Jun20 0:00 [nv_queue]
systemd+ 710 0.0 0.0 25528 12412 ? Ss Jun20 0:01 /lib/systemd/systemd-resolved
root 712 0.0 0.0 0 0 ? S Jun20 0:00 [nvidia-modeset/]
root 713 0.0 0.0 0 0 ? S Jun20 0:00 [nvidia-modeset/]
root 723 0.0 0.0 0 0 ? S Jun20 0:00 [UVM global queu]
root 724 0.0 0.0 0 0 ? S Jun20 0:00 [UVM deferred re]
root 725 0.0 0.0 0 0 ? S Jun20 0:00 [UVM Tools Event]
message+ 748 0.0 0.0 8868 4552 ? Ss Jun20 0:01 @dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
root 753 0.0 0.0 82772 4000 ? Ssl Jun20 0:28 /usr/sbin/irqbalance --foreground
root 755 0.0 0.0 32796 13832 ? Ss Jun20 0:00 /usr/bin/python3 /usr/bin/networkd-dispatcher --run-startup-triggers
nvidia-+ 757 0.0 0.0 5308 1960 ? Ss Jun20 0:00 /usr/bin/nvidia-persistenced --user nvidia-persistenced --no-persistence-mode --verbose
root 758 0.0 0.0 239268 8768 ? Ssl Jun20 0:00 /usr/libexec/polkitd --no-debug
root 759 0.0 0.0 0 0 ? I< Jun20 0:00 [nfsiod]
syslog 760 0.0 0.0 222400 5444 ? Ssl Jun20 0:18 /usr/sbin/rsyslogd -n -iNONE
root 768 0.0 0.2 1540728 44136 ? Ssl Jun20 0:47 /usr/lib/snapd/snapd
root 776 0.0 0.0 48124 7436 ? Ss Jun20 0:01 /lib/systemd/systemd-logind
root 784 0.0 0.0 392572 12260 ? Ssl Jun20 0:01 /usr/libexec/udisks2/udisksd
root 792 0.0 0.0 15420 7744 ? Ss Jun20 0:00 sshd: /usr/sbin/sshd -D [listener] 0 of 10-100 startups
root 802 0.0 0.0 317956 11580 ? Ssl Jun20 0:00 /usr/sbin/ModemManager
root 834 0.0 0.0 0 0 ? S Jun20 0:00 [NFSv4 callback]
root 848 0.0 0.1 109748 16632 ? Ssl Jun20 0:00 /usr/bin/python3 /usr/share/unattended-upgrades/unattended-upgrade-shutdown --wait-for-signal
root 853 0.0 0.0 6892 2932 ? Ss Jun20 0:01 /usr/sbin/cron -f -P
daemon 855 0.0 0.0 3860 1296 ? Ss Jun20 0:00 /usr/sbin/atd -f
root 866 0.0 0.0 6172 1084 tty1 Ss+ Jun20 0:00 /sbin/agetty -o -p -- \u --noclear tty1 linux
root 867 2.9 0.3 865688 59908 ? Ssl Jun20 144:02 /usr/sbin/tailscaled --state=/var/lib/tailscale/tailscaled.state --socket=/run/tailscale/tailscaled.sock --port=41641
root 2098 0.0 0.0 17172 9112 ? Ss Jun20 0:00 sshd: pfs [priv]
pfs 2101 0.0 0.0 17052 8816 ? Ss Jun20 0:00 /lib/systemd/systemd --user
pfs 2102 0.0 0.0 169308 3780 ? S Jun20 0:00 (sd-pam)
pfs 2183 0.0 0.0 17304 6424 ? R Jun20 0:00 sshd: pfs@pts/0
pfs 2184 0.0 0.0 8732 5180 pts/0 Ss Jun20 0:00 -bash
jellyfin 2204 5.0 27.3 24647540 4385952 ? Ssl Jun20 239:27 /usr/bin/jellyfin --webdir=/usr/share/jellyfin/web --restartpath=/usr/lib/jellyfin/restart.sh --ffmpeg=/usr/lib/jellyfin-ffmpeg/ffmpeg
root 7138 0.0 0.0 239608 8532 ? Ssl Jun20 0:00 /usr/libexec/upowerd
root 9705 0.0 0.1 295552 20152 ? Ssl Jun21 0:03 /usr/libexec/packagekitd
root 26286 0.0 0.0 0 0 ? I Jun22 0:03 [kworker/6:3-mm_percpu_wq]
root 33299 0.0 0.0 0 0 ? I 06:49 0:03 [kworker/0:3-events]
root 33833 0.0 0.0 0 0 ? I 08:30 0:01 [kworker/2:1-mm_percpu_wq]
root 36092 0.0 0.0 0 0 ? I 13:19 0:00 [kworker/5:1]
root 36816 0.0 0.0 0 0 ? I 15:22 0:01 [kworker/5:0-mm_percpu_wq]
root 36934 0.0 0.0 0 0 ? I 15:41 0:00 [kworker/2:0-events]
root 37067 0.0 0.0 0 0 ? I 15:59 0:01 [kworker/4:1-events]
root 37208 0.0 0.0 0 0 ? I 16:22 0:00 [kworker/1:1-events]
root 37423 0.0 0.0 0 0 ? I 17:04 0:00 [kworker/6:0-mm_percpu_wq]
root 37623 0.0 0.0 0 0 ? I 17:35 0:00 [kworker/0:0-cgroup_destroy]
root 44858 0.0 0.0 0 0 ? I 20:11 0:00 [kworker/3:2-events]
root 45080 0.0 0.0 0 0 ? I 20:44 0:01 [kworker/4:0-mm_percpu_wq]
root 45556 0.0 0.0 0 0 ? I 21:50 0:00 [kworker/7:0-mm_percpu_wq]
root 45640 0.0 0.0 0 0 ? I 22:02 0:00 [kworker/7:1-mm_percpu_wq]
root 47174 0.0 0.0 0 0 ? I 23:21 0:00 [kworker/1:3-mm_percpu_wq]
root 47339 0.0 0.0 0 0 ? I 23:24 0:00 [kworker/u16:5-events_unbound]
root 47619 0.0 0.0 0 0 ? I 23:31 0:00 [kworker/u16:1-flush-8:0]
root 47633 0.0 0.0 0 0 ? I< 23:32 0:00 [kworker/u17:0-xprtiod]
root 47652 0.0 0.0 0 0 ? I< 23:32 0:00 [kworker/u17:3-xprtiod]
root 48217 0.0 0.0 0 0 ? I 23:41 0:00 [kworker/3:0-mm_percpu_wq]
root 48244 0.0 0.0 0 0 ? R 23:42 0:00 [kworker/u16:0-events_unbound]
root 48269 0.0 0.0 0 0 ? I 23:48 0:00 [kworker/u16:2-flush-8:0]
root 48276 0.0 0.0 0 0 ? I 23:51 0:00 [kworker/7:2-mm_percpu_wq]
pfs 48278 0.0 0.0 10068 1608 pts/0 R+ 23:51 0:00 ps aux
After restarting ===========================================================================================
● jellyfin.service - Jellyfin Media Server
Loaded: loaded (/lib/systemd/system/jellyfin.service; enabled; vendor preset: enabled)
Drop-In: /etc/systemd/system/jellyfin.service.d
└─jellyfin.service.conf
Active: active (running) since Fri 2023-06-23 23:55:01 UTC; 9min ago
Main PID: 754 (jellyfin)
Tasks: 44 (limit: 18652)
Memory: 1.0G
CPU: 59.870s
CGroup: /system.slice/jellyfin.service
└─754 /usr/bin/jellyfin --webdir=/usr/share/jellyfin/web --restartpath=/usr/lib/jellyfin/restart.sh --ffmpeg=/usr/lib/jellyfin-ffmpeg/ffmpeg
Jun 24 00:00:01 jellyfin jellyfin[754]: [00:00:01] [INF] Daily trigger for Playback Reporting Trim Db set to fire at 2023-06-25 00:00:00.000 +00:00, which is 23:59:58.9954745 from now.
Jun 24 00:00:12 jellyfin jellyfin[754]: [00:00:12] [INF] Playback stopped reported by app Jellyfin Mobile (iOS) 1.5.0 playing Bedazzled. Stopped at 5588581 ms
Jun 24 00:00:12 jellyfin jellyfin[754]: [00:00:12] [INF] Playback stop did not have a tracker : cb75206c-7d16-4fa0-89c8-6a898044ad14-9e742a13ff6c46c590273ef186d46136-d4872b55ec85282b1a294b8427912cd6
Jun 24 00:01:00 jellyfin jellyfin[754]: [00:01:00] [INF] DailyTrigger fired for task: Remove Old Cached Data
Jun 24 00:01:00 jellyfin jellyfin[754]: [00:01:00] [INF] Queuing task HousekeepingTask
Jun 24 00:01:00 jellyfin jellyfin[754]: [00:01:00] [INF] Executing Remove Old Cached Data
Jun 24 00:01:00 jellyfin jellyfin[754]: [00:01:00] [INF] Remove Old Cached Data Completed after 0 minute(s) and 0 seconds
Jun 24 00:01:00 jellyfin jellyfin[754]: [00:01:00] [INF] ExecuteQueuedTasks
Jun 24 00:01:01 jellyfin jellyfin[754]: [00:01:01] [INF] Daily trigger for Remove Old Cached Data set to fire at 2023-06-25 00:01:00.000 +00:00, which is 23:59:58.9946607 from now.
Jun 24 00:04:30 jellyfin jellyfin[754]: [00:04:30] [WRN] Slow HTTP Response from https://x.x.x.x/Items/4a590227d0f2d46216...&quality=>
lines 1-22/22 (END)