U4 Timeshift Very Buggy

[Pat]

That current position shown in the timeshift progress bar for Jeopardy! looks wrong to me; I think it's saying the current position is 65m:36s behind the real time/end of event of 59m:58s.
You've stated it's intermittent - perhaps you're occasionally receiving bum EIT Now/Next sequences from the broadcaster in your region.

That is exactly the point, the current position is all messed up.

It still seems to know when the event starts and ends, otherwise the timeshift wouldn't be divided into events. it's just that the playback position doesn't move back when I skip back to a previous event.

Even if the data from the broadcaster is somehow messed up, you would think it would be quite simple to put some validation in the beyonwiz system to ensure the play position can never be outside the progress bar.

Where can I go next to diagnose/resolve this?

[MrQuade]

Where can I go next to diagnose/resolve this?

Right here.

If you can provide some easy steps to reproduce the problem on demand, or pin down exactly what causes this (we are speculating that we are seeing bad EIT data at this stage), then one of the devs can then reproduce the bug at their end and fix it.

It might help to know what broadcast area you are in. Some areas are better with their EIT info than others.

[Grumpy_Geoff]

It still seems to know when the event starts and ends, otherwise the timeshift wouldn't be divided into events. it's just that the playback position doesn't move back when I skip back to a previous event.

I just did a quick check of Jeopardy! EPG events in Perth, and one was 27 mins and the rest were of 25 mins duration. That 59m:58s duration you showed is a suspect event to me.

Those 6m:58s seekbar durations are also very suspect too.

Even if the data from the broadcaster is somehow messed up, you would think it would be quite simple to put some validation in the beyonwiz system to ensure the play position can never be outside the progress bar.

I wouldn't know.
Yesterday whilst checking timeshifting to see if I could see any issues, I had 11 program events in the timeshift buffer. I could move between the different buffer segments using PREV and NEXT. I could skip within a segment. I could bring up the seekbar and reposition the viewing within a segment.
It all worked as expected. Just as it's stated on the tin. I know that's not what you see.
Today I had even more and had no issues (it's easy when you park it on ABC-for-squids!).

Where can I go next to diagnose/resolve this?

Perhaps turn on debug logging.

[MrQuade]

Another thing to check. Has Pat changed any of the settings relating to "Use EIT for Now/Next". Not sure what interaction if any, that would have.

And I think we are assuming that no IceTV is in use here?

[Grumpy_Geoff]

The issue seems to be intermittent. The last two nights it seemed to be working fine, but tonight it is broken again.

Is the issue only evident with SBS?

[Pat]

Another thing to check. Has Pat changed any of the settings relating to "Use EIT for Now/Next". Not sure what interaction if any, that would have.

And I think we are assuming that no IceTV is in use here?

I AM using IceTV.

No, I haven't changed any EIT Now/Next setting.

Is the issue only evident with SBS?

I don't believe so, but I'll try to keep some notes.

Perhaps turn on debug logging.

I'll try.

It might help to know what broadcast area you are in. Some areas are better with their EIT info than others.

Burnie TAS.

[Pat]

I did some testing on channels.

Last night ABC Kids and then ABC Me seemed to work ok.

Switched to SBS Viceland and it had the issue (same as Jeopardy / 8 out of 10 previously).

Switched to NITV and it was ok.

This morning I had it on 9GO and it had the issue. Attached is the log file from just after this.

(PS I switched to the other skin but it has had no effect)

[prl]

Another thing to check. Has Pat changed any of the settings relating to "Use EIT for Now/Next". Not sure what interaction if any, that would have.

And I think we are assuming that no IceTV is in use here?

I AM using IceTV.

No, I haven't changed any EIT Now/Next setting.

Neither should affect the division of the timeshift buffer into programs, nor the placement of the "start/end" markings in recordings.

They are always set by changes in the broadcast EIT Now data.

If the issue is very intermittent, the problem may be with handling of PCR (Program Clock Register) wraparound. It is 33 bits, but in units of 1/90000 sec, so it wraps around every ~95000 sec, a little more than a day (so if you want to calculate a time difference, you have to check and handle the case where, say, now < earlier_time). I recall seeing code to handle this when I was working on related stuff, though it may not be handled correctly everywhere. But if there is a bug in handling that outside the proprietary drivers, it should affect all models equally.

I presume that 90000 is the LCM of all allowable frame rates.

[Pat]

Attached is another log file.

I had 9 Life on for a few hours so there were a few events in timeshift. I so just spent the last few minutes skipping back and forth between events.

The first few events I went back to didn't play, but then I went back a few more and it did play, back even further and it didn't.

Zapping forwards and backwards through events it seemed that some would never play automatically, some would play sometimes and not other times, some would look like they weren't going to play but then a few seconds later they would start. There wasn't a single event that would play reliably every time.

I noticed a couple of times on the ones that didn't play but then a few seconds later they did, the progress bar originally showed a crazy number but then updated to the correct number. The ones that didn't play had a crazy number but never updated.

Here are some examples of the crazy numbers:

[prl]

The numbers in those screenshots of the timeshift progess bar look suspiciously like errors caused by PCR wraparound. PCR wraparound occurs every 1590min43sec.

[peteru]

I wonder if the U4 drivers are buggy and handle 33 bit quantities using 32 bit variables. I know that the T2/T3/T4 drivers use a combination of 64 bit and 32 bit variables, but when using the 32 bit quantities, the arithmetic is done on time/2 basis so that the values fit (with one bit of precision lost).

The other possibility is that the U4 drivers can not determine the current position and rather than returning zero or error, they just return random values.

To debug this, one would have to instrument the code to see what is being reported, then make some educated guesses as to whether the symptoms fit any particular scenario. Comparing what the user interface sees to what is being returned by the drivers should help with localising the source of the problem. It could be a bug in user space code, but it's more likely that the problem is driver specific.

[prl]

If it only happens within a program-length of the PCR wrap, it might be hard to find a time when the problem can be replicated.

The only other timeshift progress bars that Pat posted looked normal.

[peteru]

I wonder if he sees the issue more often because his local transmission facility does something unusual, like reset the PCR for every event, instead of having a monotonically increasing clock that is allowed to wrap naturally. While client software should be resilient to such discontinuities, when clock resets occur unnaturally often it complicates matters. If they reset the reference clock too often, it's effectively a standards non-compliant transmission.

[Pat]

So is there anything I can do to help check these things?

Do the logs give any clues as to whether the PCR event data is screwy?

I noticed there are some errors or failures in the log, could any of these be related?
{32666}<854498.050> [eDVBPESReader] ERROR reading PES (fd=71): Value too large for defined data type
{32666}<854075.594> [eDVBPESReader] ERROR reading PES (fd=73): Value too large for defined data type

{17111}<854502.915> [eDVBTSTools] getOffset something went wrong when taking samples.
{17111}<854502.913> [eDVBTSTools] getOffset something went wrong when taking samples.

{17102}<854498.143> [eDVBTSTools] getOffset diff to big, refining
{17098}<854496.073> [eDVBTSTools] getOffset diff to big, refining

{32666}<841163.034> [Dish] tuning failed
{32666}<839641.684> [Dish] tuning failed

{32666}<841157.929> [Pixmap] setPixmapNum(0) failed! defined pixmaps: []
{32666}<839641.202> [Pixmap] setPixmapNum(0) failed! defined pixmaps: []

{32666}<839670.805> [eEPGCache] event not found
{32666}<839661.919> [eEPGCache] event not found


I don't know what I'm looking at in the logs, but maybe there is something here. Sometimes the getOffset calculates diff 0 and seems to "take" a low value:

{17125}<854509.566> [eDVBTSTools] getOffset calculated diff 0 ms
{17125}<854509.566> [eDVBTSTools] getOffset aborting. Taking 940 as offset for 0
{17125}<854509.566> [eDVBChannel] ok, resolved skip (rel: 0, diff 0), now at 000003ac

{17116}<854505.649> [eDVBTSTools] getOffset calculated diff 0 ms
{17116}<854505.649> [eDVBTSTools] getOffset aborting. Taking 3760 as offset for 0
{17116}<854505.650> [eDVBChannel] ok, resolved skip (rel: 0, diff 0), now at 00000eb0

But sometimes it calculates a positive or negative value, then tries to recalculate, but takes a high value:

{17102}<854498.143> [eDVBTSTools] getOffset calculated diff 1350 ms
{17102}<854498.143> [eDVBTSTools] getOffset diff to big, refining
{17102}<854498.143> [eDVBTSTools] getOffset using: 0:287490 -> 2632:628108
{17102}<854498.143> [eDVBTSTools] getPTS PCR 1e737a412 found at 365096 pid 11c7 (47 51 c7 3e 07 10 f3 9b d2 09 7f)
{17102}<854498.143> [eDVBTSTools] takeSample adding sample 363592: pts 140022 -> pos 365096 (diff 1504 bytes)
{17102}<854498.143> [eDVBTSTools] getOffset calculated diff -288 ms
{17102}<854498.143> [eDVBTSTools] getOffset aborting. Taking 363592 as offset for 140022
{17102}<854498.143> [eDVBChannel] ok, resolved skip (rel: 1, diff 140022), now at 00058c48

{17098}<854496.073> [eDVBTSTools] getOffset calculated diff -337 ms
{17098}<854496.073> [eDVBTSTools] getOffset diff to big, refining
{17098}<854496.073> [eDVBTSTools] getOffset using: 133300:11203300 -> 615512:41949756
{17098}<854496.074> [eDVBTSTools] getPTS PCR 1dd8f7034 found at 731132 pid 11c7 (47 11 c7 36 07 10 ee c7 b8 1a 7e)
{17098}<854496.074> [eDVBTSTools] takeSample adding sample 728688: pts 169810 -> pos 731132 (diff 2444 bytes)
{17098}<854496.074> [eDVBTSTools] getOffset calculated diff 68 ms
{17098}<854496.074> [eDVBTSTools] getOffset aborting. Taking 728688 as offset for 169810
{17098}<854496.074> [eDVBChannel] ok, resolved skip (rel: 1, diff 169810), now at 000b1e70

[Pat]

If it only happens within a program-length of the PCR wrap, it might be hard to find a time when the problem can be replicated.

I wonder if he sees the issue more often because his local transmission facility does something unusual, like reset the PCR for every event, instead of having a monotonically increasing clock that is allowed to wrap naturally. While client software should be resilient to such discontinuities, when clock resets occur unnaturally often it complicates matters. If they reset the reference clock too often, it's effectively a standards non-compliant transmission.

Were either of you able to see anything in the logs I provided that substantiate your suspicions?

Is there anything else I can do to narrow this down?

What is the next step to getting this resolved?

Based on my testing, it seems to consistently be an issue on SBS Viceland. ABC Kids seems to be consistently ok. Then some channels like 9 Life seem to be inconsistent.

Thanks.

[Pat]

If the failing HDD locks up the kernel long enough while the drivers deal with error retries on the media, then there could be secondary issues, such as lost packets from the DVB drivers. This could then present as errors and discontinuities in the stream.

My advice would be to replace the faulty HDD, reflash firmware with the most recent beta available at the time and setup from scratch, without restoring settings. You may find that doing this cures all your problems.

If it does not help with the other issues, you will have increased confidence that those issues are caused by something else, such as dodgy broadcaster practices. It's always a good idea to ensure that the fault is not at your end before asking others to look into their systems.

So I replaced the HDD, and it made absolutely no difference to the timeshift issue.

I did reflash the firmware from USB and set up from scratch, but not with the Beta. Is the Beta likely to make a difference if nothing has been done specifically to address this issue?

How easy would it be to add an out-of-bounds check and start playback from the beginning of the file rather than relying on the broadcaster's event data?