Login at Kodi Home

f5snopro · 2014-06-02, 23:04

I recently started having issues where live TV will freeze up shortly after starting XBMC and then at random times afterwards. I have XBMC set to start live TV as soon as it opens and the freeze is several seconds long. I cleared my log and recreated the issue, it occurs just before you see me terminate the live stream. It seems to be related to the updating of recorded files. Is there a parameter I should change to prevent this from happening? Thanks.

ServerWMC Log

krustyreturns · (This post was last modified: 2014-06-03, 01:22 by krustyreturns.)

I see what you are talking about, but it seems to be due to a second client coming online at ip address 192.168.2.112. Its taking over 11 secs (!) to xfer the recordings list to that client, the same recordings list takes .74 sec to xfer to the host mce machine (the one watching the livetv stream on). What is the second machine?

f5snopro · 2014-06-03, 02:54

That would be my Raspberry Pi client running RaspBMC in the basement.

scarecrow420 · (This post was last modified: 2014-06-03, 08:22 by scarecrow420.)

The server only processes 1 message at a time, so that RPi "holding things up" for so long, is causing the messages from the other client to be queued. Im surprised this is the first time anyone has seen this problem, I wanted to convert the server to handle messages in parallel but it would have affected alot of stuff that was "working" so we didnt tackle it as yet

krustyreturns · (This post was last modified: 2014-06-03, 16:22 by krustyreturns.)

Just to confirm, f5snopro please verify turning the pi off solves the problem. I recall that a user with 300 recorded programs reported it took his pi about 3 sec to get the recordings, since you have over 900 recordings the 11 sec is roughly consistent.

If this is the problem, one solution to it in the near term is to not export all the recordings to the pi, you could accomplish this with designating the channels you want to have exported to this client and it will filter the recordings accordingly.

Scarecrow I wonder if the easy way to fix this is to have the stream health check run in parallel to the main server/client processing, If that whats causing the stream to get held up.

kkphilli · 2014-06-03, 17:14

This is similar to what I have been seeing in the past. I have 3 RPi's and when one RPI is watching Live TV and another RPi is powered on and loads the EPG or selects a live TV channel, the client watching TV experiences freezing and stuttering.

f5snopro · 2014-06-04, 06:16

I powered down the Pi and the issue went away. So it is indeed the issue.

krustyreturns · 2014-06-04, 06:31

Thanks for the info. Thinking about this some more, I cannot see why the pi's GetRecordings command processing is taking more than 10x longer then the host pc. That time interval is independent of the network transfer time, its just how long the server takes to prepare the recordings list. So really the fact that the pi processes slower than the pc shouldn't even figure into it, there must be a bug somewhere - or I am still thinking about this wrong. I'll have to get back to you on this, my brain hurts.

scarecrow420 · 2014-06-04, 07:20

It must be slower to send the data back on the socket to the Pi (perhaps it not being as powerful means it is slower to read/acknowledge the data)

krustyreturns · (This post was last modified: 2014-06-04, 16:25 by krustyreturns.)

That's what I thought too, but the "finished request" log happens BEFORE we send the data back to the client. Its just a measure of the amount of time the server took to do the command. If that's the case, why an order of magnitude difference? Unless I am losing my mind again, it happens.

It would be nice to get confirmation that this getrecordings command going very slow is repeatable.

krustyreturns · 2014-06-04, 17:17

@f5snopro, if you're willing, can you start the pi while a live stream is running on the server, and after that start the pi while the server is NOT running a live stream (xbmc is idle). Then post a link to this server log. Thanks.

cdan_smith · 2014-06-05, 18:14

For another point of reference, I'm seeing almost 30 seconds to transfer the recordings list - ~ 600 recordings. Also get the freeze on live TV when the server is processing a request from a second client. Client machines are net top boxes (Acer AspireRevo) with Intel Atom processors running OpenELEC . Not sure how that stacks up against a Pi. Everything connected via ethernet thru 1Gb switches. Log file snips:

014/06/04 15:42:12.652 ServerWMC started at 6/4/2014 3:42:12 PM
2014/06/04 15:42:12.652 Assembly version: 1.0.0.29, build: 1135
2014/06/04 15:42:12.652 Config file version: 63
2014/06/04 15:42:12.652 Click-once deployment: False
2014/06/04 15:42:12.652 Server MachineName: DELLHOME2-PC
2014/06/04 15:42:12.652 OS: Windows 7 Service Pack 1 64-bit
2014/06/04 15:42:12.652 OS Version: 6.1.7601.65536
2014/06/04 15:42:19.345 Processor: Intel® Pentium® D CPU 3.40GHz
2014/06/04 15:42:19.407 Graphics: NVIDIA Quadro NVS 290 (Microsoft Corporation - WDDM v1.1)
2014/06/04 15:42:19.407 -----------------------------------------
2014/06/04 15:42:19.407 Non-default Config Settings -------------
2014/06/04 15:42:19.423 ForcedRadioChannelRanges: System.Collections.Generic.Dictionary`2[System.Double,System.Double] >>Default: -null-
2014/06/04 15:42:19.423 isAutoStart: True >>Default: False
2014/06/04 15:42:19.423 UseCredentialsInNetworkPath: True >>Default: False
2014/06/04 15:42:19.438 -----------------------------------------
2014/06/04 15:42:24.789 MainWindow> Starting InitializeWorker
2014/06/04 15:42:26.349 RecService> Starting ------------------
2014/06/04 15:42:27.550 EPG> loading...
2014/06/04 15:42:27.613 EPG> opening store
2014/06/04 15:42:42.448 EPG> TV store opened OK
2014/06/04 15:42:42.589 EnumerateRecorders> Tuner Devices and TuningSpaces found:
2014/06/04 15:42:42.589 EnumerateRecorders> 0 Content Recorder HardwareBaseId:
2014/06/04 15:42:42.589 EnumerateRecorders> HardwareId: e37cd32a-12fb-425e-ac75-9b02e0528ac7
2014/06/04 15:42:44.289 EnumerateRecorders> count: 0 Device name: HDHomeRun Prime Tuner 131229BA-2, TuningSpace: Digital Cable
2014/06/04 15:42:44.305 EnumerateRecorders> 1 Content Recorder HardwareBaseId:
2014/06/04 15:42:44.305 EnumerateRecorders> HardwareId: 6905c7a3-8584-44e8-8c55-172b50f97634
2014/06/04 15:42:44.305 EnumerateRecorders> count: 0 Device name: HDHomeRun Prime Tuner 131229BA-0, TuningSpace: Digital Cable
2014/06/04 15:42:44.305 EnumerateRecorders> 2 Content Recorder HardwareBaseId:
2014/06/04 15:42:44.305 EnumerateRecorders> HardwareId: de8c6994-4c80-4d36-90a6-cc527799f9e8
2014/06/04 15:42:44.305 EnumerateRecorders> count: 0 Device name: HDHomeRun Prime Tuner 131229BA-1, TuningSpace: Digital Cable
2014/06/04 15:42:44.305 EnumerateRecorders> done
2014/06/04 15:42:44.336 GetLineUpsAndChannels> started
2014/06/04 15:42:56.223 GetLineUpsAndChannels> Total LineUps: 1, Total channels imported: 344
2014/06/04 15:42:56.223 GetLineUpsAndChannels> Channels found in database: 738
2014/06/04 15:42:56.223 GetLineUpsAndChannels> Ignored Channels> Blocked in WMC: 387, User hidden: 0
2014/06/04 15:42:56.223 GetLineUpsAndChannels> Strange Channels> Null space: 0, Out-of-range(ignored): 7, Radio: 0
2014/06/04 15:42:56.223 GetLineUpsAndChannels> Protected Channels> encrypted: 0, DRM: 0
2014/06/04 15:42:56.223 GetLineUpsAndChannels> Edited Channels> Callsigns: 0, Numbers: 0
2014/06/04 15:42:56.223 GetLineUpsAndChannels> Channel Groups found: 0
2014/06/04 15:42:56.223 GetLineUpsAndChannels> Ignored Channel Groups> Blocked in WMC: 0, Empty groups: 1
2014/06/04 15:42:56.223 GetLineUpsAndChannels> done
2014/06/04 15:42:56.223 EPG> loading done
2014/06/04 15:43:02.136 StartRecordingLibraryWatcher> recording library watcher started
2014/06/04 15:43:13.648 RecService> EventScheduler started
2014/06/04 15:43:13.648 RecService> tuner priming turned off
2014/06/04 15:43:13.664 LoadGenreDict> 'GenreDict.xml' loaded OK
2014/06/04 15:43:13.960 CheckChannelIcons> Channel icons processed: 247
2014/06/04 15:43:13.960 RecService> -------------(DONE)----------------
2014/06/04 15:43:13.960 HandleFolders ------------------------------------
2014/06/04 15:43:13.992 --- Share detail for 'E:\Recorded TV\':
2014/06/04 15:43:14.007 > shared with: Everyone | FullControl | ContainerInherit, ObjectInherit | None | Allow
2014/06/04 15:43:14.007 > shared with: NT AUTHORITY\SYSTEM | FullControl | ContainerInherit, ObjectInherit | None | Allow
2014/06/04 15:43:14.007 > shared with: NT AUTHORITY\SYSTEM | FullControl | ContainerInherit, ObjectInherit | None | Allow
2014/06/04 15:43:14.007 > shared with: BUILTIN\Administrators | FullControl | ContainerInherit, ObjectInherit | None | Allow
2014/06/04 15:43:14.007 > shared with: S-1-5-21-2730285908-1140797587-3538199786-1001 | FullControl | ContainerInherit, ObjectInherit | None | Allow
2014/06/04 15:43:14.007 > shared with: DellHome2-PC\DellHome2 | FullControl | ContainerInherit, ObjectInherit | None | Allow
2014/06/04 15:43:14.007 > shared with: DellHome2-PC\HomeUsers | FullControl | ContainerInherit, ObjectInherit | None | Allow
2014/06/04 15:43:14.007 > shared with: NT SERVICE\ehRecvr | DeleteSubdirectoriesAndFiles, Modify, Synchronize | ContainerInherit, ObjectInherit | None | Allow
2014/06/04 15:43:14.007 > shared with: NT SERVICE\WMPNetworkSvc | Read, Synchronize | ContainerInherit, ObjectInherit | None | Allow
2014/06/04 15:43:14.007 > shared with: S-1-5-80-2913099195-3001839937-1914692661-1563395363-459793767 | DeleteSubdirectoriesAndFiles, Modify, Synchronize | ContainerInherit, ObjectInherit | None | Allow
2014/06/04 15:43:14.007 > shared with: NT SERVICE\ehSched | DeleteSubdirectoriesAndFiles, Modify, Synchronize | ContainerInherit, ObjectInherit | None | Allow
2014/06/04 15:43:14.007 ----
2014/06/04 15:43:14.007 Local WMC 'RecTV' folder: 'E:\Recorded TV\', ShareStatus: OK
2014/06/04 15:43:14.007 Format: NTFS
2014/06/04 15:43:14.007 Stored Network 'Recorded tv' path:
2014/06/04 15:43:14.007 > Samba: smb://XBMC:****@192.168.1.7/Recorded TV
2014/06/04 15:43:14.584 > UNC: \\192.168.1.7\Recorded TV, ShareStatus: OK
2014/06/04 15:43:14.584 HandleFolders -------------(DONE)----------------
2014/06/04 15:43:21.653 SocketServer> starting up SocketServer
2014/06/04 15:43:21.653 SocketServer> permission to access sockets granted
2014/06/04 15:43:21.653 SocketServer> socket object created
2014/06/04 15:43:21.669 SocketServer> started on port: 9080
2014/06/04 15:43:21.669 Worker::Init> MaintenanceTimer created
2014/06/04 15:43:21.669 InitializeWorker> successfully started: True
2014/06/04 15:43:21.684 MaintenanceTimer> callback at 3:43 PM
2014/06/04 15:43:21.965 MaintenanceTimer> callback - complete
2014/06/04 15:43:23.634 MainWindow::Window_Loaded> not running as service, checking folder status.
2014/06/04 15:43:23.634 MainWindow::Window_Loaded> Done
2014/06/04 15:43:25.428 Client: '192.168.1.15' addon Version: 0.2.95, Client OS:
2014/06/04 15:43:25.428 Client: '192.168.1.15' running remotely: True
2014/06/04 15:43:25.475 Client: '192.168.1.15' path to Rec Folder: 'smb://XBMC:****@192.168.1.7/Recorded TV'
2014/06/04 15:43:25.506 Received client request: 192.168.1.15|GetTimers
2014/06/04 15:43:38.891 Finished request GetTimers in 13.38s
2014/06/04 15:43:38.911 Client: '192.168.1.27' addon Version: 0.2.95, Client OS:
2014/06/04 15:43:38.911 Client: '192.168.1.27' running remotely: True
2014/06/04 15:43:38.971 Client: '192.168.1.27' path to Rec Folder: 'smb://XBMC:****@192.168.1.7/Recorded TV'
2014/06/04 15:43:39.001 Received client request: 192.168.1.27|GetTimers
2014/06/04 15:43:44.931 Finished request GetTimers in 5.93s
2014/06/04 15:43:44.971 Received client request: 192.168.1.15|GetRecordings
2014/06/04 15:44:15.862 Finished request GetRecordings in 30.89s
2014/06/04 15:44:15.882 Received client request: 192.168.1.27|GetRecordings
2014/06/04 15:44:46.044 GetRecordings> Completed for client 192.168.1.27, results:
2014/06/04 15:44:46.044 GetRecordings> Transfered: RecTV folder files: 578, watched files: 0
2014/06/04 15:44:46.044 GetRecordings> Ignored: local files: 0, temp files: 0
2014/06/04 15:44:46.044 GetRecordings> Weird files: no program: 0, no channel: 0, orphaned: 0
2014/06/04 15:44:46.044 GetRecordings> Misc: content protected: 0, icons: 262, instantRec: 0, metaDataReads: 0
2014/06/04 15:44:46.044 Finished request GetRecordings in 30.16s
2014/06/04 15:44:46.074 Received client request: 192.168.1.15|GetRecordings
2014/06/04 15:45:14.222 Finished request GetRecordings in 28.15s
2014/06/04 15:46:03.084 Received client request: 192.168.1.15|GetTimers
2014/06/04 15:46:06.925 Finished request GetTimers in 3.84s
2014/06/04 15:46:07.285 Received client request: 192.168.1.15|GetRecordings
2014/06/04 15:46:36.162 Finished request GetRecordings in 28.88s
...

krustyreturns · 2014-06-05, 20:30

30 sec!!! Holy crap, I didn't know if could take that long. If I provide you a test build of serverwmc would you run it with this client so I can chase down where these delays are coming from? Let me know and I will PM you a link to the build. Thanks.

cdan_smith · 2014-06-05, 22:21

Happy to help! I'll get to it tonight (ET). Let me know what logs you need (and how to post if they're big), etc ...

cdan_smith · 2014-06-06, 02:29

OK - done. Here's the log file:

http://pastebin.com/DC9veB83

There are 2 clients - both Acer AspireRevos running OpenElec. You'll see the separate IP addresses in the log. Both exhibit the ~30 second recordings transfer