Jump to content
FliegenderMaulwurf

Transcoding live tv always stops after ~20 minutes

Recommended Posts

ebr

Hi.  Is your transcode location running out of space?

Share this post


Link to post
Share on other sites
FliegenderMaulwurf

The transcode location is on my external SSD with 238 GB of free space. That shouldn't be the problem.

Share this post


Link to post
Share on other sites
Luke

Hi, do you have another browser to test and compare with such as Chrome?

Share this post


Link to post
Share on other sites
FliegenderMaulwurf

Yes, I just tried it in chrome, but the stream also stopps.

Share this post


Link to post
Share on other sites
Happy2Play

I do not know this platform but are we sure the external drive is being used for transcode-temp?

 

Share this post


Link to post
Share on other sites
cayars

Where are you playing the channel from Guide or Channels tab?  Can you try from the other tab?

Do you have a problem playing back Live TV on any other clients such as Theater, Roku, Android?

Share this post


Link to post
Share on other sites
cayars

"/storage/emulated/0/tmp/transcoding-temp/2726C2_%d.ts"

That to me looks like internal storage.

@FliegenderMaulwurf How did you mount your external SSD?

Share this post


Link to post
Share on other sites
FliegenderMaulwurf
Posted (edited)

The external SSD is mounted as internal storage. There is no way you can tell from the path where it is actually stored but when I transcode, I can see the free space on the SSD is slowly decreasing while the free space on internal storage is constant.

I tried both from Guide and Channels tab, also tried on roku, but it's always the same.

The stream plays fine for hours without transcoding btw. Also transcoding video files is no problem.

Streams only stop when transcoding live tv.

In the server log there's a line:

Quote

2020-08-18 19:33:15.849 Info VideoHlsService: ProcessRun 'StreamTranscode f86759' Process exited with code 137

Can you tell from that exit code what's happening? Would a debug log provide more useful information?

Edited by FliegenderMaulwurf

Share this post


Link to post
Share on other sites
cayars

Not sure this matters but want to ask anyway.  How did you format the SSD?  What format did you use?

Share this post


Link to post
Share on other sites
FliegenderMaulwurf

I formatted it from the shield's settings menu. In the settings menu you can select a removable disk and then select to format it as device storage.

It doesn't tell you what format that is exactly.

Share this post


Link to post
Share on other sites
cayars

Do you by any chance have another SSD or large thumb drive that could be attached and used only for one thing (transcode) directory for a few tests?

Share this post


Link to post
Share on other sites
speechles
Posted (edited)

How intense is the CPU being hammered by the transcoding? It is being sent SIGKILL because of the load it is putting on the server. What settings do you have when transcoding? Are these left default or changed in any way? If this just happens when transcoding and it results in kill being sent the operating system is doing this. It isn't Emby killing the transcoding. Something is different about your transcoding settings or something. Something is different. Maybe the amount of RAM it eats up transcoding live TV becomes too large and that gets the SIGKILL sent? Maybe it is the CPU percentage used is too great for too long? It is hard to diagnose without Android logs.

2020-08-18 19:33:14.810 Info HttpServer: HTTP Response 200 to 192.168.213.21. Time: 10ms. http://192.168.213.15:8096/emby/videos/3404674/hls/2726C2/2726C2_446.ts
2020-08-18 19:33:15.087 Info HttpServer: SocketException: http://127.0.0.1:8096/LiveTv/LiveStreamFiles/560141d740414f6dbfbd93ba4210a6f8/stream.ts
2020-08-18 19:33:15.087 Info HttpServer: HTTP Response 200 to 127.0.0.1. Time: 1343240ms. http://127.0.0.1:8096/LiveTv/LiveStreamFiles/560141d740414f6dbfbd93ba4210a6f8/stream.ts
2020-08-18 19:33:15.250 Info VideoHlsService: AppendExtraLogData - Read graph file: /storage/emulated/0/Android/data/com.emby.embyserver/files/logs/ffmpeg-transcode-f8675993-9426-4ad7-91a5-2f9bb4563755_1graph.txt
2020-08-18 19:33:15.262 Warn VideoHlsService: AppendExtraLogData: Unable read graph output file: /storage/emulated/0/Android/data/com.emby.embyserver/files/logs/ffmpeg-transcode-f8675993-9426-4ad7-91a5-2f9bb4563755_1graph.txt
2020-08-18 19:33:15.849 Info VideoHlsService: ProcessRun 'StreamTranscode f86759' Process exited with code 137

 

Edited by speechles
  • Like 1

Share this post


Link to post
Share on other sites
FliegenderMaulwurf
1 hour ago, cayars said:

Do you by any chance have another SSD or large thumb drive that could be attached and used only for one thing (transcode) directory for a few tests?

Tried that twice, but the stream also stopped. However, the transcode log shows some error here at the end (see attached).

I attached the transcoding settings. I think I left them default, but not sure.

 

Transcoding-SettingsPNG.PNG

ffmpeg-transcode-55db04fc-afd2-4d56-84cc-7d1fba22fc31_1.txt

Share this post


Link to post
Share on other sites
cayars
44 minutes ago, speechles said:

How intense is the CPU being hammered by the transcoding? It is being sent SIGKILL because of the load it is putting on the server. What settings do you have when transcoding? Are these left default or changed in any way? If this just happens when transcoding and it results in kill being sent the operating system is doing this. It isn't Emby killing the transcoding. Something is different about your transcoding settings or something. Something is different. Maybe the amount of RAM it eats up transcoding live TV becomes too large and that gets the SIGKILL sent? Maybe it is the CPU percentage used is too great for too long? It is hard to diagnose without Android logs.


2020-08-18 19:33:14.810 Info HttpServer: HTTP Response 200 to 192.168.213.21. Time: 10ms. http://192.168.213.15:8096/emby/videos/3404674/hls/2726C2/2726C2_446.ts
2020-08-18 19:33:15.087 Info HttpServer: SocketException: http://127.0.0.1:8096/LiveTv/LiveStreamFiles/560141d740414f6dbfbd93ba4210a6f8/stream.ts
2020-08-18 19:33:15.087 Info HttpServer: HTTP Response 200 to 127.0.0.1. Time: 1343240ms. http://127.0.0.1:8096/LiveTv/LiveStreamFiles/560141d740414f6dbfbd93ba4210a6f8/stream.ts
2020-08-18 19:33:15.250 Info VideoHlsService: AppendExtraLogData - Read graph file: /storage/emulated/0/Android/data/com.emby.embyserver/files/logs/ffmpeg-transcode-f8675993-9426-4ad7-91a5-2f9bb4563755_1graph.txt
2020-08-18 19:33:15.262 Warn VideoHlsService: AppendExtraLogData: Unable read graph output file: /storage/emulated/0/Android/data/com.emby.embyserver/files/logs/ffmpeg-transcode-f8675993-9426-4ad7-91a5-2f9bb4563755_1graph.txt
2020-08-18 19:33:15.849 Info VideoHlsService: ProcessRun 'StreamTranscode f86759' Process exited with code 137

 

Where are you seeing the sigkill ?

Share this post


Link to post
Share on other sites
speechles
Posted (edited)

The code 137. That is either the ulimit being exceeded and it has either: run out of RAM (m or v) or the file size (f) has become too large thereby killing itself... or.. another process has asked it to die. The Android logs of that device will show which it was.

 

Edited by speechles

Share this post


Link to post
Share on other sites
cayars

Thank you sir, mucho appreciated!

Share this post


Link to post
Share on other sites
FliegenderMaulwurf

2020-08-20 22:43:35.983 Info VideoHlsService: ProcessRun 'StreamTranscode d04528' Process exited with code 137

Here are the system logs for this error:

08-20 22:42:38.277  3335  4391 D         : signalling poll failure
08-20 22:42:38.278  3335  4391 I         : SecureHdcp_PollFailure
08-20 22:42:38.278  3335  4391 E         : hdcp_status: readstatus failed
08-20 22:42:38.696  3453  8298 D NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 277.777778, AvgFrameRate = 277.658640 
08-20 22:42:38.760  3711  3735 I system_server: Background concurrent copying GC freed 74443(9MB) AllocSpace objects, 0(0B) LOS objects, 42% free, 12MB/21MB, paused 139us total 162.307ms
08-20 22:42:43.282  3335  4391 E         : hdcp_generate_nonce: nonce generation failure
08-20 22:42:43.282  3335  4391 E         : hdcp_status: hdcp_generate_nonce for version failed
08-20 22:42:43.376  3453  8298 D NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 277.777778, AvgFrameRate = 277.659408 
08-20 22:42:45.685  3450  3545 E storaged: getDiskStats failed with result NOT_SUPPORTED and size 0
08-20 22:42:48.287  3335  4391 D         : signalling poll failure
08-20 22:42:48.287  3335  4391 I         : SecureHdcp_PollFailure
08-20 22:42:48.287  3335  4391 E         : hdcp_status: readstatus failed
08-20 22:42:48.489  3453  8298 D NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 277.777778, AvgFrameRate = 277.660167 
08-20 22:42:53.290  3453  8298 D NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 277.777778, AvgFrameRate = 277.660916 
08-20 22:42:53.291  3335  4391 E         : hdcp_generate_nonce: nonce generation failure
08-20 22:42:53.291  3335  4391 E         : hdcp_status: hdcp_generate_nonce for version failed
08-20 22:42:57.062  3711  3735 I system_server: Background concurrent copying GC freed 70806(9MB) AllocSpace objects, 0(0B) LOS objects, 42% free, 12MB/21MB, paused 178us total 143.237ms
08-20 22:42:57.797  3453  8298 D NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 277.777778, AvgFrameRate = 277.661656 
08-20 22:42:58.296  3335  4391 D         : signalling poll failure
08-20 22:42:58.296  3335  4391 I         : SecureHdcp_PollFailure
08-20 22:42:58.296  3335  4391 E         : hdcp_status: readstatus failed
08-20 22:43:00.216  3349  3349 E lowmemorykiller: Error opening /dev/memcg/apps/uid_10084/pid_19997/memory.swappiness; errno=2
08-20 22:43:00.292  3711  3711 W Looper  : Slow dispatch took 138ms main h=android.app.ActivityThread$H c=android.app.-$$Lambda$LoadedApk$ReceiverDispatcher$Args$_BumDX2UKsnxLVrE6UJsJZkotuA@d0ceedf m=0
08-20 22:43:00.408  3349  3349 I chatty  : uid=0(root) /system/bin/lmkd identical 3 lines
08-20 22:43:00.412  3349  3349 E lowmemorykiller: Error opening /dev/memcg/apps/uid_10084/pid_19997/memory.swappiness; errno=2
08-20 22:43:02.910  3453  8298 D NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 277.777778, AvgFrameRate = 277.662386 
08-20 22:43:03.300  3335  4391 E         : hdcp_generate_nonce: nonce generation failure
08-20 22:43:03.300  3335  4391 E         : hdcp_status: hdcp_generate_nonce for version failed
08-20 22:43:03.363  3711  3711 E ActivityThread: Failed to find provider info for com.nvidia.ibeta
08-20 22:43:03.609  8941  8941 I chromium: [8941:8941:INFO:metrics_recorder.cc(106)] Metrics stat: total=5
08-20 22:43:03.609  8941  8941 I chromium: Cast.Discovery.Mdns.Query.Cast.Count=1
08-20 22:43:03.609  8941  8941 I chromium: Cast.Discovery.Mdns.Request.In=1
08-20 22:43:03.609  8941  8941 I chromium: Cast.Discovery.Mdns.Response.Out=1
08-20 22:43:03.609  8941  8941 I chromium: CastV2.Transport.Ping.Out=24
08-20 22:43:03.609  8941  8941 I chromium: CastV2.Transport.Pong.In=24
08-20 22:43:03.635  3711  3711 W Looper  : Slow dispatch took 328ms main h=android.os.Handler c=vendor.nvidia.hardware.server.wifi.NvWifi$iBetaQuery@ec3d72c m=0
08-20 22:43:03.636  3711  3711 E ActivityThread: Failed to find provider info for com.nvidia.ibeta
08-20 22:43:03.639  3711  3711 W Looper  : Slow delivery took 331ms main h=android.os.Handler c=vendor.nvidia.hardware.server.wifi.NvWifi$iBetaQuery@cfa35f5 m=0
08-20 22:43:03.735  8941  8985 I chromium: [8941:8985:INFO:wifi_proximity.cc(176)] Request scan.
08-20 22:43:03.794  8941  8983 I chromium: [8941:8983:INFO:mdns_app_filter.cc(2791)] Mdns cast queries recently sent: queries=1
08-20 22:43:05.000  8941  9027 I chromium: [8941:9027:INFO:ssdp_device.c(101)] SSDP packets sent for 39 seconds = 7
08-20 22:43:07.486  3453  8298 D NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 277.777778, AvgFrameRate = 277.663107 
08-20 22:43:07.671  8941  8981 E chromium: [8941:8981:ERROR:http_server.cc(472)] Cannot handle request with protocol: HTTP/1.0
08-20 22:43:07.672  8941  8981 E chromium: [8941:8981:ERROR:http_server.cc(472)] Cannot handle request with protocol: HTTP/1.0
08-20 22:43:07.847  8941  8983 I chromium: [8941:8983:INFO:mdns_app_filter.cc(2604)] MdnsAppFilter: responses sent in 64 seconds: 1
08-20 22:43:08.305  3335  4391 D         : signalling poll failure
08-20 22:43:08.305  3335  4391 I         : SecureHdcp_PollFailure
08-20 22:43:08.305  3335  4391 E         : hdcp_status: readstatus failed
08-20 22:43:12.311  3453  8298 D NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 277.777778, AvgFrameRate = 277.663820 
08-20 22:43:13.309  3335  4391 E         : hdcp_generate_nonce: nonce generation failure
08-20 22:43:13.309  3335  4391 E         : hdcp_status: hdcp_generate_nonce for version failed
08-20 22:43:15.847  8941  8984 I chromium: [8941:8984:INFO:metrics_recorder.cc(261)] Cast v2 action(socket_id=e30c0f39-51a5-69a0-5769-4628ed460a1e.3): CastV2.Connection.Connect.In
08-20 22:43:15.850  8941  8985 I chromium: [8941:8985:INFO:setup_namespace_handler.cc(92)] Added a peer for setup namespace: e30c0f39-51a5-69a0-5769-4628ed460a1e.3:gms_cast_prober-1
08-20 22:43:15.851  8941  8985 I chromium: [8941:8985:INFO:setup_state.cc(543)] EurekaInfoCalled: wifi_state=0, is_usable_ip_address=1, connected=1, is_initial_setup=0
08-20 22:43:15.872  8941  8985 I chromium: [8941:8985:INFO:setup_namespace_handler.cc(102)] Removed a peer for setup namespace: e30c0f39-51a5-69a0-5769-4628ed460a1e.3:gms_cast_prober-1
08-20 22:43:15.878  8941  8984 I chromium: [8941:8984:INFO:v2_ssl_socket.cc(356)] Stop reading on pending closed socket
08-20 22:43:16.004  3711  3735 I system_server: Background concurrent copying GC freed 71080(9MB) AllocSpace objects, 3(108KB) LOS objects, 42% free, 12MB/22MB, paused 145us total 136.493ms
08-20 22:43:17.018  3453  8298 D NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 277.777778, AvgFrameRate = 277.664523 
08-20 22:43:18.314  3335  4391 D         : signalling poll failure
08-20 22:43:18.314  3335  4391 I         : SecureHdcp_PollFailure
08-20 22:43:18.314  3335  4391 E         : hdcp_status: readstatus failed
08-20 22:43:18.527  7506  8304 I emby.embyserve: Explicit concurrent copying GC freed 3(16KB) AllocSpace objects, 0(0B) LOS objects, 58% free, 1100KB/2MB, paused 66us total 16.164ms
08-20 22:43:19.032  8941  8941 I chromium: [8941:8941:INFO:robot_account_auth_manager.cc(379)] Sending oauth request for client_id: 0
08-20 22:43:19.047  8941  8966 I chromium: [8941:8966:INFO:chromium_http_connection.cc(434)] Creating a new chromium http url loader factory
08-20 22:43:19.047  8941  8941 I chromium: [8941:8941:INFO:metrics_recorder.cc(261)] cast event: Cast.Assistant.Auth.FetchToken
08-20 22:43:19.090  8941  8941 I chromium: [8941:8941:INFO:robot_account_auth_manager.cc(519)] Got CAS response: 200
08-20 22:43:19.090  8941  8941 I chromium: [8941:8941:INFO:metrics_recorder.cc(261)] cast event: Cast.Assistant.AuthError.NOT_LINKED
08-20 22:43:19.090  8941  8941 I chromium: [8941:8941:INFO:robot_account_auth_manager.cc(747)] Current error: NOT_LINKED, new error: NOT_LINKED
08-20 22:43:21.703  3453  8298 D NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 277.777778, AvgFrameRate = 277.665218 
08-20 22:43:23.317  3335  4391 E         : hdcp_generate_nonce: nonce generation failure
08-20 22:43:23.317  3335  4391 E         : hdcp_status: hdcp_generate_nonce for version failed
08-20 22:43:26.612  3453  8298 D NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 277.777778, AvgFrameRate = 277.665904 
08-20 22:43:28.322  3335  4391 D         : signalling poll failure
08-20 22:43:28.322  3335  4391 I         : SecureHdcp_PollFailure
08-20 22:43:28.322  3335  4391 E         : hdcp_status: readstatus failed
08-20 22:43:31.509  3453  8298 D NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 277.777778, AvgFrameRate = 277.666582 
08-20 22:43:33.326  3335  4391 E         : hdcp_generate_nonce: nonce generation failure
08-20 22:43:33.326  3335  4391 E         : hdcp_status: hdcp_generate_nonce for version failed
08-20 22:43:35.194  3453  3453 E OMXNodeInstance: !!! Observer died. Quickly, do something, ... anything...
08-20 22:43:35.195  3453  3534 E OMXNodeInstance: !!! Observer died. Quickly, do something, ... anything...
08-20 22:43:35.318  3453  8300 D NvOsDebugPrintf: NVMEDIA: NVMEDIAFrameStatusReporting: 1839: Closing NVMEDIA Frame Status Thread -------------
08-20 22:43:35.319  3453  8301 D NvOsDebugPrintf: NVMEDIA: NVMEDIAVPRFloorSizeSettingThread: 1658: Closing NVMEDIAVPRFloorSizeSettingThread -------------
08-20 22:43:35.319  3453  8299 D NvOsDebugPrintf: NVMEDIA: NVMEDIAFrameDelivery: 1694: Closing NVMEDIA Frame Delivery Thread -------------
08-20 22:43:35.320  3453  8302 D NvOsDebugPrintf: NVMEDIA: DeinterlaceThread: 860: Closing Deinterlace Thread 
08-20 22:43:35.323  3453  8290 D NvOsDebugPrintf: NVMEDIA: NvMMLiteTVMRDecBlockClose: 3386: Done 
08-20 22:43:35.390  3711  3711 W Looper  : Drained
08-20 22:43:36.361  3711  3735 I system_server: Background concurrent copying GC freed 74755(9MB) AllocSpace objects, 0(0B) LOS objects, 42% free, 12MB/22MB, paused 213us total 175.287ms

 

Share this post


Link to post
Share on other sites
cayars

What else do you have running on this device?

Is this the Shield Tube or Pro version?

Share this post


Link to post
Share on other sites
FliegenderMaulwurf

This is the regular (not pro) shield 2017 version.

I don't think I have anything else running on this device.

Share this post


Link to post
Share on other sites
speechles
08-20 22:43:00.216  3349  3349 E lowmemorykiller: Error opening /dev/memcg/apps/uid_10084/pid_19997/memory.swappiness; errno=2
08-20 22:43:00.292  3711  3711 W Looper  : Slow dispatch took 138ms main h=android.app.ActivityThread$H c=android.app.-$$Lambda$LoadedApk$ReceiverDispatcher$Args$_BumDX2UKsnxLVrE6UJsJZkotuA@d0ceedf m=0
08-20 22:43:00.408  3349  3349 I chatty  : uid=0(root) /system/bin/lmkd identical 3 lines
08-20 22:43:00.412  3349  3349 E lowmemorykiller: Error opening /dev/memcg/apps/uid_10084/pid_19997/memory.swappiness; errno=2

 

The Android low memory killer daemon (lmkd) process monitors the memory state of a running Android system and reacts to high memory pressure by killing the least essential processes to keep system performing at acceptable levels.

The least essential in this case is ffmpeg. How much RAM is on that device?

Share this post


Link to post
Share on other sites
FliegenderMaulwurf

The device has 3 GB RAM.

I've monitored CPU and RAM usage while transcoding and ffmpeg's RAM usage is constantly increasing while transcoding. It is using 46.6% of RAM before it's being killed.

 

cpu-ram-usage.txt

Share this post


Link to post
Share on other sites
Luke

Are you still running into this?

Share this post


Link to post
Share on other sites
FliegenderMaulwurf

Yes, unfortunately.

Share this post


Link to post
Share on other sites
Luke
On 8/18/2020 at 6:49 PM, FliegenderMaulwurf said:

Yes, I just tried it in chrome, but the stream also stopps.

Can we look at a log example from Chrome? Thanks.

Share this post


Link to post
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now

×
×
  • Create New...