Transcode - disk space usage - weird behavior

Plex Media Server
1

plex logs 1 - failure.log (281.3 KB)
plex logs 2 - throttling.log (692.2 KB)

Server Version#: 1.32.3.7162

Hi,

I’ve found a very weird behavior when transcoding media and found many similar topics without response or with response it’s not a bug, it’s just bad usage of Plex. Anyway, I had to try to get it fixed as I think I have found a real bug there.

Below is an EXAMPLE with small tmpfs, but the same behavior can be achieved using real configuration. I’m using Plex in docker container on small PC without large device for transcode and don’t like the idea of FLASH/SSD wear out. And even 16 GB is not enough for large movies.

EAMPLE CONFIGURATION

  • 512 MB /transcode dir
  • HEVC video, 57 minutes length
  • playing using Android app with cast to Chromecast 3 (needs transcode to H264)

1. START VIDEO FROM THE BEGINNING

  • video plays, transcoding is in progress
  • after (approx.) 80s there is 15% of the movie already pre-transcoded, free disk space is 0, transcoder fails, video stops
  • THERE WAS NO THROTTLING
  • note: percentage above is taken from web UI - dashboard and transcodeProgressPercent field)

2. START VIDEO AND REWIND AFTER CURRENT TRANSCODE CACHE PRELOAD

  • video plays, transcoding is in progress
  • after 15s there is only a few % transcoded, so rewind to 5:00 (needs to be after current transcode cache preload)
  • video plays correctly till the end, /transcode dir has approx. 100 MB free after few minutes and it stays the same till the end
  • throttling / sloth mode is working as expected
  • note: in this case after rewind I saw no transcode progress bar in the web UI, and it was because the value of transcodeProgressPercent was lower than playProgressPercent (but it’s probably just cosmetics.

Logs from both cases are in attachment, but I’ve also added small snip below.

Logs for case 1 (no throttling, failure)

Jun 06, 2023 17:36:15.853 [140242819853112] WARN - [Req#10c7/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 357.51kB source file, 512MB capacity, 1.62MB available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:15.853 [140242819853112] WARN - [Req#10c7/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 0B source file, 512MB capacity, 1.62MB available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:15.853 [140242819853112] WARN - [Req#10c7/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 0B source file, 512MB capacity, 1.62MB available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:15.853 [140242819853112] WARN - [Req#10c7/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 0B source file, 512MB capacity, 1.62MB available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:15.853 [140242819853112] WARN - [Req#10c7/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 0B source file, 512MB capacity, 1.62MB available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:16.045 [140242732849976] ERROR - [Req#10c6/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] av_interleaved_write_frame(): No space left on device
Jun 06, 2023 17:36:16.118 [140242830572344] ERROR - [Req#10cb/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] av_interleaved_write_frame(): No space left on device
Jun 06, 2023 17:36:16.118 [140242819853112] ERROR - [Req#10cc/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] [segment @ 0x7f2ee27616c0] Failure occurred when ending segment 'chunk-00156'
Jun 06, 2023 17:36:16.119 [140242732849976] DEBUG - [Req#10c8/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Transcoder segment range: 26 - 156 (156)
Jun 06, 2023 17:36:16.119 [140242732849976] WARN - [Req#10c8/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 357.51kB source file, 512MB capacity, 0B available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:16.119 [140242732849976] WARN - [Req#10c8/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 0B source file, 512MB capacity, 0B available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:16.119 [140242830572344] ERROR - [Req#10cd/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Error writing trailer of chunk-%05d: No space left on device
Jun 06, 2023 17:36:16.119 [140242732849976] WARN - [Req#10c8/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 0B source file, 512MB capacity, 0B available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:16.119 [140242732849976] WARN - [Req#10c8/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 0B source file, 512MB capacity, 0B available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:16.119 [140242732849976] WARN - [Req#10c8/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 0B source file, 512MB capacity, 0B available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:16.119 [140242819853112] WARN - [Req#10ce/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 357.51kB source file, 512MB capacity, 0B available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:16.119 [140242819853112] WARN - [Req#10ce/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 0B source file, 512MB capacity, 0B available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:16.119 [140242819853112] WARN - [Req#10ce/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 0B source file, 512MB capacity, 0B available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:16.119 [140242819853112] WARN - [Req#10ce/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 0B source file, 512MB capacity, 0B available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:16.119 [140242819853112] WARN - [Req#10ce/Transcode/h7tnm1cqmcnkjhyf1ck3kmyf/050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f] Low disk space: 0B source file, 512MB capacity, 0B available on "/transcode/Transcode/Sessions/plex-transcode-h7tnm1cqmcnkjhyf1ck3kmyf-050cd6d2-8aa1-47d7-bb8e-060c3ed7dc4f"
Jun 06, 2023 17:36:16.146 [140242871503672] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 1320 is 1 (failure)
Jun 06, 2023 17:36:16.146 [140242762369848] DEBUG - Notifying consumer that data is complete.
Jun 06, 2023 17:36:16.146 [140242747616056] DEBUG - [TranscodeOutputStream] Input processing thread exited after writing 10063 bytes, m_closed=0, m_endOfFileReached=1, session->isStopped()=0
Jun 06, 2023 17:36:16.146 [140242762369848] DEBUG - Notifying consumer that data is complete.
Jun 06, 2023 17:36:16.146 [140242762369848] DEBUG - Streaming Resource: Terminating session 0x7f8cd2684e08:7u9kc6e7l2ez80ygd50tiigg which is using 10000000kbps of WAN bandwidth.  Used is now 0kbps
Jun 06, 2023 17:36:16.146 [140242762369848] DEBUG - Streaming Resource: Terminating session 0x7f8cd2684e08:7u9kc6e7l2ez80ygd50tiigg which is using transcoder slot.  Used slots is now 0
Jun 06, 2023 17:36:16.146 [140242817497912] DEBUG - Killing job.
Jun 06, 2023 17:36:16.146 [140242817497912] DEBUG - Signalling job ID 1320 with 9

Logs for case 2 (throttling, no failure)

Jun 06, 2023 17:54:30.796 [140242724412216] WARN - [Req#3bea/Transcode/1ys823rwm5alt3vgyi04uv0d/9adc5729-6f5c-4f6b-99cd-b803fb9f0209] Low disk space: 357.51kB source file, 512MB capacity, 89.75MB available on "/transcode/Transcode/Sessions/plex-transcode-1ys823rwm5alt3vgyi04uv0d-9adc5729-6f5c-4f6b-99cd-b803fb9f0209"
Jun 06, 2023 17:54:30.796 [140242724412216] WARN - [Req#3bea/Transcode/1ys823rwm5alt3vgyi04uv0d/9adc5729-6f5c-4f6b-99cd-b803fb9f0209] Low disk space: 0B source file, 512MB capacity, 89.75MB available on "/transcode/Transcode/Sessions/plex-transcode-1ys823rwm5alt3vgyi04uv0d-9adc5729-6f5c-4f6b-99cd-b803fb9f0209"
Jun 06, 2023 17:54:30.796 [140242724412216] DEBUG - [Req#3bea/Transcode/1ys823rwm5alt3vgyi04uv0d/9adc5729-6f5c-4f6b-99cd-b803fb9f0209] Pruning segments older than 5, view offset is 530.000000, min was 0, max is 81, last returned is 564.607000
Jun 06, 2023 17:54:30.796 [140242724412216] DEBUG - [Req#3bea/Transcode/1ys823rwm5alt3vgyi04uv0d/9adc5729-6f5c-4f6b-99cd-b803fb9f0209] Pruning segment 4
Jun 06, 2023 17:54:30.797 [140242724412216] DEBUG - [Req#3bea/Transcode/1ys823rwm5alt3vgyi04uv0d/9adc5729-6f5c-4f6b-99cd-b803fb9f0209] Pruning segment 3
Jun 06, 2023 17:54:30.797 [140242724412216] DEBUG - [Req#3bea/Transcode/1ys823rwm5alt3vgyi04uv0d/9adc5729-6f5c-4f6b-99cd-b803fb9f0209] Pruning segment 2
Jun 06, 2023 17:54:30.797 [140242724412216] DEBUG - [Req#3bea/Transcode/1ys823rwm5alt3vgyi04uv0d/9adc5729-6f5c-4f6b-99cd-b803fb9f0209] Pruning segment 1
Jun 06, 2023 17:54:30.798 [140242724412216] DEBUG - [Req#3bea/Transcode/1ys823rwm5alt3vgyi04uv0d/9adc5729-6f5c-4f6b-99cd-b803fb9f0209] Pruning segment 0
Jun 06, 2023 17:54:30.799 [140242804792120] DEBUG - [Req#3bef/Transcode/1ys823rwm5alt3vgyi04uv0d/9adc5729-6f5c-4f6b-99cd-b803fb9f0209] Transcoder segment range: 5 - 82 (81)
Jun 06, 2023 17:54:31.158 [140242817497912] DEBUG - [Req#3bee/Transcode/1ys823rwm5alt3vgyi04uv0d/9adc5729-6f5c-4f6b-99cd-b803fb9f0209] Session 1ys823rwm5alt3vgyi04uv0d (2) is throttling
Jun 06, 2023 17:54:31.159 [140242724412216] DEBUG - [Req#3bf3/Transcode/1ys823rwm5alt3vgyi04uv0d/9adc5729-6f5c-4f6b-99cd-b803fb9f0209] Throttle - Going into sloth mode.
2

In case 1, the transcoder never makes it to the point of throttling.

May I please have the full logs ZIP file so I have the full version/ distro / processor info?

I see the failure in the log excerpt but it’s not enough to speak to the engineer about.

3

Yes, that is exactly my point. In case 1 transcoder is 8 minutes ahead, disk space is full and throttling is not happening at all. When I enlarged /transcode to 2 GB, transcoder was approx. 32 minutes ahead when it crashed.

Difference for case 2 is just rewind few minutes and whole throttling funcionality works fine.

I’ve just reproduced it agin with clean logs while streaming to Chromecast 3 using Android app. The same is when using app.plex.tv and web browser to stream to the same Chromecast.
Plex Media Server Logs_2023-06-08_06-58-23.zip (53.7 KB)

Please note that I was not able to reproduce it when playing from web browser even I tried to set transcoding as well.

4

@j_rypacek

Thank you! This is perfect capture.

I’m writing up now and submitting

FWIW: 512 MB transcode directory space is extremely small and pretty unrealistic if you want to transcode videos as it will spend most of its time pruning.

I question whether there’s enough room for the transcoder to build up a sufficient buffer for the player to actually use and maintain more than a few seconds of buffer.
(but that’s highly subject to output video bitrate)

5

Thanks! In my case 512MB is probably enough for approx. 8 minute buffer of transcoded video.
I could do the same test with larger transcode directory space for you, but the testing and log output would be much larger.
This small size is only for purpose of example and I’m using larger transcode dir, but the result is the same.

P.S. Last year I created another report of bug here and it’s still valid. But it does not affect me as I was able to find a workaround at network level (NAT).

6

Hi Chuck, is there anything new about this issue?

7

We’re going through all our outstanding transcode issues right now (since the staffing change) and prioritizing.

Unfortunately, I don’t have anything to report to you at this time.
This problem is still on the “To Fix” list.

1 Like
8

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.