Alpha patch for fix for Bug #590: IceTV timer description issues

[prl]

Bug #591: Lookup errors in eEPGCache::lookupEventTime()

[prl]

I'll start testing the new code for both the IceTV plugin and the eEPGCache in our in-use T4 tomorrow.

Grumpy_Geoff, unfortunately this new upcoming patch won't be compatible with the patch that fixes overwriting the start/end markers in recordings. I'll be suffering with you

If the new patch for the IceTV timers proves stable, I'll make a combined patch that has both.

[Grumpy_Geoff]

Righto, thanks for the info.

[prl]

I just grabbed the opportunity to install the new alpha on the on-use T4. Proper testing starts now.

[Grumpy_Geoff]

"Are we there yet?"

[prl]

Nearly! I hope to post a patch later this afternoon.

Testing is slow because it takes several days to have a reasonable chance of getting eit or description updates in the EPG.

[Grumpy_Geoff]

Okay.
For my timers, since our power was restored after a blackout last Saturday, I've had 18 description changes on 12 occasions .

FYI, given you've previously mentioned the update time, for those changes, the 'updateDescriptions time' ranged from 254ms to 307ms. For all of the other non-updates, the times ranged from 4ms to 19ms.

[prl]

...
FYI, given you've previously mentioned the update time, for those changes, the 'updateDescriptions time' ranged from 254ms to 307ms. For all of the other non-updates, the times ranged from 4ms to 19ms.

Yes, where there is a change made in the update, the time is dominated by the time to write the changes to timers.xml, by a factor of around 8:1 in my current version. The new version will log the write and processing times as well as the total time (which is what's shown in the current version). The average times I have for the 7 cases where I have updates and the separate timings are: processing 14ms, write 112ms, total 125ms. Where no updates are made, the time will be ~14ms.

Processing time will be roughly proportional to the number of waiting timers, and write time proportional to the total number of timers, though processed timers have log entries and will take longer to write than waiting timers. I currently have a total of 85 timer entries, 35 waiting and 50 finished.

Since making my changes to the eEPGCache::lookupEventTime() code, I haven't seen any timers where the eit or description is missing. I saw a couple of them in earlier testing, so perhaps that bug is laid to rest now.

There's also an opportunity to reduce the number of writes to timers.xml for normal IceTV timer new recordings, since for each batch of timers sent from IceTV, timers.xml is written for each deleted timer and each new timer in the batch. Also, when IceTV sends an update to an existing timer, timers.xml isn't updated unless there's a new timer that follows it in the processing (timer deletions should always precede additions and updates, so deletions can't incidentally update timers.xml for updates).

The process that ensures that only one write is done for these eit/description updates should be extended to ensure that timers.xml is written no more than once for each batch of changes.

[prl]

The new version of the patch has been posted in the first post in the topic.

NB: the new patch is intended for T4 PVRs only. It may work on others, but it may fail in ways unrelated to the fix. The install/uninstall instructions have changed. The names of the install/uninstall scripts have changed to make it possible to use File Commander to do the install & uninstall.

This patch is no longer compatible with the fix to Patch for #520: Start / End bookmarks missing on recording. You can have this patch installed, or the #520 patch installed, but not both. After some more testing I may make a combined patch available if the #520 fix hasn't moved to beta by then.

[Grumpy_Geoff]

It installed fine

One 'eit' and one 'description' updated
[EPGFetcher] Update descriptions time 23.0ms write 271.6ms total 294.6ms

60 waiting timers
105 finished
10 disabled

[prl]

Great! The numbers are about what I'd expect.

[prl]

This version should fix any timers that are missing eit or description that are still around from the previous version.

[Grumpy_Geoff]

It passes scheduling 'last event on service' test -
Temporary Close
14.06.2017 22:50 - 15.06.2017 05:24
ABC ME
Station Close.
waiting

[but you knew that, otherwise you'd have not released this ]


The penny just dropped on -
[EPGFetcher] updateDescriptions from EPG eit 1:0:19:564:506:1013:EEEE0000:0:0:0: 'Seven News' 21322 -> 34217
My daily repeat timer is now being updated each day with the new EPG eit value, so the timer can be edited via the EPG. Yes?

[prl]

It passes scheduling 'last event on service' test -
Temporary Close
14.06.2017 22:50 - 15.06.2017 05:24
ABC ME
Station Close.
waiting

I was more asking whether you had any timers that had missing eit & description before the yesterday's version, and if you had, whether the new version had fixed them.

[but you knew that, otherwise you'd have not released this ]

Yes. One of my tests for the new version of eEPGCache::lookupEventTime() is Python code to find, and then test various lookups on, the last event in a service's EPG.

The penny just dropped on -
[EPGFetcher] updateDescriptions from EPG eit 1:0:19:564:506:1013:EEEE0000:0:0:0: 'Seven News' 21322 -> 34217
My daily repeat timer is now being updated each day with the new EPG eit value, so the timer can be edited via the EPG. Yes?

I'm not quite sure what the question is. My new code only ever changes the eit id and the description fields of timers under IceTV control (whether set from the Beyonwiz or from the IceTV server). It won't change any other updates of, say, repeat timers, from IceTV. One consequence of the changes that I mentioned early in the original discussion about missing descriptions was that if you manually edit the description of a timer under IceTV control, the new code will overwrite those manual description changes the next time the timer is examined.

I'm still at a bit of a loss about how IceTV is supposed to interact with repeat timers.

[prl]

There is a final pair of speed optimisations for these changes that I'd like to raise. It's coded and tested, but currently disabled.

In the current code, each time there's an update from IceTV, all IceTV-controlled timers are checked against the EPG to see whether their eit id or description has changed.

The two optimisations are:

• If the IceTV update contains no EPG data, skip the checks of the timers altogether. If there's no new data, there should be nothing to do. This is a fast test on whether an existing list is empty or not.
• If the IceTV update contains no EPG data for a particular service, skip checks of timers on that service. This test requires some pre-calculation to create an set of services contained in the EPG update, but the per-timer test is fast. Again, if there's no new EPG data for a service, there should be no need to check the timers that record from that service.

I took these optimisations out because there was (and possibly remains) doubt over which conditions cause IceTV timers to be created without either an eit id or description. The optimisations will do the right thing (or at least the best possible thing) in the case where looking up a timer fails because it's the last event in the service's EPG. When eventually there is an EPG update for the timer's service that moves its event to no longer be the last event, the fields will then be updated correctly.

However, if there are other cases where looking up the timer fails, these optimisations may delay when the eit id and description are finally set. This is one of the reasons why I'm interested in whether there are still any cases where the eit id and description aren't set n a timer, even though the timer's event data is correct and has a description.

These optimisations will not make much difference to worst-case times, because they will normally be dominated by the write time to timers.xml, but they do make a significant improvement to best-case times.

[Grumpy_Geoff]

...
I was more asking whether you had any timers that had missing eit & description before the yesterday's version, and if you had, whether the new version had fixed them.

I've now only a completed (Fargo) timer without description and eit - no waiting timers are missing those values.
There has been no log entries indicating an empty description has been updated.

The penny just dropped on -
[EPGFetcher] updateDescriptions from EPG eit 1:0:19:564:506:1013:EEEE0000:0:0:0: 'Seven News' 21322 -> 34217
My daily repeat timer is now being updated each day with the new EPG eit value, so the timer can be edited via the EPG. Yes?

I'm not quite sure what the question is. My new code only ever changes the eit id and the description fields of timers under IceTV control (whether set from the Beyonwiz or from the IceTV server). It won't change any other updates of, say, repeat timers, from IceTV. One consequence of the changes that I mentioned early in the original discussion about missing descriptions was that if you manually edit the description of a timer under IceTV control, the new code will overwrite those manual description changes the next time the timer is examined.

The repeat timer I have does have the 'ice_timer_id' attribute, but Ice knows nowt about it subsequent to its first firing. I think the new code is altering the timer's eit value when the change is detected - that was the "yes?".

[prl]

...
The repeat timer I have does have the 'ice_timer_id' attribute, but Ice knows nowt about it subsequent to its first firing. I think the new code is altering the timer's eit value when the change is detected - that was the "yes?".

The eit updating is just done on the basis of the timer having the 'ice_timer_id' attribute and there being an EPG entry that matches the midpoint of the timer.

The code doesn't know whether the IceTV server side knows about the timer or not beyond the attribute being present, and probably can't find out easily.

The test to see whether the timer should be checked for an EPG update is:

Code: Select all

        for timer in _session.nav.RecordTimer.timer_list:  # Only test active timers
            if timer.ice_timer_id and timer.service_ref.ref and not getattr(timer, "record_service", None):  # Has IceTV timer id, a service reference and isn't currently recording
            	...

[peteru]

I'd only bother with the optimisations if they do not significantly impact the legibility of the code AND are actually needed to solve performance issues. For example, if the update process is likely to induce a spinner or cause the UI to become unresponsive for seconds at a time, then clearly optimisation is worthwhile. If you are looking at shaving off 250ms once or twice a day, during IceTV daily updates, I'd probably not bother.

I'd suggest starting with the simplest optimisation first, collect some metrics and then decide whether anything more complicated is worth pursuing.

[prl]

I'd only bother with the optimisations if they do not significantly impact the legibility of the code AND are actually needed to solve performance issues. For example, if the update process is likely to induce a spinner or cause the UI to become unresponsive for seconds at a time, then clearly optimisation is worthwhile. If you are looking at shaving off 250ms once or twice a day, during IceTV daily updates, I'd probably not bother.

I'd suggest starting with the simplest optimisation first, collect some metrics and then decide whether anything more complicated is worth pursuing.

The optimisations are simply an early return if the EPG part of the update are empty and the test on the set of triplets in the update:

Code: Select all

        updated = False
        if not showMap:
             return updated
        triplets = set((triplet for channel_id in showMap if channel_id in self.channel_service_map for triplet in self.channel_service_map[channel_id]))
        for timer in _session.nav.RecordTimer.timer_list:
            if timer.ice_timer_id and timer.service_ref.ref and not getattr(timer, "record_service", None) and tuple((timer.service_ref.ref.getUnsignedData(i) for i in (3, 2, 1))) in triplets:

However, it doesn't help (in fact slightly slows) worst case performance, so I may drop it anyway, or just leave the early return in. The EPG update is quite frequently empty (for the default 15 min update frequency).

I'm currently collecting performance data.

[prl]

I've put a link to a new alpha patch in the first post. The ZIP file has a different name (icetvdesc1-installer.zip), but it will unpack to the same directory name as before (icetvdesc-installer).

I've removed the link to the older version.

I hope that this new version will be the last alpha for this fix. If there are no problems with this patch, I'll delete or comment out the remaining logging to the debug log and make a combined patch that also covers the fixes to recording start/end markers when chaseplay is used. After a but more testing, I'll also start submitting the changes. I'll also submit the changes to eEPGCache::lookupEventTime() upstream to OpenViX.

[Grumpy_Geoff]

It installed fine

Full EPG fetch - 2 descriptions updated:
[EPGFetcher] updateDescriptions from EPG description SBS ONE HD 'Motor Sport: Speedweek': {blah}...
[EPGFetcher] updateDescriptions from EPG description ABC HD 'Media Watch': {blah}...
[EPGFetcher] Update descriptions time 29.0ms write 242.1ms total 271.1ms

15 minutes later - no new guide events::
[EPGFetcher] Update descriptions time 0.0ms total 0.0ms

A further 15 minutes later - 2 new events:
[EPGFetcher] Update descriptions time 28.2ms total 28.2ms


Cheers,
Geoff

[prl]

Yep, that all looks good. Thanks.

[prl]

I've started testing the combined patch that does both these IceTV description fixes and the chaseplay recording start/stop mark fixes.

If no-one finds any problems with these fixes in the next couple of days, I'll post the combined patch on Friday or Saturday.

[Paul_oz53]

I've started testing the combined patch that does both these IceTV description fixes and the chaseplay recording start/stop mark fixes.

If no-one finds any problems with these fixes in the next couple of days, I'll post the combined patch on Friday or Saturday.

Have also installed the updated patch and can report no obvious problems.

I did have a random restart of the GUI days ago whilst replaying a recording. I don't think it was related to the patch. It hasn't recurred.

Showing my ignorance here but:
1. Is this combined patch the same patch as in the first post? And,
2. Where is the log file kept? And,
3. Does it need anything turned on to activate the log?

I've looked in the usual place for a log but it is empty. Since I recently reinstalled the firmware my logging settings may have changed.

Thanks, Paul

[prl]

I've started testing the combined patch that does both these IceTV description fixes and the chaseplay recording start/stop mark fixes.

If no-one finds any problems with these fixes in the next couple of days, I'll post the combined patch on Friday or Saturday.

Have also installed the updated patch and can report no obvious problems.

I did have a random restart of the GUI days ago whilst replaying a recording. I don't think it was related to the patch. It hasn't recurred.

Do you have the crash log file? I'd like to check that it was unrelated to the IceTV patch (and see what caused it anyway).

Showing my ignorance here but:
1. Is this combined patch the same patch as in the first post?

The combined patch has not yet been made available publicly. I'm testing it on my test T4 and on our in-use T4. See my highlight of the text you quoted from my post. It's still Thursday. I'm waiting to see whether there are any problems in the latest version of the fix for just this bug (#590: IceTV timer description issues).

And,
2. Where is the log file kept?

If debug logging is enabled, it defaults to /home/root/logs. It can also be configured to log to HDD (/media/hdd/logs).

And,
3. Does it need anything turned on to activate the log?

Yes. In Open Webif, tick Settings>Log settings>Enable debug log. You may also want to change Log location in the same settings screen. Then reboot.

The log files will go in the logs subdirectory of the Log location you selected.

I've looked in the usual place for a log but it is empty. Since I recently reinstalled the firmware my logging settings may have changed.
...

A USB upgrade without a restore settings will have cleared any log settings you had back to their defaults.

[Paul_oz53]

Enigma2_crash_2017-06-12_01-39-53.log

(16.85 KiB) Downloaded 83 times

... I'll post the combined patch on Friday or Saturday.

In plain sight! It was late at night - and maybe too much red...

I did have a random restart of the GUI days ago whilst replaying a recording. I don't think it was related to the patch. It hasn't recurred.

Do you have the crash log file? I'd like to check that it was unrelated to the IceTV patch (and see what caused it anyway).

Attached - I was playing some recordings from the PC at the time when the GUI restart fired off.

Enigma2_crash_2017-06-12_01-39-53.log

(16.85 KiB) Downloaded 83 times

If debug logging is enabled, it defaults to /home/root/logs. It can also be configured to log to HDD (/media/hdd/logs).

Found them - they were in /media/hdd/logs. Must have restored settings afterall. I've also attached the latest log for info.

Enigma2-2017-06-14_13-09-57.log

(1.48 MiB) Downloaded 62 times

[prl]

It doesn't look like the crash had anything to do with the IceTV changes.

It's a crash in a fairly low-level method, eMessagePump::do_recv():

Code: Select all

{541}< 48787.182> [eServiceMP3] destruct!
{541}< 48787.184> PC: 0061c76c
{541}< 48787.184>     00000000 00000001 00000000 0147aa68
{541}< 48787.184>     01114f68 00000000 ffffffff 73ad36e8
{541}< 48787.184>     73a9a7e0 0000000d 00000028 00000004
{541}< 48787.184>     7ff06800 77cda4a0 00000000 00710000
{541}< 48787.184>     00000000 014f5aa8 01197070 00000006
{541}< 48787.184>     01197078 00000001 7ff06a44 007d1dd0
{541}< 48787.184>     00714734 771e3460 7283bdc0 00000000
{541}< 48787.184>     7720c020 7ff068a0 7ff06970 0061c74c
{541}< 48787.199> Backtrace:
{541}< 48787.200> /usr/bin/enigma2(_Z17handleFatalSignaliP9siginfo_tPv) [0x470c9c]
{541}< 48787.200> /usr/bin/enigma2(_ZN17eFixedMessagePumpI4ePtrI19GstMessageContainerEE7do_recvEi) [0x61c76e]
{541}< 48787.200> /usr/bin/enigma2(_ZN9eMainloop15processOneEventEjPP7_object9ePyObject) [0x4797dc]
{541}< 48787.201> /usr/bin/enigma2(_ZN9eMainloop7iterateEjPP7_object9ePyObject) [0x479cc8]
{541}< 48787.201> /usr/bin/enigma2(_ZN9eMainloop4pollE9ePyObjectS0_) [0x479edc]
{541}< 48787.201> /usr/bin/enigma2(n/a) [0x5b3628]
{541}< 48787.201> /usr/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx) [0x7782bd44]
{541}< 48787.201> -------FATAL SIGNAL (11)

There have also been a couple of odd crashes recently where there was no obvious crash (Python or C++ stack traceback), but a " [eFixedMessagePump] Got event but queue is empty" log message just before the end of the log.

The crash signal is SIGSEGV, illegal memory reference.

[prl]

The log file shows a couple of successful timer description updates.

[Paul_oz53]

It doesn't look like the crash had anything to do with the IceTV changes.

It's a crash in a fairly low-level method, eMessagePump::do_recv():
...
There have also been a couple of odd crashes recently where there was no obvious crash (Python or C++ stack traceback), but a " [eFixedMessagePump] Got event but queue is empty" log message just before the end of the log.

The crash signal is SIGSEGV, illegal memory reference.

Obvious really ----- not! Glad one of us knows what they're doing.

If its low level then maybe a driver/hardware issue? So far, it seems random and not recurring so only a minor hickup which I will ignore for now.

Glad the timer updates are as expected. I could see the updates happened in the log but reading the timestamps was beyond my ken. Vaguely recall reading a discussion of how to convert them to human form.

Now, if we can just get accurate start/end markers in the saved recordings. But, in saying that I also understand we are prisoners of the broadcasters. ABC and SBS are usually tolerably close but the commercial stations appear to use a random number generator at times.

Paul

[prl]

...
Obvious really ----- not! Glad one of us knows what they're doing.

First used Unix in about 1978

If its low level then maybe a driver/hardware issue? So far, it seems random and not recurring so only a minor hickup which I will ignore for now.

Not that low level. It's in the main application code. The crash was in the code for a message queue. I couldn't see anything obviously wrong with it.

Glad the timer updates are as expected. I could see the updates happened in the log but reading the timestamps was beyond my ken. Vaguely recall reading a discussion of how to convert them to human form. ...

Code: Select all

{27751}< 75655.389> [EPGFetcher] updateDescriptions from EPG description TEN HD 'MasterChef Australia': '2017 - Mildura Salt Pan Challenge' -> '2017 - Team Challenge: Air'

{thread id}<seconds since boot> [name of class writing to log] message

And the message is that a timer on TEN HD for MasterChef had its description changed from "2017 - Mildura Salt Pan Challenge" to "2017 - Team Challenge: Air".

Mmmmm... Air... Mmmmm... really got the saliva running in anticipation of that. Has MasterChef gone Breatharian?

[prl]

I've put a link to a new alpha patch in the first post. The ZIP file has a different name from earlier versions (icetvdesc2-installer.zip), but it will unpack to the same directory name as before (icetvdesc-installer).

I've removed the link to the older version.

The patch now has fixes for both the IceTV description updates and for problems with start/stop marks when chaseplaying a recording.

I've also updated the IceTV plugin version number and fixed a minor bug with the handling of EPG description data that contains newlines.

This is intended to be the operational version of the code for both fixes.

I have submitted the changes to eEPGCache::lookupEventTime() upstream to both the Beyonwiz repository and OpenViX.

[Grumpy_Geoff]

It installed fine, and passed the chase-play bookmark test.
I haven't had any Ice timers sans description since your changes to eEPGCache::lookupEventTime()
Thanks.


Cheers.
Geoff

[prl]

It installed fine, and passed the chase-play bookmark test.
I haven't had any Ice timers sans description since your changes to eEPGCache::lookupEventTime()
Thanks.
...

Thanks for the update. I haven't seen any descriptionless IceTV timers since the updates to eEPGCache::lookupEventTime(), either.

I think I'll submit the changes tomorrow.

[Paul_oz53]

It installed fine, and passed the chase-play bookmark test.
I haven't had any Ice timers sans description since your changes to eEPGCache::lookupEventTime()
Thanks.


Cheers.
Geoff

+1

Appears to be performing as expected. Somewhat anticlimactic - nothing to report!

[prl]

Thanks. That's what I like to hear!

[Grumpy_Geoff]

Thanks. That's what I like to hear!

Yeah, so do we - remember the UI not starting issue in the original binary fix for 'sound loss on playback of HDMI-IN recordings'? Execute permissions were lost through Dropbox.
Those were the days when it was a tough life being an alpha-tester. The young-uns these days have it easy!

[prl]

My fixes to eEPGCache::lookupEventTime() have been merged into the Dev branch of OpenViX. The fixes to the IceTV plugin don't apply to OpenViX.

I've submitted the IceTV plugin fixes to the Beyonwiz repository.

[Grumpy_Geoff]

Okey, dokey. I've not seen any issues - still no empty timer descriptions.

Thanks,
Geoff

[Paul_oz53]

+1

[prl]

Thanks.

Are you seeing occasional "Update timer details from EPG" messages in the IceTV log? I haven't seen one in a while, but maybe there just haven't been any for my timers.

[Paul_oz53]

Are you seeing occasional "Update timer details from EPG" messages in the IceTV log?

Yes, there are two for Big Bang Theory today.

[Grumpy_Geoff]

Are you seeing occasional "Update timer details from EPG" messages in the IceTV log?

Nup. With only the last ~10 updates shown in the Ice UI log, you need to be quick to see them.
No more logging to the debug log, right?

[prl]

No more logging to the debug log, right?

Yep. That's right.

[Grumpy_Geoff]

Are you seeing occasional "Update timer details from EPG" messages in the IceTV log? ...

Yep, got one now - "Update timer details from EPG 'program name'"
I've also seen entries for EIT changes for my repeats, but I can't remember if the text is the same (I think it may have been).

Is there any need to keep my T4 in standby when not in use, or can I now go back to shutdown when not needed?

[prl]

Are you seeing occasional "Update timer details from EPG" messages in the IceTV log? ...

Yep, got one now - "Update timer details from EPG 'program name'"
I've also seen entries for EIT changes for my repeats, but I can't remember if the text is the same (I think it may have been).

Yes, I've seen all three update combinations, eit id changed without a description change, description change without an eit id change, and both changed.

Is there any need to keep my T4 in standby when not in use, or can I now go back to shutdown when not needed?

I don't think so. I've reverted our in-use T4 back to shutdown when not in use, too.