Just to confirm, you only need the Plex Media Server.log? Or do you want the whole /Logs directory zipped up?
On plex version: 1.26.0.5715
The session that had an issue when I changed it to 3mbps: wxcgx8tnxl9ffutk5tiipf55
PMS.log.zip (52.0 KB)
Thanks for that log⊠but I do need DEBUG logging level enabled.
What little bit I am seeing points to other problems as well.
Itâs clear the Xeon doesnât have QSV (I have E5-2690v4). Those errors are expected as the transcoder probes for capabilities.
Apr 14, 2022 08:16:48.385 [0x7efd1f04bb38] WARN - [DatabaseFixups] Held transaction for too long (/data/jenkins/server/3529576666/Library/MetadataCollection.cpp:479): 0.320000 seconds
Apr 14, 2022 08:16:48.451 [0x7efd1efc2b38] INFO - AutoUpdate: no updates available
Apr 14, 2022 08:16:48.669 [0x7efd1fc47b38] WARN - [EventSourceClient/pubsub/184.105.148.118:443] MyPlex: attempted a reachability check but we're not yet mapped.
Apr 14, 2022 08:16:48.718 [0x7efd1f04bb38] WARN - [DatabaseFixups] Held transaction for too long (/data/jenkins/server/3529576666/Library/MetadataCollection.cpp:479): 0.300000 seconds
Apr 14, 2022 08:16:49.106 [0x7efd1f04bb38] WARN - [DatabaseFixups] Held transaction for too long (/data/jenkins/server/3529576666/Library/MetadataCollection.cpp:479): 0.110000 seconds
Apr 14, 2022 08:16:49.109 [0x7efd1eb8cb38] WARN - SLOW QUERY: It took 260.000000 ms to retrieve 0 items.
Apr 14, 2022 08:16:49.249 [0x7efd1f04bb38] WARN - [DatabaseFixups] Held transaction for too long (/data/jenkins/server/3529576666/Library/MetadataCollection.cpp:479): 0.160000 seconds
Apr 14, 2022 08:16:49.311 [0x7efd1f04bb38] WARN - [DatabaseFixups] Held transaction for too long (/data/jenkins/server/3529576666/Library/MetadataCollection.cpp:479): 0.190000 seconds
Apr 14, 2022 08:16:49.326 [0x7efd1ed39b38] WARN - SLOW QUERY: It took 1160.000000 ms to retrieve 6 items.
Apr 14, 2022 08:16:49.368 [0x7efd1ebb7b38] WARN - SLOW QUERY: It took 1310.000000 ms to retrieve 0 items.
Apr 14, 2022 08:16:49.427 [0x7efd1ed94b38] WARN - SLOW QUERY: It took 1510.000000 ms to retrieve 6 items.
How many items are indexed in the DB?
When is the last time the butler ran to optimize the database ?
How many other things are happening on the CPU?
DEBUG is turned onâŠshould I completely clear the logs after that? I turned debugging on for the latest one at ~9:46 â do a grep on the session id and youâll see it is on âwxcgx8tnxl9ffutk5tiipf55â
How do I check for those details âhow many items indexed/butlerâ?
The server is running a lot of docker containers, but it isnât really heavily utilized all that much. The plex directory is on a 4TB NVMe drive as well, so it shouldnât have ANY slowness whatsoever. But now that you mention it, since iâve moved the directory to this NVMe drive is when it startedâŠstrange.
If you , with DEBUG logging turned on, recreate and then Download the logs ZIP again, that will give me what I need to see.
Regarding the NVMe performance, this is what I get.
Itâs probably a good idea to confirm youâre getting similar results.
[chuck@lizum Downloads.2019]$ sudo hdparm /dev/nvme0n1
/dev/nvme0n1:
HDIO_DRIVE_CMD(identify) failed: Inappropriate ioctl for device
readonly = 0 (off)
readahead = 256 (on)
HDIO_DRIVE_CMD(identify) failed: Inappropriate ioctl for device
geometry = 976762/64/32, sectors = 2000409264, start = 0
[chuck@lizum Downloads.2020]$ sudo hdparm -t /dev/nvme0n1
/dev/nvme0n1:
HDIO_DRIVE_CMD(identify) failed: Inappropriate ioctl for device
Timing buffered disk reads: 6718 MB in 3.00 seconds = 2239.21 MB/sec
[chuck@lizum Downloads.2021]$
Secondary thought: Did you enable fstrim.service ?
Trimmed PMS logs (DEBUG Only) Plex Media Server.zip (12.4 KB)
sudo hdparm /dev/nvme0n1 PLEX
/dev/nvme0n1:
HDIO_DRIVE_CMD(identify) failed: Inappropriate ioctl for device
readonly = 0 (off)
readahead = 256 (on)
geometry = 3052360/64/32, sectors = 6251233968, start = 0
root / $ sudo hdparm -t /dev/nvme0n1 PLEX
/dev/nvme0n1:
Timing buffered disk reads: 4098 MB in 3.00 seconds = 1365.42 MB/sec
fstrim is not enabledâŠ
That I/O should be almost 2x that rate at minimum.
I recommend:
sudo systemctl enable fstrim.service
sudo systemctl start fstrim
BE ADVISED:
When you manually start fstrim,
-
The disk i/o light will go wild as it frees ALL the unused pages/blocks
-
The system will seem like itâs hung except for the disk i/o. (The I/O bus is monopolized for these few seconds)
-
Freeing the unused pages/blocks is a huge performance boost because the SSD will no longer Copy/Modify/Write for each I/O. It will go directly to âWriteâ for all new blocks allocated.
-
Once enabled, Linux will run this monthly for you. Youâll never need worry about it again. It does this to ensure even SSD wear and improve performance.
Any questions?
started fstrim & fstrim.timer for scheduled running of fstrim (fstrim.service doesnât allow that)
It is taking a LONG time for it to go through it all â I also have a few other mdadm SSDs which I assume itâs going through and fixing now as well?
Also, I included the DEBUG logs for you here Converting to a lower quality fails with Hardware-Accelerated Streaming in Plex Web - #226 by lastb0isct
Yes, it will go through every SSD which has a filesystem.
It does a really great job.
If youâre willing to conduct a test, I have an older version for you.
PMS 1.24.5.5173
I know it will quiet one of the things Iâm seeing in your logs .
If, with this version, you now get correct playback, Iâll know there was a regression in 1.26.0 and start digging.
1 Like
Thanks! Iâll get to testingâŠ
Didnât resolve the issue, it seems. Added the log below. Same behavior where I change the settings to 3mbps, it plays for 30 seconds and then stops and doesnât continue.
PMS.zip (67.5 KB)
Would you do that one more time please?
This time, Stop the playback and stop PMS before grabbing the ZIP manually.
What I got in the log was mid-playback to 192.168.1.127
Apr 14, 2022 16:35:53.072 [0x7f1533f3cb38] DEBUG - Completed: [192.168.1.127:51447] 200 GET /status/sessions (9 live) TLS GZIP 0ms 475 bytes (pipelined: 72)
Apr 14, 2022 16:35:54.463 [0x7f1533f19b38] DEBUG - Completed: [192.168.1.127:51517] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (9 live) TLS GZIP 20001ms 5 bytes (pipelined: 4)
Apr 14, 2022 16:35:54.470 [0x7f1533a41b38] DEBUG - Request: [192.168.1.127:51517 (Allowed Network (Subnet))] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (9 live) TLS GZIP Signed-in Token (lastb0isct)
Apr 14, 2022 16:35:54.470 [0x7f1533a41b38] DEBUG - Content-Length is -1 (of total: -1).
<EOF>
This is an Android device ? Which one please ?
That was a different device it seems. Iâll take the time to stop/start the service and get a more specific log to go through.
That was WebUI on a Windows machine. This time I used Chrome on OSX.
I am testing the transcodes on WebUI because its much easier to select the transcode setting to reproduce it.
Finally got around to reproducing this again today. Let me know if you need anything further.
PMS_1.24.5.5173.zip (44.6 KB)
Just to expand a little more on it, if its set to transcode initially or if i manually change the stream to transcode it dies via HW decode/encode â not sure which is causing the issue.
Which Nvidia GPU are you using and which version drivers?
What I see in the logs is a software encode attempt followed by a hardware switchover.
Did you change transcoder sessions while playing in the one window?
Itâs a P400 I think? Iâll have to double check. Yes, I started playback at original and then swapped to 4mbps and then it stops playing back. Similar behavior when I set it to always 4mbpsâŠit isnât able to hardware encode
nvidia-smi will tell you everything you need.
[chuck@lizum ~.2001]$ gog nvidia-smi
Tue Apr 26 13:46:37 2022
+-----------------------------------------------------------------------------+
| NVIDIA-SMI 510.47.03 Driver Version: 510.47.03 CUDA Version: 11.6 |
|-------------------------------+----------------------+----------------------+
| GPU Name Persistence-M| Bus-Id Disp.A | Volatile Uncorr. ECC |
| Fan Temp Perf Pwr:Usage/Cap| Memory-Usage | GPU-Util Compute M. |
| | | MIG M. |
|===============================+======================+======================|
| 0 Quadro P2200 On | 00000000:07:00.0 Off | N/A |
| 47% 39C P0 27W / 75W | 701MiB / 5120MiB | 17% Default |
| | | N/A |
+-------------------------------+----------------------+----------------------+
+-----------------------------------------------------------------------------+
| Processes: |
| GPU GI CI PID Type Process name GPU Memory |
| ID ID Usage |
|=============================================================================|
| 0 N/A N/A 2142830 C ...diaserver/Plex Transcoder 697MiB |
+-----------------------------------------------------------------------------+
[chuck@lizum ~.2001]$
Here is the output:
| NVIDIA-SMI 510.60.02 Driver Version: 510.60.02 CUDA Version: 11.6 |
|-------------------------------+----------------------+----------------------+
| GPU Name Persistence-M| Bus-Id Disp.A | Volatile Uncorr. ECC |
| Fan Temp Perf Pwr:Usage/Cap| Memory-Usage | GPU-Util Compute M. |
| | | MIG M. |
|===============================+======================+======================|
| 0 Quadro P400 Off | 00000000:84:00.0 Off | N/A |
| 48% 60C P8 N/A / N/A | 2MiB / 2048MiB | 0% Default |
| | | N/A |
+-------------------------------+----------------------+----------------------+
+-----------------------------------------------------------------------------+
| Processes: |
| GPU GI CI PID Type Process name GPU Memory |
| ID ID Usage |
|=============================================================================|
| No running processes found |
+-----------------------------------------------------------------------------+
Thanks for confirming.
That P400, being the first card of the series, is limited (capped).
I tried switching mid-playback and replicated.
I then set the desired bitrate first before launching playback â This played flawlessly.
Can you confim?
