The wrong subtitle is sometimes displayed when "Seek Selection start" is used with the video paused

[sbraz]

Hi,
I have a video for which subtitles start points match frame timecodes exactly.

I have set context_length = 0 and I'm using Seek Selection start with the video paused and I noticed that:

• seeking always works for the video, the right frame is displayed
• however, sometimes the wrong subtitle is displayed (it's still the one from the previous seek)
• if I run Seek Selection start once more, the right subtitle is displayed

I don't really know how to reproduce this reliably: if I try to repeatedly seek to one subtitle, then to the previous one, it never fails. However, it happens when I keep seeking to the start of different subtitles sequentially (sub number 1, then number 2, number 3, etc.). Unpausing the video makes the right sub appear.

As a workaround, I now press Ctrl+up twice every time to make sure I get the right subtitle to appear.

I am running gaupol 1.9 and gstreamer 1.16.2 on Gentoo. I haven't yet tried to reproduce on another distro.

[sbraz]

For what it's worth, I tried a very dumb change to attempt to solve the problem and it doesn't work, even with a delay:

diff --git a/gaupol/agents/video.py b/gaupol/agents/video.py
index cd737197..6ce3af80 100644
--- a/gaupol/agents/video.py
+++ b/gaupol/agents/video.py
@@ -309,11 +309,16 @@ class VideoAgent(aeidon.Delegate):
     @aeidon.deco.export
     def _on_seek_selection_start_activate(self, *args):
         """Seek to the start of selection."""
-        page = self.get_current_page()
-        rows = page.view.get_selected_rows()
-        pos = page.project.subtitles[rows[0]].start_seconds
-        offset = gaupol.conf.video_player.context_length
-        self.player.seek(max(pos - offset, 0))
+        for i in range(2):
+            import time
+            if i == 1:
+                time.sleep(0.5)
+            print("seeking", i)
+            page = self.get_current_page()
+            rows = page.view.get_selected_rows()
+            pos = page.project.subtitles[rows[0]].start_seconds
+            offset = gaupol.conf.video_player.context_length
+            self.player.seek(max(pos - offset, 0))
 
     def _on_seekbar_change_value(self, seekbar, scroll, value, data=None):
         """Seek to specified position in video."""

[sbraz]

I have also tried seeking 100 ms later and the problem is still present:

diff --git a/gaupol/agents/video.py b/gaupol/agents/video.py
index cd737197..aa46d829 100644
--- a/gaupol/agents/video.py
+++ b/gaupol/agents/video.py
@@ -313,6 +313,7 @@ class VideoAgent(aeidon.Delegate):
         rows = page.view.get_selected_rows()
         pos = page.project.subtitles[rows[0]].start_seconds
         offset = gaupol.conf.video_player.context_length
+        offset = -0.1
         self.player.seek(max(pos - offset, 0))
 
     def _on_seekbar_change_value(self, seekbar, scroll, value, data=None):

[otsaloma]

I would suggest adding debug prints to VideoAgent._on_player_update_subtitle and start Gaupol from the terminal, so that when you do run into this, you could check what's happening. That function should be called every 10 ms, so it's not dependent on a single event-based trigger. My best guess is that either the code execution goes into one of the special cases in VideoAgent._on_player_update_subtitle causing the update to not happen, or then it's an issue with the GStreamer textoverlay not responding, which would be more difficult for us to fix.

[sbraz]

I added this:

diff --git a/gaupol/agents/video.py b/gaupol/agents/video.py
index cd737197..dedb4b4f 100644
--- a/gaupol/agents/video.py
+++ b/gaupol/agents/video.py
@@ -240,14 +240,18 @@ class VideoAgent(aeidon.Delegate):
         if not self.player.ready:
             return True # to be called again.
         pos = self.player.get_position(aeidon.modes.SECONDS)
+        print(f"pos={pos}")
         if pos is None:
             return True # to be called again.
         subtitles = list(filter(lambda x: x[0] <= pos <= x[1], self._cache))
         if subtitles:
             text = subtitles[-1][2]
+            print("subtitles found", text)
             if text != self.player.subtitle_text_raw:
+                print("subtitles need to be updated")
                 self.player.subtitle_text = text
         else:
+            print("no subtitles found")
             if self.player.subtitle_text:
                 self.player.subtitle_text = ""
         return True # to be called again.

I can see the value of text is correct, the subtitles need to be updated line is printed once. Is there any way to force a refresh to the overlay?

I'm also going to remove the if text != self.player.subtitle_text_raw: line to force the text to update every 10 ms even if it's not very good performance-wise.

[sbraz]

I tried updating self.player.subtitle_text at each call but sadly it doesn't work:

diff --git a/gaupol/agents/video.py b/gaupol/agents/video.py
index cd737197..ba6d3ae7 100644
--- a/gaupol/agents/video.py
+++ b/gaupol/agents/video.py
@@ -245,8 +245,8 @@ class VideoAgent(aeidon.Delegate):
         subtitles = list(filter(lambda x: x[0] <= pos <= x[1], self._cache))
         if subtitles:
             text = subtitles[-1][2]
-            if text != self.player.subtitle_text_raw:
-                self.player.subtitle_text = text
+            print("updating text")
+            self.player.subtitle_text = text
         else:
             if self.player.subtitle_text:
                 self.player.subtitle_text = ""

[otsaloma]

Is there any way to force a refresh to the overlay?

The textoverlay plugin doesn't really have much of an API, just a "text" property, so maybe some more general GStreamer thing is needed. Maybe try something like seeking one frame forwards after changing the text? There might also be something in Playbin or GstPipeline to try, but looking at the API documentation, I don't see anything obvious.

[sbraz]

I don't even need to actually seek to a different frame, seeking to the same position after changing the text fixes the problem:

diff --git a/gaupol/agents/video.py b/gaupol/agents/video.py
index cd737197..642a4962 100644
--- a/gaupol/agents/video.py
+++ b/gaupol/agents/video.py
@@ -247,6 +247,7 @@ class VideoAgent(aeidon.Delegate):
             text = subtitles[-1][2]
             if text != self.player.subtitle_text_raw:
                 self.player.subtitle_text = text
+                self.player.seek(pos)
         else:
             if self.player.subtitle_text:
                 self.player.subtitle_text = ""

I have performed a few tests:

• It seems to happen with MPEG2, Xvid and h264 SD videos
• I can't seem to reproduce with HD videos
• I think the problem is only present when the subtitle starts on a video frame timecode but I'm not 100% sure

My supposition is that seek should be called after the overlay is updated. At the moment, you seek first and update the overlay later. However, seeking actually takes time and seek returns immediately, resulting in the overlay being updated before seeking is actually done.
Maybe there is a way to check whether the seek has completed? I'm afraid my patch will cause the seek to happen twice, resulting in degraded performance.

I'm attaching a test video and subtitle that you can use to reproduce the problem and test the fix.
test_seek.zip

To reproduce:

1. set context_length = 0
2. open the attached subtitle and load the video
3. pause the video
4. press ctrl+up
5. press down
6. repeat steps 4 and 5 until the text no longer matches

I can also see the problem on Archlinux with gaupol 1.9 and gstreamer 1.18.2.

[sbraz]

Running with GST_DEBUG=4:

• for quickly decoding videos, all GST_EVENTs happen before self._text_overlay.props.text is changed here → the overlay is not updated.
• for videos that need a bit more time to be decoded, I can see one GST_EVENT after self._text_overlay.props.text is set → the overlay is correctly updated.

[otsaloma]

Thanks, this confirms that it's an update issue in GStreamer, but hopefully as an actual fix we can find something better than the seek. I'll test this soon, when I have the time.

Maybe there is a way to check whether the seek has completed?

There is the pipeline state. It's currently just used to distinguish between play/pause, but if I remember correctly, the state data that comes from GStreamer is very detailed.

https://github.com/otsaloma/gaupol/blob/master/gaupol/player.py#L267

[sbraz]

There is the pipeline state. It's currently just used to distinguish between play/pause, but if I remember correctly, the state data that comes from GStreamer is very detailed.

Sadly I didn't see much of interest to get from this:

diff --git a/gaupol/player.py b/gaupol/player.py
index b9517fd2..f163c011 100644
--- a/gaupol/player.py
+++ b/gaupol/player.py
@@ -267,6 +267,7 @@ class VideoPlayer(aeidon.Observable):
     def _on_bus_message_state_changed(self, bus, message):
         """Emit signal if state changed in a relevant manner."""
         old, new, pending = message.parse_state_changed()
+        print(old, new, pending)
         states = (Gst.State.NULL, Gst.State.PAUSED, Gst.State.PLAYING)
         if not new in states: return
         if new == self._prev_state: return

All I get is this:

<enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State>
<enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State>
<enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State>
<enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State>
<enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State>
<enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_VOID_PENDING of type Gst.State>
<enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_VOID_PENDING of type Gst.State>
<enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_VOID_PENDING of type Gst.State>
<enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_VOID_PENDING of type Gst.State>
<enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_PAUSED of type Gst.State> <enum GST_STATE_VOID_PENDING of type Gst.State>

[otsaloma]

Maybe there is a way to check whether the seek has completed?

I found this now, it was the async-done message. It was not the state that was detailed, but the messages and you need to subscribe to them one by one. That did not help though.

I tried a bunch of stuff, but didn't find anything better than the seek. It feels a bit silly, but I don't notice any slow-down or glitches. Zero seek with a slightly outdated position is on my computer about a 0.2 ms jump back, but that's less than a frame and probably not noticeable.

I'd move the seek to Player, but otherwise the same. If this causes some issues, it's possible to later make it conditional, but I wouldn't complicate this unless there's a reason to.

diff --git a/gaupol/player.py b/gaupol/player.py
index 2617c04d..e71afe07 100644
--- a/gaupol/player.py
+++ b/gaupol/player.py
@@ -395,6 +395,10 @@ class VideoPlayer(aeidon.Observable):
         text = aeidon.RE_ANY_TAG.sub("", text)
         text = GLib.markup_escape_text(text)
         self._text_overlay.props.text = text
+        # Do a zero seek to force an update of the overlay.
+        # https://github.com/otsaloma/gaupol/issues/181
+        with aeidon.util.silent(Exception, tb=True):
+            self.seek_relative(0)
 
     @property
     def volume(self):

Shall we go with this?

[sbraz]

Zero seek with a slightly outdated position is on my computer about a 0.2 ms jump back, but that's less than a frame and probably not noticeable.

I don't really understand that part. Where do you see that 0.2 ms difference? In the value of the timestamp?

I don't notice any slow-down or glitches.

I tried doing it on a few HD videos for which seeking takes some time and I couldn't really check whether it was taking longer than just one seek. But as you said, it can probably be made conditional later if necessary.

Shall we go with this?

Sure :)

[otsaloma]

I don't really understand that part. Where do you see that 0.2 ms difference? In the value of the timestamp?

    def seek_relative(self, offset):
        """Seek to `offset` relative to current position."""
        self._ensure_default_segment()
        pos = self.get_position(aeidon.modes.SECONDS)
        duration = self.get_duration(aeidon.modes.SECONDS)
        if pos is None or duration is None: return
        pos = pos + self.calc.to_seconds(offset)
        pos = max(0, min(pos, duration))
        pos = pos * Gst.SECOND
        seek_flags = Gst.SeekFlags.FLUSH | Gst.SeekFlags.ACCURATE
        self._playbin.seek_simple(Gst.Format.TIME, seek_flags, pos)

I mean if the video is playing and I add a second self.get_position call right before the last line, which does the actual seek, and compare it to the earlier call, I get that 0.2 ms difference. It's the time the video has moved onwards while the code between was being executed, i.e. at normal 1x playback speed, it's just the time it takes to execute the code. I think I could actually squeeze it a bit with a special function that avoids all those conversions, but still it won't a true zero seek.

[otsaloma]

If I make it simple, it goes down to 0.07 ms and works just the same.

        pos = self.get_position(mode=None)
        if pos is None: return
        seek_flags = Gst.SeekFlags.FLUSH | Gst.SeekFlags.ACCURATE
        self._playbin.seek_simple(Gst.Format.TIME, seek_flags, pos)

[otsaloma]

There it is, thanks for debugging!