Lagging behind osc decorations

[natural-harmonia-gropius]

#5 doesn't completely fix the issue.
The position will now be updated in time, but the frame will still be frozen. Maybe we need to add debounce or lock to make sure there is no parallel execution.

[po5]

You get the same issue if you block parallel execution, by the time your seek is done, you've hovered on a different part of the timeline.
The script seeks on a secondary mpv instance without a cache, this is to be expected.

I think the can_generate variable was meant to prevent parallel seeks, but I don't know what it actually does now :^)

Should update properly once you stop moving the mouse, it'll catch up and display the correct thumbnail for your current position.
If that's not the case I'll look at it.

[natural-harmonia-gropius]

This one took me 25 seconds, sometimes it happens very soon just about 3 seconds.

Drifting.Home.2022.1080p.NF.WEB-DL.DUAL.DDP5.1.H.264-SMURF.mkv.-.mpv.2022-09-21.22-36-37_Trim.mp4

[tomasklaen]

Haven't looked into internals too much, but can't you execute seek only after the last one is done? And the queued one gets overwritten by new requests.

[natural-harmonia-gropius]

log here, looks like subprocess down.

[ 141.112][d][cplayer] Run command: seek, flags=41, args=[target="1650.940622", flags="absolute+keyframes", legacy="unused"]
[ 141.112][v][ipc_852] Client disconnected
[ 141.112][v][mkv] queuing seek to 1650.940622
[ 141.112][d][ipc_852] Exiting...
[ 141.112][v][mkv] execute seek (to 1650.940622 flags 0)
[ 141.112][v][file] stream level seek from 814731254 to 607255168
[ 141.112][v][mkv] seek done
[ 141.115][d][ffmpeg] filter: w:320 h:180 flags:'' interl:0
[ 141.115][d][ffmpeg/video] h264: Reinit context to 1920x1088, pix_fmt: yuv420p
[ 141.123][v][vd] Decoder format: 1920x1080 yuv420p auto/auto/auto/auto/auto CL=mpeg2/4/h264
[ 141.123][v][vd] Using container aspect ratio.
[ 141.123][d][ffmpeg] mpv_src_default_in: w:1920 h:1080 pixfmt:yuv420p tb:1/1000000 fr:992008/41375 sar:1/1
[ 141.128][d][ffmpeg] filter: w:1920 h:1080 fmt:yuv420p sar:1/1 -> w:320 h:180 fmt:yuv420p sar:1/1 flags:0x0
[ 141.132][d][ffmpeg] filter: w:1920 h:1080 fmt:yuv420p sar:1/1 -> w:320 h:180 fmt:yuv420p sar:1/1 flags:0x0
[ 141.136][d][ffmpeg] filter: w:1920 h:1080 fmt:yuv420p sar:1/1 -> w:320 h:180 fmt:yuv420p sar:1/1 flags:0x0
[ 141.140][d][ffmpeg] filter: w:1920 h:1080 fmt:yuv420p sar:1/1 -> w:320 h:180 fmt:yuv420p sar:1/1 flags:0x0
[ 141.141][d][ffmpeg] mpv_src_default_in: w:320 h:180 pixfmt:yuv420p tb:1/1000000 fr:992008/41375 sar:1/1
[ 141.141][d][ffmpeg] filter: w:320 h:180 -> w:320 h:180 x:0 y:0 color:0x000000FF
[ 141.141][e][ffmpeg] image2: Could not open file : C:\Users\user/AppData/Local/Temp\thumbfast.out
[ 141.141][e][encode] Writing packet failed.
[ 141.141][v][cplayer] first video frame after restart shown
[ 141.141][d][cplayer] starting video playback
[ 141.141][v][cplayer] playback restart complete @ 1649.606000, audio=eof, video=playing (paused)
[ 141.141][v][cplayer] EOF code: 6  
[ 141.141][d][vd] Uninit decoder.
[ 141.149][d][cplayer] Terminating demuxers...
[ 141.149][d][cplayer] Done terminating demuxers.
[ 141.149][v][cplayer] finished playback, something happened (reason 4)
[ 141.149][i][cplayer] 
[ 141.320][v][ipc_853] Client connected
[ 141.320][d][cplayer] Run command: seek, flags=41, args=[target="4187.751822", flags="absolute+keyframes", legacy="unused"]
[ 141.320][v][ipc_853] Client disconnected
[ 141.320][d][ipc_853] Exiting...
[ 141.324][v][ipc_854] Client connected
[ 141.324][d][cplayer] Run command: seek, flags=41, args=[target="4248.152089", flags="absolute+keyframes", legacy="unused"]
[ 141.324][v][ipc_854] Client disconnected
[ 141.324][d][ipc_854] Exiting...

[po5]

Keeping this open until it's confirmed working.

[hooke007]

Still freeze here (windows 10)
see #8 (comment)

[natural-harmonia-gropius]

EOF code 6 is PT_ERROR, // play next playlist entry (due to an error)
--keep-open=always or --loop=inf doesn't help.

the image2: Could not open file : C:\Users\user/AppData/Local/Temp\thumbfast.out is the point.
but we can do nothing here.

thumbfast/thumbfast.lua

Lines 346 to 351 in 85a737e

	-- os.rename can't replace files on windows
	if os_name == "Windows" then
	os.remove(options.thumbnail..".bgra")
	end
	-- move the file because it can get overwritten while overlay-add is reading it, and crash the player
	os.rename(options.thumbnail, options.thumbnail..".bgra")

[Zabooby]

White background of thumbnail lags when repeatedly moving on the timeline

lag.mp4

[natural-harmonia-gropius]

continue #25 (comment)

This one work's pretty unstable, much easier to reproduce this issue.
Change video-rotate to test it.
Touching these state management is very evil. Uhhhh.

[Zabooby]

Doesn't #36 fix this? I tried it and the freezing had stopped.

[natural-harmonia-gropius]

I will try it in few days. no pc right now.

The probability is greatly reduced, but not really fixed.

[Zabooby]

Yup, after playing around after the pr I noticed this too.

[po5]

Can't reproduce on latest commit.

[natural-harmonia-gropius]

With lavfi-crop, size changed, but frozen, sometimes.

[Zabooby]

For me its fixed, however when moving the mouse very fast the white background drags a bit. Doesn't happen when moving the mouse at a steady rate.

[hooke007]

Filters are nearly out of our control in this script... Any vf would probably break the thumbnail.
i.e. vf pad=21/9

[po5]

For me its fixed, however when moving the mouse very fast the white background drags a bit. Doesn't happen when moving the mouse at a steady rate.

@Zabooby Try tomasklaen/uosc#353, it shouldn't have this issue. Comment on that PR if you find anything wrong.

[Zabooby]

Sorry I'm dumb, how do I download uosc with the pull request you made?

[po5]

Pull https://github.com/po5/uosc/tree/script-thumbnails (or download as zip).

[Zabooby]

Yup its fixed now! Both frames freezing and the background drag.

[jalenzz]

@po5 Hello, I use MordenX, it still have this problem. Also this problem happen every time and I could only preview the first time, after that, the preview picture will keep and do not change

2023-01-03.16.45.39.mp4

[po5]

@jalenzz Your issue is #87, and it was fixed recently.

[po5]

I am beginning to understand the deeper reasons why thumbnails can desync.
Basics: Scripts run on an event loop, that will be called whenever the player has anything going on.
A script's blocking execution however, can take longer than one event loop. The script can send messages to other scripts without having to wait for its own event loop to finish, and those scripts can process them directly.
The script can update image and ass overlays as often as it wants within one event loop. (Note it's still bound to the video's framerate)
This is one potential source for desyncs, but also a blessing as I'll summarize later.
When the script stops being busy, all incoming events that got queued up are announced. This is when the script truly receives messages.
It's possible that when we receive a message like thumb, we are busy doing some other processing, the next event loop run is delayed, and we'll get the updated positions only after we finish whatever we were doing.
I don't know how to test for this, but I know how to test for queued up events like in memo (which means the delay was so bad we didn't finish in time for the next event loop).

--- a/thumbfast.lua
+++ b/thumbfast.lua
@@ -115,6 +115,8 @@ if options.direct_io then
     end
 end
 
+local event_loop_exhausted = false
+
 local spawned = false
 local network = false
 local disabled = false
@@ -607,6 +609,11 @@ end)
 file_timer:kill()
 
 local function thumb(time, r_x, r_y, script)
+    if event_loop_exhausted then
+        print("last", x, y)
+        print("curr", r_x, r_y)
+    end
+    event_loop_exhausted = true
     if disabled then return end
 
     time = tonumber(time)
@@ -645,6 +652,7 @@ local function clear()
 end
 
 local function watch_changes()
+    event_loop_exhausted = false
     if not dirty then return end
 
     local old_w = effective_w

I managed to trigger this and confirmed we did get updated position values we would've liked to have earlier.

[thumbfast] last 1126 866 
[thumbfast] curr 484 866

I don't know if long processing is the entirety of all desync cases, but it's certainly a factor.
I need to make a script that just draws the same overlay image at whatever position we got, with the same method for detecting event loop delays.
And if everything seems to line up all the time, we'll have to benchmark and optimize everything to fit within any event loop... or split the script into a worker for getting everything ready, and the main script that displays the thumbnail, always on time. Unless there's a way to do truly async lua processing, or we can chunk whatever heavy processing we're currently doing into smaller jobs across event loops.

The good news is that there shouldn't be desyncs the other way around, where the UI script is busy and can't catch an event loop. It's still able to run osd:update() immediately, send us the message, we can receive it, we just have to be ready for it. During normal operation, anyway. It's better if the UI script isn't blocking for ages because we do need to send it thumbfast-info once in a while.

Another observation is that the event loop can enter "idle" more often than the "tick" event is propagated, I haven't yet looked into how they're implemented. Maybe some idle steps are redundant.

Please tell me what you know, if I am missing important info.

[po5]

Calling mp.dispatch_events() in the middle of our slow processing is enough to receive and react to events (if any).
It also means we have to account for our idle function sometimes running from that point in the script.

From a quick glance it looks like this will break timers, and the fix is implementing a custom event loop.
There's only one call to mp.add_timeout() in thumbfast, and it's just as a hack to delay info() to the next event loop.
I don't think our use case is impacted, but it can easily be done away with if needed.

We still have to isolate what's being slow, to place the call there.
So long as it's not a single line that takes long enough on its own to miss an update, this should work.

[po5]

These are the functions that take the longest (worst case):

0.177739 info
0.122617 file_load
0.069010 thumb
0.068973 draw
0.044563 calc_dimensions
0.044113 clear
0.044031 watch_changes
0.035766 spawn
0.033313 vf_string
0.029292 check_new_thumb
0.014761 request_seek
0.014715 move_file
0.014587 run
0.011874 get_os

Stats from seek were misattributed to move_file, but it's one of the fastest functions.

seek is less slow when increasing the seek_period. Can we be smarter and avoid this tradeoff?
I notice we call io.open every run of the function, surely we can stop closing the file and store it for later.

Most of the time in draw is spent on this line:

if mp.get_property_number("video-params/rotate", 0) % 180 == 90 then

Makes sense. We should avoid querying properties in such a critical function. Call mp.dispatch_events() if we really need updated props now, in this function or others.
draw is what makes up most of thumb's time as well.

overlay-remove unsurprisingly takes up most of clear, I'm hoping it'll get better if we use mp.command_native_async() when not pre_0_30_0. Do the same for overlay-add. Should get dispatched in order anyway, that's all we care about.

Storing property changes as they arrive would be better than querying them in watch_changes, calc_dimensions, spawn, file_load, vf_string, info.

These changes should greatly improve the situation.

[po5]

I think everything that could be done to address this without fundamentally changing how the script works has been done.
My setup for profiling was annoying so I'm not providing updated timings, but the few functions I glanced at ran consistently faster. thumb takes up to 0.0003s.
Please submit a new issue if you encounter bugs with the recent changes.