FliegenderMaulwurf 1 Posted August 18, 2020 Share Posted August 18, 2020 When I play a live tv channel on my web browser (with transcoding), the stream will alway stop after about 20 minutes. Logs attached. ffmpeg-transcode-f8675993-9426-4ad7-91a5-2f9bb4563755_1.txt embyserver.txt Link to comment Share on other sites More sharing options...
ebr 14912 Posted August 18, 2020 Share Posted August 18, 2020 Hi. Is your transcode location running out of space? Link to comment Share on other sites More sharing options...
FliegenderMaulwurf 1 Posted August 18, 2020 Author Share Posted August 18, 2020 The transcode location is on my external SSD with 238 GB of free space. That shouldn't be the problem. Link to comment Share on other sites More sharing options...
Luke 37062 Posted August 18, 2020 Share Posted August 18, 2020 Hi, do you have another browser to test and compare with such as Chrome? Link to comment Share on other sites More sharing options...
FliegenderMaulwurf 1 Posted August 18, 2020 Author Share Posted August 18, 2020 Yes, I just tried it in chrome, but the stream also stopps. Link to comment Share on other sites More sharing options...
Happy2Play 8281 Posted August 18, 2020 Share Posted August 18, 2020 I do not know this platform but are we sure the external drive is being used for transcode-temp? Link to comment Share on other sites More sharing options...
Carlo 4330 Posted August 18, 2020 Share Posted August 18, 2020 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? Link to comment Share on other sites More sharing options...
Carlo 4330 Posted August 19, 2020 Share Posted August 19, 2020 "/storage/emulated/0/tmp/transcoding-temp/2726C2_%d.ts" That to me looks like internal storage. @FliegenderMaulwurf How did you mount your external SSD? Link to comment Share on other sites More sharing options...
FliegenderMaulwurf 1 Posted August 20, 2020 Author Share Posted August 20, 2020 (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 August 20, 2020 by FliegenderMaulwurf Link to comment Share on other sites More sharing options...
Carlo 4330 Posted August 20, 2020 Share Posted August 20, 2020 Not sure this matters but want to ask anyway. How did you format the SSD? What format did you use? Link to comment Share on other sites More sharing options...
FliegenderMaulwurf 1 Posted August 20, 2020 Author Share Posted August 20, 2020 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. Link to comment Share on other sites More sharing options...
Carlo 4330 Posted August 20, 2020 Share Posted August 20, 2020 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? Link to comment Share on other sites More sharing options...
speechles 1917 Posted August 20, 2020 Share Posted August 20, 2020 (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 August 20, 2020 by speechles 1 Link to comment Share on other sites More sharing options...
FliegenderMaulwurf 1 Posted August 20, 2020 Author Share Posted August 20, 2020 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. ffmpeg-transcode-55db04fc-afd2-4d56-84cc-7d1fba22fc31_1.txt Link to comment Share on other sites More sharing options...
Carlo 4330 Posted August 20, 2020 Share Posted August 20, 2020 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 ? Link to comment Share on other sites More sharing options...
speechles 1917 Posted August 20, 2020 Share Posted August 20, 2020 (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 August 20, 2020 by speechles Link to comment Share on other sites More sharing options...
Carlo 4330 Posted August 20, 2020 Share Posted August 20, 2020 Thank you sir, mucho appreciated! Link to comment Share on other sites More sharing options...
FliegenderMaulwurf 1 Posted August 20, 2020 Author Share Posted August 20, 2020 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 Link to comment Share on other sites More sharing options...
Carlo 4330 Posted August 20, 2020 Share Posted August 20, 2020 What else do you have running on this device? Is this the Shield Tube or Pro version? Link to comment Share on other sites More sharing options...
FliegenderMaulwurf 1 Posted August 20, 2020 Author Share Posted August 20, 2020 This is the regular (not pro) shield 2017 version. I don't think I have anything else running on this device. Link to comment Share on other sites More sharing options...
speechles 1917 Posted August 21, 2020 Share Posted August 21, 2020 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? Link to comment Share on other sites More sharing options...
FliegenderMaulwurf 1 Posted August 21, 2020 Author Share Posted August 21, 2020 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 Link to comment Share on other sites More sharing options...
Luke 37062 Posted August 31, 2020 Share Posted August 31, 2020 Are you still running into this? Link to comment Share on other sites More sharing options...
FliegenderMaulwurf 1 Posted August 31, 2020 Author Share Posted August 31, 2020 Yes, unfortunately. Link to comment Share on other sites More sharing options...
Luke 37062 Posted September 2, 2020 Share Posted September 2, 2020 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. Link to comment Share on other sites More sharing options...
Recommended Posts
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 accountSign in
Already have an account? Sign in here.
Sign In Now