[ViX_Misc] Timers starting 100 seconds late.

[ccs]

ET10K, 4xDVB-T2 tuners, channel changes from one mux to another are instant. Box always wakes up on bbc1 HD mux.

I hardly ever watch live tv, so I usually chase play recordings.

eg program with padding starts at 18:58, so I start it as soon as it appears (red) in the movie list and then pause it until all the adverts can be skipped.

I've recently noticed that some recording files appear (green dot) on time at 18:58 (say) as a zero second file, but can take a long time before the red dot appears when the recording actually starts.

This "long time" happens to be 100 seconds

Other recordings, changing from state 1 to state 2 is instant.

I've extracted this from a debug log, and I'll post a full log if/when I can spot a pattern. (Added real times are badly offset, but are helpful.)

2017-10-03 11:01:39   1240.570  [RecordTimer] activating state 1     not default mux
2017-10-03 11:03:19   1340.587  [RecordTimer] activating state 2     recording starts
2017-10-03 11:43:19   3740.572  [RecordTimer] activating state 3     ends

2017-10-03 11:04:59   1440.579  [RecordTimer] activating state 1     default mux
2017-10-03 11:06:39   1540.583  [RecordTimer] activating state 2     recording starts
2017-10-03 11:43:19   3740.986  [RecordTimer] activating state 3     ends

2017-10-03 11:34:59   3240.571  [RecordTimer] activating state 1     default mux
2017-10-03 11:36:39   3340.611  [RecordTimer] activating state 2     recording starts
2017-10-03 12:13:20   5541.571  [RecordTimer] activating state 3     ends 

2017-10-03 12:35:00   6841.571  [RecordTimer] activating state 1     default mux
2017-10-03 12:35:00   6841.602  [RecordTimer] activating state 2     recording starts
2017-10-03 13:13:20   9141.571  [RecordTimer] activating state 3     ends

2017-10-03 13:35:00  10441.571  [RecordTimer] activating state 1     default mux
2017-10-03 13:35:00  10441.586  [RecordTimer] activating state 2     recording starts
2017-10-03 14:43:20  14541.571  [RecordTimer] activating state 3     ends

This is the 1st recording in more detail.......

2017-10-03 11:01:39   1240.570  [RecordTimer] activating state 1
2017-10-03 11:01:39   1240.572  [RecordTimer] Found enough free space to record
2017-10-03 11:01:39   1240.574  [RecordTimer] Filename calculated as: '/media/hdd/movie/20171002 1825 - BBC ONE Yk&Li - Look North'
2017-10-03 11:01:39   1240.575  [Navigation] recording service: 1:0:1:104F:104F:233A:EEEE0000:0:0:0:
2017-10-03 11:01:39   1240.576  [eDVBResourceManager] allocate channel.. 104f:233a
2017-10-03 11:01:39   1240.576  [eDVBResourceManager] available channel.. 4089:233a
2017-10-03 11:01:39   1240.576  [eDVBResourceManager] allocateFrontend, score=1
2017-10-03 11:01:39   1240.576  [eDVBResourceManager] allocateFrontend, score=1
2017-10-03 11:01:39   1240.576  [eDVBResourceManager] allocateFrontend, score=1
2017-10-03 11:01:39   1240.576  [eDVBResourceManager] allocateFrontend, score=1
2017-10-03 11:01:39   1240.576  [eDVBFrontend] opening frontend 1
2017-10-03 11:01:39   1240.580  [eDVBFrontend] (1)tune
2017-10-03 11:01:39   1240.580  [eDVBFrontend] tune setting type to 2 from 0
2017-10-03 11:01:39   1240.581  [eDVBChannel] OURSTATE: tuning
2017-10-03 11:01:39   1240.581  [eDVBServicePMTHandler] allocate Channel: res 0
2017-10-03 11:01:39   1240.581  [eDVBCIInterfaces] addPMTHandler 1:0:1:104F:104F:233A:EEEE0000:0:0:0:
2017-10-03 11:01:39   1240.581  [eDVBChannel] getDemux cap=00
2017-10-03 11:01:39   1240.581  [eDVBResourceManager] allocate demux cap=00
2017-10-03 11:01:39   1240.581  [eDVBResourceManager] allocating demux adapter=0, demux=1, source=-1 fesource=1
2017-10-03 11:01:39   1240.581  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:39   1240.582  [eEPGCache] saveEventToFile epg event id d829
2017-10-03 11:01:39   1240.583  [RecordTimer] prepare ok, waiting for begin
2017-10-03 11:01:39   1240.589  [Trashcan] probing folders
2017-10-03 11:01:39   1240.590  [eDVBFrontend] startTuneTimeout 5000
2017-10-03 11:01:39   1240.590  [eDVBFrontend] setVoltage 0
2017-10-03 11:01:39   1240.592  [eDVBFrontend] setFrontend 1
2017-10-03 11:01:39   1240.592  [eDVBFrontend] setting frontend 1
2017-10-03 11:01:40   1241.381  [eDVBFrontend] (1)fe event: status 0, inversion off, m_tuning 1
2017-10-03 11:01:40   1241.393  [Trashcan] found following trashcan's: ['/media/hdd/.Trash', '/media/hdd/movie/.Trash']
2017-10-03 11:01:40   1241.393  [Trashcan] looking in trashcan /media/hdd/.Trash
2017-10-03 11:01:40   1241.423  [Trashcan] /media/hdd/.Trash: Size: 0
2017-10-03 11:01:40   1241.423  [Trashcan] /media/hdd/.Trash: Size now: 0
2017-10-03 11:01:40   1241.423  [Trashcan] looking in trashcan /media/hdd/movie/.Trash
2017-10-03 11:01:40   1241.448  [Trashcan] /media/hdd/movie/.Trash: Size: 32533649729
2017-10-03 11:01:40   1241.482  [Trashcan] /media/hdd/movie/.Trash: Size now: 32533649729
2017-10-03 11:01:40   1241.485  [Task] job Components.Task.Job name=Cleaning Trashes #tasks=1 completed with [] in None
2017-10-03 11:01:40   1241.593  [eDVBFrontend] (1)fe event: status 1f, inversion off, m_tuning 2
2017-10-03 11:01:40   1241.593  [eDVBChannel] OURSTATE: ok
2017-10-03 11:01:40   1241.593  [eDVBLocalTimerHandler] channel 0x13de898 running
2017-10-03 11:01:40   1241.593  [eDVBChannel] getDemux cap=00
2017-10-03 11:01:40   1241.593  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.593  [eDVBSectionReader] DMX_SET_FILTER pid=20
2017-10-03 11:01:40   1241.594  [eEPGCache] channel 0x13de898 running
2017-10-03 11:01:40   1241.594  [eDVBChannel] getDemux cap=00
2017-10-03 11:01:40   1241.594  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.594  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.595  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.595  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.596  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.596  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.597  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.597  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.598  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.598  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.599  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.599  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.600  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.603  [eDVBResourceManager] stop release channel timer
2017-10-03 11:01:40   1241.603  [eDVBChannel] getDemux cap=01
2017-10-03 11:01:40   1241.603  [eDVBResourceManager] allocate demux cap=01
2017-10-03 11:01:40   1241.603  [eDVBResourceManager] allocating shared demux adapter=0, demux=1, source=1
2017-10-03 11:01:40   1241.603  [eDVBServicePMTHandler] ok ... now we start!!
2017-10-03 11:01:40   1241.603  [eDVBServiceRecord] RECORD service event 5
2017-10-03 11:01:40   1241.603  [eDVBCAService] new service 1:0:1:104F:104F:233A:EEEE0000:0:0:0:
2017-10-03 11:01:40   1241.603  [eDVBCAService] add demux 1 to slot 0 service 1:0:1:104F:104F:233A:EEEE0000:0:0:0:
2017-10-03 11:01:40   1241.603  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.606  [eDVBSectionReader] DMX_SET_FILTER pid=0
2017-10-03 11:01:40   1241.606  [eDVBServiceRecord] RECORD service event 6
2017-10-03 11:01:40   1241.606  [eDVBServiceRecord] tuned..
2017-10-03 11:01:40   1241.606  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.607  [eDVBSectionReader] DMX_SET_FILTER pid=18
2017-10-03 11:01:40   1241.608  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.608  [eDVBSectionReader] DMX_SET_FILTER pid=0
2017-10-03 11:01:40   1241.609  [eEPGCache] next update in 2 sec
2017-10-03 11:01:40   1241.640  [eDVBServicePMTHandler] PATready
2017-10-03 11:01:40   1241.640  [eDVBServicePMTHandler] use pmtpid 0064 for service_id 104f
2017-10-03 11:01:40   1241.640  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.640  [eDVBSectionReader] DMX_SET_FILTER pid=100
2017-10-03 11:01:40   1241.641  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.641  [eDVBSectionReader] DMX_SET_FILTER pid=0
2017-10-03 11:01:40   1241.642  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.643  [eDVBSectionReader] DMX_SET_FILTER pid=100
2017-10-03 11:01:40   1241.644  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.644  [eDVBSectionReader] DMX_SET_FILTER pid=17
2017-10-03 11:01:40   1241.679  [eDVBLocalTimerHandler] diff is -2
2017-10-03 11:01:40   1241.679  [eDVBLocalTimerHandler] diff < 120 .. use Transponder Time
2017-10-03 11:01:40   1241.679  [eDVBLocalTimerHandler] set RTC Time
2017-10-03 11:01:40   1241.680  [eDVBLocalTimerHandler] update RTC
2017-10-03 11:01:40   1241.680  [eDVBLocalTimerHandler] time update to 18:24:39
2017-10-03 11:01:40   1241.680  [eDVBLocalTimerHandler] m_time_difference is -2
2017-10-03 11:01:40   1241.680  [eDVBLocalTimerHandler] set Linux Time
2017-10-03 11:01:40   1241.680  [eDVBChannel] getDemux cap=00
2017-10-03 11:01:40   1241.700  [eDVBServiceRecord] RECORD service event 5
2017-10-03 11:01:40   1241.701  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.701  [eDVBSectionReader] DMX_SET_FILTER pid=7270
2017-10-03 11:01:40   1241.703  [eDVBCIInterfaces] gotPMT
2017-10-03 11:01:40   1241.703  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.704  [eDVBSectionReader] DMX_SET_FILTER pid=100
2017-10-03 11:01:40   1241.705  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.706  [eDVBSectionReader] DMX_SET_FILTER pid=200
2017-10-03 11:01:40   1241.792  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.792  [eDVBSectionReader] DMX_SET_FILTER pid=500
2017-10-03 11:01:40   1241.848  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.848  [eDVBSectionReader] DMX_SET_FILTER pid=6120
2017-10-03 11:01:40   1241.891  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.891  [eDVBSectionReader] DMX_SET_FILTER pid=2700
2017-10-03 11:01:40   1241.971  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:40   1241.971  [eDVBSectionReader] DMX_SET_FILTER pid=6140
2017-10-03 11:01:41   1242.071  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:41   1242.071  [eDVBSectionReader] DMX_SET_FILTER pid=400
2017-10-03 11:01:41   1242.103  [eDVBServicePMTHandler] AITready
2017-10-03 11:01:41   1242.103  [eDVBServicePMTHandler] AIT: BBC Red Button HTML
2017-10-03 11:01:41   1242.158  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:41   1242.158  [eDVBSectionReader] DMX_SET_FILTER pid=700
2017-10-03 11:01:41   1242.172  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:41   1242.172  [eDVBSectionReader] DMX_SET_FILTER pid=6100
2017-10-03 11:01:41   1242.239  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:41   1242.239  [eDVBSectionReader] DMX_SET_FILTER pid=6110
2017-10-03 11:01:41   1242.321  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:41   1242.322  [eDVBSectionReader] DMX_SET_FILTER pid=6130
2017-10-03 11:01:41   1242.415  [eDVBServicePMTHandler] sdt update done!
2017-10-03 11:01:42   1243.484  [eDVBServiceRecord] now running: BBC News at Six (1800 seconds)
2017-10-03 11:01:42   1243.484  [eDVBDemux] open demux /dev/dvb/adapter0/demux1
2017-10-03 11:01:42   1243.484  [eDVBSectionReader] DMX_SET_FILTER pid=18
2017-10-03 11:01:42   1243.610  [eEPGCache] start caching events(1506965081)
2017-10-03 11:01:42   1243.610  [eDVBSectionReader] DMX_SET_FILTER pid=18
2017-10-03 11:01:42   1243.610  [eDVBSectionReader] DMX_SET_FILTER pid=18
2017-10-03 11:01:42   1243.611  [eDVBSectionReader] DMX_SET_FILTER pid=18
2017-10-03 11:01:49   1250.634  [eEPGCache] nownext finished(1506965088)
2017-10-03 11:02:12   1273.908  [eEPGCache] schedule finished(1506965111)
2017-10-03 11:03:19   1340.587  [RecordTimer] activating state 2
2017-10-03 11:03:19   1340.588  [RecordTimer] start recording
2017-10-03 11:03:19   1340.589  [eDVBServiceRecord] Recording to /media/hdd/movie/20171002 1825 - BBC ONE Yk&Li - Look North.ts...
2017-10-03 11:03:19   1340.590  [eDVBServiceRecord] start recording...
2017-10-03 11:03:19   1340.591  [eDVBServiceRecord] RECORD: have 1 video stream(s) (0065), and 2 audio stream(s) (0066, 006a) (0069), and the pcr pid is 0065, and the text pid is ffffffff

 

[ccs]

For what it's worth, today, the same first two recordings don't appear to have been delayed - timer info doesn't give detail in seconds, but in both cases the minute value hasn't changed.

Differences - booted from deep standby (as opposed to already switched on), and debugging switched off.

 

[birdman]

This "long time" happens to be 100 seconds

That would be this bug:

http://www.world-of-satellite.com/showthread.php?57337-Sleep-Timer-Function-on-Vix-images&p=458301&viewfull=1#post458301

fixed in latest Dev.