[Mut@nt] HD51 Long delay after some key presses

[wooders7]

The symptom is that when I complete certain actions (e.g. change timer, cleanup timers, reboot) there can be a long delay (30 seconds) before the screen changes to show that the action has completed.

I first noticed this when I was running OpenViX 5.2.028 with Simple_Ten_Eighty skin. Rebooting made no difference.

I upgraded to OpenViX 5.2.039. No difference.

I changed skin to Vix Night HD. No difference.

In all cases, if I navigate through the menus but make no changes or cancel out of any change then there is no delay. The moment that a change needs to be applied then the long delay is encountered.

I started to think that it might be a problem with the hard drive, which is a Seagate ST1000LM024 HN-M supplied with the HD51, but recordings are still being made correctly.

Does anyone have any idea what it might be?

 

[abu baniaz]

Your debug log may show the problem. There was another thread recently about it.

https://www.world-of-satellite.com/showthread.php?61259-Strange-delay-in-key-processing-sometimes

 

[wooders7]

Your debug log may show the problem. There was another thread recently about it.

https://www.world-of-satellite.com/showthread.php?61259-Strange-delay-in-key-processing-sometimes

Abu, thanks for your response. I had already checked the thread that you mentioned but it didn't seem relevant.

I have looked in the debug log but I have seen nothing that gives me any clue about the cause. I set a timer for a film, The Cold Light of Day, this morning (green button in EPG) and I have included a portion of the log file in case you, or anyone else, can glean something useful from it. On pressing the green button to save the timer nothing appeared to happen but I took no action and waited until the timer screen was closed and the EPG re-appeared. I didn't time how long it took before the screen changed but it seemed like a good 30 seconds.

Does each line start with the time in seconds since start up?

<140802.362> [eInputDeviceInit] 1 67 1
<140802.364> [InfoBarGenerics] KEY: 103 UP
<140802.364> [ActionMap] Keymap 'DirectionActions' -> Action = 'up'
<140802.567> [eInputDeviceInit] 0 67 1
<140802.568> [InfoBarGenerics] KEY: 103 UP
<140803.770> [eInputDeviceInit] 1 67 1
<140803.771> [InfoBarGenerics] KEY: 103 UP
<140803.772> [ActionMap] Keymap 'DirectionActions' -> Action = 'up'
<140803.975> [eInputDeviceInit] 0 67 1
<140803.976> [InfoBarGenerics] KEY: 103 UP
<140821.066> [eInputDeviceInit] 1 18f 1
<140821.069> [InfoBarGenerics] KEY: 399 GREEN
<140821.271> [eInputDeviceInit] 0 18f 1
<140821.273> [InfoBarGenerics] KEY: 399 GREEN
<140821.274> [ActionMap] Keymap 'EPGSelectActions' -> Unknown action 'timerAdd'! (Typo in keymap?)
<140821.274> [ActionMap] Keymap 'ColorActions' -> Action = 'green'
<140821.278> menu_path: Timer entry
<140821.287> [Skin] processing screen TimerEntry:
<140821.302> [GUISkin] warning, skin is missing element ok in <class 'Screens.TimerEntry.TimerEntry'>
<140821.310> [Skin] processing screen NumericalTextInputHelpDialog:
<140821.325> [GUISkin] warning, skin is missing element cancel in <class 'Screens.TimerEntry.TimerEntry'>
<140821.332> [Skin] processing screen SetupSummary:
<140823.415> [eInputDeviceInit] 1 18f 1
<140823.417> [InfoBarGenerics] KEY: 399 GREEN
<140823.418> [ActionMap] Keymap 'SetupActions' -> Action = 'save'
<140827.356> [gRC] main thread is non-idle! display spinner!
<140854.582> [eInputDeviceInit] 0 18f 1
<140854.638> [InfoBarGenerics] KEY: 399 GREEN
<140854.665> [eDVBFrontend0] opening frontend
<140854.668> [TimerSanityCheck] conflict not found!
<140854.668> [Timer] Record RecordTimerEntry(name=The Cold Light of Day, begin=Thu May  2 19:08:00 2019, serviceref=1:0:1:2404:7F9:2:11A0000:0:0:0:, justplay=False, isAutoTimer=False)
<140856.661> [gRC] main thread is non-idle! display spinner!
<140858.675> [gRC] main thread is non-idle! display spinner!
<140885.919> [Task] job Components.Task.Job name=SoftcamCheck #tasks=1 completed with [] in None
<140885.959> [eDboxLCD] setLCDBrightness 75
<140885.972> [eDboxLCD] setLCDBrightness 74
<140885.983> [eDboxLCD] setLCDBrightness 73
<140885.995> [eDboxLCD] setLCDBrightness 72
<140886.006> [eDboxLCD] setLCDBrightness 71
<140886.017> [eDboxLCD] setLCDBrightness 70
<140886.028> [eDboxLCD] setLCDBrightness 69
<140886.039> [eDboxLCD] setLCDBrightness 68
<140886.050> [eDboxLCD] setLCDBrightness 67
<140886.061> [eDboxLCD] setLCDBrightness 66
<140886.072> [eDboxLCD] setLCDBrightness 65
<140886.083> [eDboxLCD] setLCDBrightness 64
<140886.094> [eDboxLCD] setLCDBrightness 63
<140886.105> [eDboxLCD] setLCDBrightness 62
<140886.115> [eDboxLCD] setLCDBrightness 61
<140886.126> [eDboxLCD] setLCDBrightness 60
<140886.137> [eDboxLCD] setLCDBrightness 59
<140886.148> [eDboxLCD] setLCDBrightness 58
<140886.159> [eDboxLCD] setLCDBrightness 57
<140886.170> [eDboxLCD] setLCDBrightness 56
<140886.181> [eDboxLCD] setLCDBrightness 55
<140886.192> [eDboxLCD] setLCDBrightness 54
<140886.203> [eDboxLCD] setLCDBrightness 53
<140886.214> [eDboxLCD] setLCDBrightness 52
<140886.225> [eDboxLCD] setLCDBrightness 51
<140886.236> [eDboxLCD] setLCDBrightness 50
<140886.247> [eDboxLCD] setLCDBrightness 49
<140886.258> [eDboxLCD] setLCDBrightness 48
<140886.269> [eDboxLCD] setLCDBrightness 47
<140886.280> [eDboxLCD] setLCDBrightness 46
<140886.291> [eDboxLCD] setLCDBrightness 45
<140886.302> [eDboxLCD] setLCDBrightness 44
<140886.313> [eDboxLCD] setLCDBrightness 43
<140886.323> [eDboxLCD] setLCDBrightness 42
<140886.334> [eDboxLCD] setLCDBrightness 41
<140886.345> [eDboxLCD] setLCDBrightness 40
<140886.356> [eDboxLCD] setLCDBrightness 39
<140886.367> [eDboxLCD] setLCDBrightness 38
<140886.379> [eDboxLCD] setLCDBrightness 37
<140886.390> [eDboxLCD] setLCDBrightness 36
<140886.401> [eDboxLCD] setLCDBrightness 35
<140886.412> [eDboxLCD] setLCDBrightness 34
<140886.423> [eDboxLCD] setLCDBrightness 33
<140886.435> [eDboxLCD] setLCDBrightness 32
<140886.446> [eDboxLCD] setLCDBrightness 31
<140886.457> [eDboxLCD] setLCDBrightness 30
<140886.468> [eDboxLCD] setLCDBrightness 29
<140886.479> [eDboxLCD] setLCDBrightness 28
<140886.490> [eDboxLCD] setLCDBrightness 27
<140886.501> [eDboxLCD] setLCDBrightness 26
<140886.512> [eDboxLCD] setLCDBrightness 25
<140906.493> [eInputDeviceInit] 1 ae 1
<140906.495> [InfoBarGenerics] KEY: 174 EXIT
<140906.495> [ActionMap] Keymap 'OkCancelActions' -> Action = 'cancel'
<140906.524> [eDboxLCD] setLCDBrightness 30
<140906.540> [eDboxLCD] setLCDBrightness 35
<140906.552> [eDboxLCD] setLCDBrightness 40
<140906.568> [eDboxLCD] setLCDBrightness 45
<140906.578> [eDboxLCD] setLCDBrightness 50
<140906.590> [eDboxLCD] setLCDBrightness 55
<140906.601> [eDboxLCD] setLCDBrightness 60
<140906.612> [eDboxLCD] setLCDBrightness 65
<140906.623> [eDboxLCD] setLCDBrightness 70
<140906.634> [eDboxLCD] setLCDBrightness 75
<140906.645> [eDboxLCD] setLCDBrightness 76
<140906.703> [eInputDeviceInit] 0 ae 1
<140906.705> [InfoBarGenerics] KEY: 174 EXIT
<140907.319> [eInputDeviceInit] 1 ae 1
<140907.321> [InfoBarGenerics] KEY: 174 EXIT
<140907.322> [ActionMap] Keymap 'OkCancelActions' -> Action = 'cancel'
<140907.527> [eInputDeviceInit] 0 ae 1
<140907.529> [InfoBarGenerics] KEY: 174 EXIT
<140911.334> [eHdmiCEC] detected physical address change: 2600 --> 6000
<140911.334> [eHdmiCEC] send message 84 60 00 01
<140937.537> [eDboxLCD] setLCDBrightness 75
<140937.549> [eDboxLCD] setLCDBrightness 74
<140937.560> [eDboxLCD] setLCDBrightness 73
<140937.571> [eDboxLCD] setLCDBrightness 72
<140937.581> [eDboxLCD] setLCDBrightness 71
<140937.592> [eDboxLCD] setLCDBrightness 70
<140937.603> [eDboxLCD] setLCDBrightness 69
<140937.614> [eDboxLCD] setLCDBrightness 68
<140937.625> [eDboxLCD] setLCDBrightness 67
<140937.636> [eDboxLCD] setLCDBrightness 66
<140937.647> [eDboxLCD] setLCDBrightness 65
<140937.657> [eDboxLCD] setLCDBrightness 64
<140937.668> [eDboxLCD] setLCDBrightness 63
<140937.679> [eDboxLCD] setLCDBrightness 62
<140937.690> [eDboxLCD] setLCDBrightness 61
<140937.701> [eDboxLCD] setLCDBrightness 60
<140937.712> [eDboxLCD] setLCDBrightness 59
<140937.722> [eDboxLCD] setLCDBrightness 58
<140937.733> [eDboxLCD] setLCDBrightness 57
<140937.744> [eDboxLCD] setLCDBrightness 56
<140937.755> [eDboxLCD] setLCDBrightness 55
<140937.766> [eDboxLCD] setLCDBrightness 54
<140937.776> [eDboxLCD] setLCDBrightness 53
<140937.787> [eDboxLCD] setLCDBrightness 52
<140937.798> [eDboxLCD] setLCDBrightness 51
<140937.809> [eDboxLCD] setLCDBrightness 50
<140937.820> [eDboxLCD] setLCDBrightness 49
<140937.831> [eDboxLCD] setLCDBrightness 48
<140937.842> [eDboxLCD] setLCDBrightness 47
<140937.852> [eDboxLCD] setLCDBrightness 46
<140937.863> [eDboxLCD] setLCDBrightness 45
<140937.874> [eDboxLCD] setLCDBrightness 44
<140937.885> [eDboxLCD] setLCDBrightness 43
<140937.895> [eDboxLCD] setLCDBrightness 42
<140937.906> [eDboxLCD] setLCDBrightness 41
<140937.917> [eDboxLCD] setLCDBrightness 40
<140937.928> [eDboxLCD] setLCDBrightness 39
<140937.939> [eDboxLCD] setLCDBrightness 38
<140937.949> [eDboxLCD] setLCDBrightness 37
<140937.961> [eDboxLCD] setLCDBrightness 36
<140937.972> [eDboxLCD] setLCDBrightness 35
<140937.983> [eDboxLCD] setLCDBrightness 34
<140937.994> [eDboxLCD] setLCDBrightness 33
<140938.005> [eDboxLCD] setLCDBrightness 32
<140938.015> [eDboxLCD] setLCDBrightness 31
<140938.026> [eDboxLCD] setLCDBrightness 30
<140938.037> [eDboxLCD] setLCDBrightness 29
<140938.048> [eDboxLCD] setLCDBrightness 28
<140938.059> [eDboxLCD] setLCDBrightness 27
<140938.069> [eDboxLCD] setLCDBrightness 26
<140938.081> [eDboxLCD] setLCDBrightness 25
<141017.201> [eEPGCache] FS subtable (60cbdf00) version changed (28) now/next (1)
<141136.739> [eDVBDemux] open demux /dev/dvb/adapter0/demux0
<141136.739> [eDVBSectionReader] DMX_SET_FILTER pid=20
<141138.754> [eDVBLocalTimerHandler] diff is 1
<141138.754> [eDVBLocalTimerHandler] diff < 120 .. use Transponder Time
<141138.754> [eDVBLocalTimerHandler] no RTC available :(
<141138.754> [eDVBLocalTimerHandler] time update to 09:21:52
<141138.754> [eDVBLocalTimerHandler] m_time_difference is 1
<141138.754> [eDVBLocalTimerHandler] slewing Linux Time by 001 seconds
<141138.755> [eDVBChannel] getDemux cap=00
<141155.138> [eEPGCache] FS subtable (60256200) version changed (11) now/next (1)
<141187.564> [eEPGCache] FS subtable (61256200) version changed (13) now/next (1)
<141200.874> [eEPGCache] FS subtable (60288d00) version changed (27) now/next (1)
<141201.060> [eEPGCache] FS subtable (60288e00) version changed (2) now/next (1)
<141201.310> [eEPGCache] FS subtable (60289500) version changed (19) now/next (1)
<141202.242> [eEPGCache] FS subtable (60289300) version changed (14) now/next (1)
<141205.732> [eEPGCache] FS subtable (60193600) version changed (24) now/next (1)
<141214.649> [Task] job Components.Task.Job name=SoftcamCheck #tasks=1 completed with [] in None
<141574.653> [Task] job Components.Task.Job name=SoftcamCheck #tasks=1 completed with [] in None
<141713.859> [eEPGCache] FS subtable (60274c00) version changed (31) now/next (1)
<141724.613> [eEPGCache] FS subtable (60289500) version changed (20) now/next (1)
<141727.849> [eEPGCache] FS subtable (60193c00) version changed (19) now/next (1)
<141728.195> [eEPGCache] FS subtable (60193600) version changed (25) now/next (1)
<141730.195> [eEPGCache] FS subtable (61193c00) version changed (12) now/next (1)
<141734.524> [eEPGCache] FS subtable (6027ab00) version changed (27) now/next (1)
<141751.173> [eEPGCache] FS subtable (60520800) version changed (2) now/next (1)
<141783.832> [eEPGCache] FS subtable (61289600) version changed (0) now/next (1)
<141784.319> [eEPGCache] FS subtable (61289700) version changed (2) now/next (1)
<141934.657> [Task] job Components.Task.Job name=SoftcamCheck #tasks=1 completed with [] in None
<141996.868> [eEPGCache] FS subtable (6022e300) version changed (18) now/next (1)
<142036.257> [eDVBServicePlay] timeshift
<142036.258> [eDVBServicePlay] pts of eit change: 7c98a606, fixup_pts: bd1dac0, first_pts: 70c6cb46
<142036.264> [eDVBDemux] open demux /dev/dvb/adapter0/demux0
<142036.264> [eDVBSectionReader] DMX_SET_FILTER pid=18
<142037.258> [eDVBServicePlay] timeshift
<142037.259> [eDVBServicePlay] timeshift
<142037.266> [eFilePushThreadRecorder] stopping thread.
<142037.267> [eDVBRecordFileThread] waiting for aio to complete
<142037.267> [eDVBRecordFileThread] buffer usage histogram (40 buffers of 188 kB)
<142037.267> [eDVBRecordFileThread]   0:      1
<142037.267> [eDVBRecordFileThread]   1:   3300
<142037.370> [eFilePushThreadRecorder] THREAD STOP
<142037.375> [eDVBServicePlay] remove timeshift files
<142037.394> [eThread] old thread joined 0
<142037.396> [setIoPrio] best-effort level 7 ok
<142037.396> [eBackgroundFileEraser] deleting '/media/hdd/timeshift/timeshift.tymyiF.del'
<142037.396> [eBackgroundFileEraser] deleting '/media/hdd/timeshift/timeshift.tymyiF.sc.del'
<142037.404> [eDVBServicePlay] timeshift
<142037.419> [eDVBServicePlay] timeshift
<142037.419> [eDVBServicePlay] timeshift
<142037.420> [eDVBServicePlay] Start timeshift!
<142037.420> [eDVBServicePlay] timeshift recording to /media/hdd/timeshift/timeshift.ZCPBQI
<142037.426> [setIoPrio] realtime level 7 ok
<142037.426> [eFilePushThreadRecorder] THREAD START
<142037.438> [eEPGCache] saveEventToFile epg event id 4a9
<142037.438> [eEPGCache] event 04a9 not found in epgcache
<142037.438> [eDVBServicePlay] timeshift
<142037.438> [eDVBServicePlay] unpause
<142037.440> [eDVBServicePlay] timeshift
<142037.440> [eDVBServicePlay] timeshift
<142037.440> [eDVBServicePlay] timeshift
<142038.755> [eDVBDemux] open demux /dev/dvb/adapter0/demux0
<142038.755> [eDVBSectionReader] DMX_SET_FILTER pid=20
<142041.026> [eDVBLocalTimerHandler] diff is 0
<142041.027> [eDVBLocalTimerHandler] diff < 120 .. use Transponder Time
<142041.027> [eDVBLocalTimerHandler] not changed
<142041.028> [eDVBChannel] getDemux cap=00
<142046.208> [eEPGCache] FS subtable (6018ac00) version changed (20) now/next (1)
<142263.581> [NetworkTime] setting E2 time: 1556268038.2
<142294.661> [Task] job Components.Task.Job name=SoftcamCheck #tasks=1 completed with [] in None
<142509.752> [eEPGCache] FS subtable (6027b500) version changed (20) now/next (1)
<142520.812> [eEPGCache] FS subtable (6127b500) version changed (23) now/next (1)
<142554.048> [eEPGCache] FS subtable (60275600) version changed (20) now/next (1)
<142564.407> [eEPGCache] FS subtable (61275600) version changed (23) now/next (1)
<142587.901> [AutoTimer] current auto poll 2019-04-26 09:46:02
<142587.902> [AutoTimer] Auto Poll Started
<142587.904> [AutoTimer] No changes in configuration, won't parse
<142587.905> [eEPGCache] event d383 not found in epgcache
<142587.905> [eEPGCache] event 02f7 not found in epgcache
<142587.906> [eEPGCache] event 4057 not found in epgcache
<142587.907> [eEPGCache] event 16f5 not found in epgcache
<142587.911> [AutoTimer] next auto poll at 2019-04-26 10:16:02

 

[wooders7]

This is just an update for anyone experiencing similar problems.

I installed the latest image without restoring any settings and re-configured my box from scratch. The problem of delays has now gone away. I have no idea what was the cause but I am no longer suffering from it.

 

[leshay]

Hi
I updated to the latest release last night (Sunday night), couch flash with auto restore settings and I still have the delay(s) - particularly when stopping a recording. I may have to try your solution.
I did try adjusting the Storage timeout setting fromm(what I think was the default of 5min to 2hours - made no difference.

 

[Andy_Hazza]

Hi
I updated to the latest release last night (Sunday night), couch flash with auto restore settings and I still have the delay(s) - particularly when stopping a recording. I may have to try your solution.
I did try adjusting the Storage timeout setting fromm(what I think was the default of 5min to 2hours - made no difference.

Reflash latest ViX image WITHOUT any restores.


Sent from my iPhone using Tapatalk

 

[leshay]

This is just an update for anyone experiencing similar problems.

I installed the latest image without restoring any settings and re-configured my box from scratch. The problem of delays has now gone away. I have no idea what was the cause but I am no longer suffering from it.

Hi

That seems to have fixed it for me too.

 

[abu baniaz]

If possible, it would be nice to compare the settings files to see differences.

 

[ccs]

… or maybe first do an image backup, and then do a settings restore from the failing version (if you have one) and see if the problem comes back.

 

[abu baniaz]

You can extract the older backup, no need to restore. I use 7zip.

Notepad++ has a compare plugin.

 

[leshay]

Hi

That seems to have fixed it for me too.

Hi

That post was after updating to 5.2.039, and it did fix the issue - until yesterday (Thurs 09 May), when for no apparent reason, the same delays started again. I had NOT changed any settings in the meantime to account for the issue returning.

I have now updated to 5.3.040 and so far seems to have stooped the issue (only a few hours using this version so far though)

 

[twol]

Maybe check free memory - sounds like something is using up your memory

 

[leshay]

Hi

OK, so I have taken a screen shot of current memory status and will use that as a baseline to watch it.

 

[birdman]

Maybe check free memory - sounds like something is using up your memory

Unless you have swap configured (that's swap as in Linux swap) surely you'd crash if you ran out of memory?

 

[twol]

Unless you have swap configured (that's swap as in Linux swap) surely you'd crash if you ran out of memory?

Maybe the sluggishness just shows memory use as heavy or restricted ...... I don‘t know enough about linux memory handling to know if this could cause the issue but just worth a look.