TSWriter deadlock potential fix. | Page 29

Discussion in 'Area 51 - Testing Area' started by DJBlu, December 21, 2012.

  1. doskabouter
    • Premium Supporter

    doskabouter Community Plugin Dev

    Joined:
    September 27, 2009
    Messages:
    2,836
    Likes Received:
    798
    Location:
    Nuenen
    Ratings:
    +1,167 / 1
    Home Country:
    Netherlands Netherlands
    Show System Specs
    I also had a problem about an hour ago.

    I was just watching tv when everything froze. Restarted mediaportal, but that didn't help.
    Tried various channels (not sure if they were on same card or not), nothing worked.



    Logged into tvservice, started config, and saw service was doing nothing. Tried preview of a channel and that worked ok.
    After that, another try in mediaportal (same channel as I previewed) but nothing... after a while "unable to play stream"

    Then, restarted tvservice (through the still running tvserver config), and after that, all worked again.

    Logs attached, last (failed attempt) at 21:50:21 tvservice time, and 21:49:38 client time.
    Notice the difference in time (40-50 seconds), could that be the problem?
     

    Attached Files:

    • freeze.zip
      File size:
      1.1 MB
      Uploaded:
      October 15, 2013
      Views:
      121
  2. Google AdSense Guest Advertisement



    to hide all adverts.
  3. mm1352000
    • Team MediaPortal

    mm1352000 Development Group

    Joined:
    September 1, 2008
    Messages:
    21,527
    Likes Received:
    4,738
    Ratings:
    +8,205 / 17
    Home Country:
    New Zealand New Zealand
    This looks like something totally different, related to the streaming server.
    From the SS log:
    I have no idea what any of this means. :(
     
  4. doskabouter
    • Premium Supporter

    doskabouter Community Plugin Dev

    Joined:
    September 27, 2009
    Messages:
    2,836
    Likes Received:
    798
    Location:
    Nuenen
    Ratings:
    +1,167 / 1
    Home Country:
    Netherlands Netherlands
    Show System Specs
    Well, let's hope it's a one time-issue then...

    I'll keep an aye on it
     
  5. mm1352000
    • Team MediaPortal

    mm1352000 Development Group

    Joined:
    September 1, 2008
    Messages:
    21,527
    Likes Received:
    4,738
    Ratings:
    +8,205 / 17
    Home Country:
    New Zealand New Zealand
    Hello again mcraenz

    Okay, so based on that at this stage we can't tie the problem to a specific MP or driver release. What I'm driving at is that if the problem wasn't occurring when you first got the 6984, then started at some point with the 6984 (and has continued with the 6985)... something changed to trigger this, and we need to isolate what that something is. Unfortunately your answers don't shed any light...

    @gibman
    Think I need your advice here.
    It looks like reservations are not being cleaned up properly in certain cases...

    It isn't in the manual and you're not the only person to ask:
    https://forum.team-mediaportal.com/...-screen-tv-server-config.121513/#post-1027042

    mm
     
  6. mcraenz
    • Premium Supporter

    mcraenz MP Donator

    Joined:
    July 28, 2007
    Messages:
    647
    Likes Received:
    44
    Location:
    Auckland
    Ratings:
    +47 / 0
    Home Country:
    New Zealand New Zealand
    Show System Specs
    Okey it did it again. After watching TV for a while tonight I went to SetupTV and tried to time-shift. All cards busy when choosing a specific card. All DVB-S cards (currently highest priority) skipped and tuned on DVB-T. Logs attached. Sorry they are a bit messy realised I still had a schedule for a sky channel which kept trying to start recording. Anyway it looks like the same problem and once again cannot kill TVService.exe

    Interesting to note the DVB-T card doesn't get blocked up. Maye because all EPG grabbing by this card is disabled?

    Logs attached.
     
    • Thank You! Thank You! x 1
  7. mm1352000
    • Team MediaPortal

    mm1352000 Development Group

    Joined:
    September 1, 2008
    Messages:
    21,527
    Likes Received:
    4,738
    Ratings:
    +8,205 / 17
    Home Country:
    New Zealand New Zealand
    Okay, so I think you just ruled out that plugin.

    It starts here:
    Show Spoiler
    [2013-10-16 21:40:29,729] [Log ] [DVB EPG timer] [INFO ] - dvbs: Tune:DVBS:tv:TVNZ U Freq:12483000 ONID:47 TSID:22 SID:1904 PMT:0x10B FTA:True LCN:10000 SymbolRate:22500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
    [2013-10-16 21:40:29,729] [Log ] [DVB EPG timer] [INFO ] - dvb:GetNewSubChannel:0 #0
    [2013-10-16 21:40:29,731] [Log ] [DVB EPG timer] [INFO ] - TvDvbChannel ctor new subchIndex:0
    [2013-10-16 21:40:29,731] [Log ] [DVB EPG timer] [INFO ] - card: AddTuneEvent card: 4018 / subch: 0
    [2013-10-16 21:40:29,732] [Log ] [DVB EPG timer] [INFO ] - LNB low:10750 hi:10750 switch:0
    [2013-10-16 21:40:29,732] [Log ] [DVB EPG timer] [INFO ] - dvbs:channel modulation is set to ModNotSet
    [2013-10-16 21:40:29,732] [Log ] [DVB EPG timer] [INFO ] - dvbs:channel FECRate is set to Rate3_4
    [2013-10-16 21:40:29,833] [Log ] [DVB EPG timer] [INFO ] - dvb:confused:ubmiting tunerequest Channel:U subChannel:0
    [2013-10-16 21:40:29,833] [Log ] [DVB EPG timer] [INFO ] - dvb:using existing subchannel:0
    [2013-10-16 21:40:29,833] [Log ] [DVB EPG timer] [INFO ] - dvb:confused:ubmit tunerequest size:1 new:0
    [2013-10-16 21:40:29,834] [Log ] [DVB EPG timer] [INFO ] - subch:0 OnBeforeTune
    [2013-10-16 21:40:29,835] [Log ] [DVB EPG timer] [INFO ] - dvb:confused:ubmit tunerequest calling put_TuneRequest
    [2013-10-16 21:40:29,835] [Log ] [DVB EPG timer] [INFO ] - dvb:confused:ubmit tunerequest done calling put_TuneRequest
    [2013-10-16 21:40:29,835] [Log ] [DVB EPG timer] [INFO ] - subch:0 OnAfterTune
    [2013-10-16 21:40:29,836] [Log ] [DVB EPG timer] [INFO ] - RunGraph
    [2013-10-16 21:40:29,836] [Log ] [DVB EPG timer] [INFO ] - subch:0 OnGraphStart
    [2013-10-16 21:40:29,837] [Log ] [DVB EPG timer] [INFO ] - dvb: RunGraph
    [2013-10-16 21:40:30,041] [Log ] [DVB EPG timer] [INFO ] - dvb: LockInOnSignal ok
    [2013-10-16 21:40:30,042] [Log ] [DVB EPG timer] [INFO ] - subch:0 OnGraphStarted
    [2013-10-16 21:40:30,042] [Log ] [DVB EPG timer] [INFO ] - subch:0 SetupPmtGrabber:pid 10B sid:770
    [2013-10-16 21:40:30,042] [Log ] [DVB EPG timer] [INFO ] - subch:0 set pmt grabber pmt:10B sid:770
    [2013-10-16 21:40:30,043] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: Waiting for PMT 10B
    [2013-10-16 21:40:40,043] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: Timed out waiting for PMT after 10 seconds. Increase the PMT timeout value?
    [2013-10-16 21:40:40,043] [Log ] [DVB EPG timer] [DEBUG] - Setting to 0 to search for new PMT.
    [2013-10-16 21:40:40,043] [Log ] [DVB EPG timer] [INFO ] - subch:0 SetupPmtGrabber:pid 0 sid:770
    [2013-10-16 21:40:40,043] [Log ] [DVB EPG timer] [INFO ] - subch:0 set pmt grabber pmt:0 sid:770
    [2013-10-16 21:40:40,044] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: Waiting for PMT 0
    [2013-10-16 21:40:50,044] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: Timed out waiting for PMT after 10 seconds. Increase the PMT timeout value?
    [2013-10-16 21:40:50,044] [Log ] [DVB EPG timer] [DEBUG] - Setting to 0 to search for new PMT.
    [2013-10-16 21:40:50,044] [Log ] [DVB EPG timer] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
    [2013-10-16 21:40:50,045] [Log ] [DVB EPG timer] [INFO ] - DVB subch:0 Decompose()
    [2013-10-16 21:40:50,046] [Log ] [DVB EPG timer] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
    [2013-10-16 21:40:50,047] [Log ] [DVB EPG timer] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
    [2013-10-16 21:40:50,047] [Log ] [DVB EPG timer] [INFO ] - dvb:confused:topGraph called
    [2013-10-16 21:40:50,047] [Log ] [DVB EPG timer] [INFO ] - tvcard:FreeAllSubChannels
    [2013-10-16 21:40:50,047] [Log ] [DVB EPG timer] [INFO ] - dvb:confused:topGraph


    The graph is not fully stopped, but we can see that TsWriter stops:
    So again, some upstream filter is not able to stop successfully. Here is where I think I would start to suspect TBS drivers.

    Eventually we see:
    Show Spoiler
    [2013-10-16 22:04:33,912] [Log ] [17 ] [INFO ] - Controller: epg stop
    [2013-10-16 22:04:33,912] [EPG ] [17 ] [INFO ] - EPG: grabber stopped..
    [2013-10-16 22:04:33,912] [EPG ] [17 ] [INFO ] - EpgCard: card: 4018 stop grabbing
    [2013-10-16 22:04:33,912] [EPG ] [17 ] [INFO ] - EpgGrabbing: Stop - user epg
    [2013-10-16 22:04:33,912] [Log ] [17 ] [INFO ] - user:epg remove
    [2013-10-16 22:04:42,535] [Log ] [17 ] [INFO ] - Controller: epg stop
    [2013-10-16 22:04:42,541] [Log ] [17 ] [INFO ] - Controller: epg start
    [2013-10-16 22:04:42,583] [EPG ] [17 ] [INFO ] - EPG: grabber initialized for 17 transponders..
    [2013-10-16 22:04:45,776] [Log ] [20 ] [INFO ] - Controller: StartTimeShifting TV1 1
    [2013-10-16 22:04:45,776] [Log ] [20 ] [INFO ] - Controller: epg stop
    [2013-10-16 22:04:45,777] [EPG ] [20 ] [INFO ] - EPG: grabber stopped..
    [2013-10-16 22:04:45,777] [Log ] [20 ] [INFO ] - Controller: find free card for channel TV1
    [2013-10-16 22:04:45,777] [Log ] [20 ] [INFO ] - Controller: find card for channel TV1
    [2013-10-16 22:04:45,778] [Log ] [20 ] [INFO ] - Controller: got 2 tuning details for TV1
    [2013-10-16 22:04:45,778] [Log ] [20 ] [INFO ] - Controller: channel #1 DVBT:tv:TVNZ TV ONE Freq:530000 ONID:8746 TSID:25 SID:1200 PMT:0x64 FTA:True LCN:1 BandWidth:8
    [2013-10-16 22:04:45,779] [Log ] [20 ] [INFO ] - Controller: card:8 type:RadioWebStream is disabled
    [2013-10-16 22:04:45,779] [Log ] [20 ] [INFO ] - Controller: card:7 type:Analog is disabled
    [2013-10-16 22:04:45,779] [Log ] [20 ] [INFO ] - Controller: card:4015 type:DvbS cannot tune to channel
    [2013-10-16 22:04:45,779] [Log ] [20 ] [INFO ] - Controller: card:4016 type:DvbS cannot tune to channel
    [2013-10-16 22:04:45,780] [Log ] [20 ] [INFO ] - Controller: card:4017 type:DvbS cannot tune to channel
    [2013-10-16 22:04:45,780] [Log ] [20 ] [INFO ] - Controller: card:4018 type:DvbS cannot tune to channel
    [2013-10-16 22:04:45,780] [Log ] [20 ] [INFO ] - Controller: card:6 type:DvbT can tune to channel
    [2013-10-16 22:04:45,781] [Log ] [20 ] [INFO ] - Controller: channel #2 DVBS:tv:TVNZ TV ONE Freq:12483000 ONID:47 TSID:22 SID:1035 PMT:0x10D FTA:True LCN:10000 SymbolRate:22500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
    [2013-10-16 22:04:45,781] [Log ] [20 ] [INFO ] - Controller: card:8 type:RadioWebStream is disabled
    [2013-10-16 22:04:45,781] [Log ] [20 ] [INFO ] - Controller: card:7 type:Analog is disabled
    [2013-10-16 22:04:45,782] [Log ] [20 ] [INFO ] - Controller: card:4015 type:DvbS can tune to channel
    [2013-10-16 22:04:45,782] [Log ] [20 ] [INFO ] - Controller: card:4016 type:DvbS can tune to channel
    [2013-10-16 22:04:45,783] [Log ] [20 ] [INFO ] - Controller: card:4017 type:DvbS can tune to channel
    [2013-10-16 22:04:45,783] [Log ] [20 ] [INFO ] - Controller: card:4018 type:DvbS can tune to channel
    [2013-10-16 22:04:45,784] [Log ] [20 ] [INFO ] - Controller: card:6 type:DvbT cannot tune to channel
    [2013-10-16 22:04:45,784] [Log ] [20 ] [INFO ] - Controller: found 5 card(s) for channel
    [2013-10-16 22:04:45,784] [Log ] [20 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 6 msec
    [2013-10-16 22:04:45,784] [Log ] [20 ] [INFO ] - Controller: found 5 free card(s)
    [2013-10-16 22:04:45,785] [Log ] [20 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 7 msec
    [2013-10-16 22:04:45,785] [Log ] [20 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=1639, tuningdetails=DVBS:tv:TVNZ TV ONE Freq:12483000 ONID:47 TSID:22 SID:1035 PMT:0x10D FTA:True LCN:10000 SymbolRate:22500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
    [2013-10-16 22:04:45,786] [Log ] [20 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=1640, tuningdetails=DVBS:tv:TVNZ TV ONE Freq:12483000 ONID:47 TSID:22 SID:1035 PMT:0x10D FTA:True LCN:10000 SymbolRate:22500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
    [2013-10-16 22:04:45,786] [Log ] [20 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=1641, tuningdetails=DVBS:tv:TVNZ TV ONE Freq:12483000 ONID:47 TSID:22 SID:1035 PMT:0x10D FTA:True LCN:10000 SymbolRate:22500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
    [2013-10-16 22:04:45,786] [Log ] [20 ] [DEBUG] - CardReservationBase.HasUserHigherPriorityThanBlockingUser: True - user 'setuptv-1--1' with prio=2 vs blocking user 'epg' with prio=1
    [2013-10-16 22:04:45,787] [Log ] [20 ] [INFO ] - card: WaitForCancelledTuneToFinish card: 4018 / subch: 0


    At the end you can see the fact that the graph failed to stop for tuner 4018 is blocking the other 3 tuners from being used.

    I'm sorry but I'm not really able to explain what is going with any more certainty. It looks like TV Server is behaving as intended, but unusual failure conditions related to your TBS tuners are causing TV Server to also be unreliable.

    At this point I would recommend to fix any outdated tuning details, including U and PRIME and re-introduce the plugin.
     
  8. gibman
    • Premium Supporter

    gibman Retired Team Member

    Joined:
    October 4, 2006
    Messages:
    2,998
    Likes Received:
    1,321
    Occupation:
    Developer
    Location:
    Aarhus
    Ratings:
    +1,372 / 0
    Home Country:
    Denmark Denmark
    Bad drivers can cause all kinds of situations where any graph related operation (stop/start/pause) blocks indefinitely.

    What this means is that the card reservation ticket is never released.
    So when the next channel is tuned, which requires this specific card, then you will see this card reservation error in the log.
    It should atleast give you the card reservation ticket ID that is blocking, so you can use this ID to back-trace your logs.

    Did you try stress testing the card using the stress test tool in setupTV ?
    You could try stress test tool on different driver revisions, keeping track of the stress test stats on each run.

    /gibman
     
    • Like Like x 2
  9. mm1352000
    • Team MediaPortal

    mm1352000 Development Group

    Joined:
    September 1, 2008
    Messages:
    21,527
    Likes Received:
    4,738
    Ratings:
    +8,205 / 17
    Home Country:
    New Zealand New Zealand
    This advice is definitely right for the MediaPortalLogs_16_10_13__22_14.zip logs.

    However, it seems something different is happening in the earlier logs (MediaPortalLogs_15_10_13__23_38.zip) when the stress test was done. There I am seeing that cancelled tune requests from the stress test seem to be creating failed reservations.
     
  10. mcraenz
    • Premium Supporter

    mcraenz MP Donator

    Joined:
    July 28, 2007
    Messages:
    647
    Likes Received:
    44
    Location:
    Auckland
    Ratings:
    +47 / 0
    Home Country:
    New Zealand New Zealand
    Show System Specs
    Thanks for all the help and advice guys. I've deleted the defunct channels and done a re-scan. I'll report back.
     
  11. Owlsroost
    • Team MediaPortal

    Owlsroost Development Group

    Joined:
    October 28, 2008
    Messages:
    5,537
    Likes Received:
    2,829
    Location:
    Cambridge
    Ratings:
    +4,131 / 1
    Home Country:
    United Kingdom United Kingdom
    Show System Specs
    So - we are going to have to decide soon to include (or not) the current version of the fixes into MP 1.6.0 pre-release - my feeling is that it's OK (no regressions) and a considerable improvement over the old code i.e. I think we should include it.

    Comments/thoughts please ?
     
    • Agree Agree x 1
Loading...

Users Viewing Thread (Users: 0, Guests: 0)

  1. This site uses cookies to help personalise content, tailor your experience and to keep you logged in if you register.
    By continuing to use this site, you are consenting to our use of cookies.
    Dismiss Notice
  • About The Project

    The vision of the MediaPortal project is to create a free open source media centre application, which supports all advanced media centre functions, and is accessible to all Windows users.

    In reaching this goal we are working every day to make sure our software is one of the best.

             

  • Support MediaPortal!

    The team works very hard to make sure the community is running the best HTPC-software. We give away MediaPortal for free but hosting and software is not for us.

    Care to support our work with a few bucks? We'd really appreciate it!