video regions seem to play frames out of order occasionally, if moused over too much

[totaam]

Issue migrated from trac ticket # 1290

component: server | priority: major | resolution: invalid

2016-08-23 02:26:05: afarr created the issue

---

Testing a bit with win32 1.0 r13101 client against 1.0 r13401 fedora 23 server, when mousing over a video region (google-chrome, youtube in this case) the framerate seems to drop (not too surprisingly), but doing so ... let's call it "ridiculously vigorously"... seems to sometimes trigger frames to play/display apparently "out of order" (it looks like "back frames" occasionally get re-displayed... or at least that's the best description I can provide).

It doesn't seem to matter what video content is playing, but it's often necessary to "mouse vigorously" over the video region for several "long seconds" before this behavior starts to show. It does, however, seem to potentially be a "late-spotted" issue potentially related to #1218.

I collected the following small bit of logs with -d regionrefresh,mouse... let me know if there're any other that might be of use... and whether there might be some to use to convince me that I'm imagining things.

2016-08-22 17:18:25,708 add_video_refresh(rectangle[18, 150, 640, 360]) rectangle=rectangle[18, 150, 640, 360]
2016-08-22 17:18:25,709 cancel_refresh_timer() timer=31992
2016-08-22 17:18:25,718 raising WindowModel(0xa00002)
2016-08-22 17:18:25,718 move_pointer(2, (1997, 561))
2016-08-22 17:18:25,725 raising WindowModel(0xa00002)
2016-08-22 17:18:25,725 move_pointer(2, (1997, 560))
2016-08-22 17:18:25,744 add_video_refresh(rectangle[18, 150, 640, 360]) rectangle=rectangle[18, 150, 640, 360]
2016-08-22 17:18:25,745 cancel_refresh_timer() timer=32000
2016-08-22 17:18:25,755 raising WindowModel(0xa00002)
2016-08-22 17:18:25,755 move_pointer(2, (1855, 535))
2016-08-22 17:18:25,761 raising WindowModel(0xa00002)
2016-08-22 17:18:25,762 move_pointer(2, (1734, 518))
2016-08-22 17:18:25,768 add_video_refresh(rectangle[18, 150, 640, 360]) rectangle=rectangle[18, 150, 640, 360]
2016-08-22 17:18:25,768 cancel_refresh_timer() timer=32013
2016-08-22 17:18:25,781 add_video_refresh(rectangle[18, 150, 640, 360]) rectangle=rectangle[18, 150, 640, 360]
2016-08-22 17:18:25,782 cancel_refresh_timer() timer=32026
2016-08-22 17:18:25,787 raising WindowModel(0xa00002)
2016-08-22 17:18:25,788 move_pointer(2, (1407, 503))
2016-08-22 17:18:25,791 raising WindowModel(0xa00002)
2016-08-22 17:18:25,791 move_pointer(2, (1350, 503))
2016-08-22 17:18:25,800 add_video_refresh(rectangle[18, 150, 640, 360]) rectangle=rectangle[18, 150, 640, 360]
2016-08-22 17:18:25,800 cancel_refresh_timer() timer=32031
2016-08-22 17:18:25,815 raising WindowModel(0xa00002)
2016-08-22 17:18:25,816 move_pointer(2, (1315, 502))
2016-08-22 17:18:25,837 remove_refresh_region(rectangle[0, 260, 18, 85]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,838 remove_refresh_region(rectangle[658, 346, 106, 44]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,840 remove_refresh_region(rectangle[0, 150, 18, 25]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,841 remove_refresh_region(rectangle[658, 260, 104, 22]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,851 remove_refresh_region(rectangle[0, 90, 762, 60]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,852 raising WindowModel(0xa00002)
2016-08-22 17:18:25,853 move_pointer(2, (1323, 502))
2016-08-22 17:18:25,854 remove_refresh_region(rectangle[658, 282, 104, 63]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,855 remove_refresh_region(rectangle[0, 345, 18, 45]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,859 remove_refresh_region(rectangle[658, 450, 444, 60]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,861 raising WindowModel(0xa00002)
2016-08-22 17:18:25,861 move_pointer(2, (1507, 502))
2016-08-22 17:18:25,872 remove_refresh_region(rectangle[658, 150, 104, 25]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,876 raising WindowModel(0xa00002)
2016-08-22 17:18:25,876 move_pointer(2, (1802, 502))
2016-08-22 17:18:25,881 remove_refresh_region(rectangle[762, 90, 340, 192]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,883 remove_refresh_region(rectangle[0, 513, 764, 2]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,883 remove_refresh_region(rectangle[658, 345, 104, 1]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,884 remove_refresh_region(rectangle[0, 515, 764, 3]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,886 remove_refresh_region(rectangle[764, 346, 338, 44]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,887 remove_refresh_region(rectangle[0, 430, 18, 83]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,888 remove_refresh_region(rectangle[658, 175, 104, 85]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,889 remove_refresh_region(rectangle[0, 175, 18, 85]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,890 remove_refresh_region(rectangle[0, 390, 18, 40]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,892 remove_refresh_region(rectangle[762, 282, 340, 64]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,895 raising WindowModel(0xa00002)
2016-08-22 17:18:25,896 move_pointer(2, (1916, 504))
2016-08-22 17:18:25,897 remove_refresh_region(rectangle[658, 390, 444, 60]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,899 remove_refresh_region(rectangle[18, 510, 1084, 3]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,916 subregion auto-refresh delay: 376
2016-08-22 17:18:25,920 raising WindowModel(0xa00002)
2016-08-22 17:18:25,921 move_pointer(2, (1888, 504))
2016-08-22 17:18:25,930 raising WindowModel(0xa00002)
2016-08-22 17:18:25,931 move_pointer(2, (1826, 498))
2016-08-22 17:18:25,934 add_video_refresh(rectangle[18, 150, 640, 360]) rectangle=rectangle[18, 150, 640, 360]
2016-08-22 17:18:25,934 cancel_refresh_timer() timer=32041
2016-08-22 17:18:25,939 raising WindowModel(0xa00002)
2016-08-22 17:18:25,939 move_pointer(2, (1650, 478))
2016-08-22 17:18:25,942 raising WindowModel(0xa00002)
2016-08-22 17:18:25,942 move_pointer(2, (1546, 475))
2016-08-22 17:18:25,953 add_video_refresh(rectangle[18, 150, 640, 360]) rectangle=rectangle[18, 90, 1084, 633]
2016-08-22 17:18:25,955 cancel_refresh_timer() timer=32145
2016-08-22 17:18:25,965 raising WindowModel(0xa00002)
2016-08-22 17:18:25,966 move_pointer(2, (1451, 473))
2016-08-22 17:18:25,981 add_video_refresh(rectangle[18, 150, 640, 360]) rectangle=rectangle[18, 90, 1084, 633]
2016-08-22 17:18:25,984 cancel_refresh_timer() timer=32167
2016-08-22 17:18:25,986 remove_refresh_region(rectangle[18, 722, 1084, 1]) updated refresh regions=[R(18, 150, 640, 360)]
2016-08-22 17:18:25,989 raising WindowModel(0xa00002)
2016-08-22 17:18:25,989 move_pointer(2, (1339, 475))
2016-08-22 17:18:26,006 raising WindowModel(0xa00002)
2016-08-22 17:18:26,007 move_pointer(2, (1390, 497))
2016-08-22 17:18:26,008 raising WindowModel(0xa00002)
2016-08-22 17:18:26,017 add_video_refresh(rectangle[18, 90, 1084, 633]) rectangle=rectangle[18, 90, 1084, 633]
2016-08-22 17:18:26,017 cancel_refresh_timer() timer=32177
2016-08-22 17:18:26,017 move_pointer(2, (1444, 515))
2016-08-22 17:18:26,022 remove_refresh_region(rectangle[0, 90, 18, 633]) updated refresh regions=[R(18, 90, 1084, 633)]
2016-08-22 17:18:26,024 remove_refresh_region(rectangle[18, 722, 1084, 1]) updated refresh regions=[R(18, 90, 1084, 632)]
2016-08-22 17:18:26,045 add_video_refresh(rectangle[18, 90, 1084, 632]) rectangle=rectangle[18, 90, 1084, 633]
2016-08-22 17:18:26,046 cancel_refresh_timer() timer=32185
2016-08-22 17:18:26,052 remove_refresh_region(rectangle[0, 90, 18, 633]) updated refresh regions=[R(18, 90, 1084, 632)]
2016-08-22 17:18:26,052 raising WindowModel(0xa00002)
2016-08-22 17:18:26,053 move_pointer(2, (1717, 575))
2016-08-22 17:18:26,055 raising WindowModel(0xa00002)
2016-08-22 17:18:26,055 move_pointer(2, (1804, 591))
2016-08-22 17:18:26,061 add_video_refresh(rectangle[18, 150, 640, 363]) rectangle=rectangle[18, 90, 1084, 633]
2016-08-22 17:18:26,061 cancel_refresh_timer() timer=32195
2016-08-22 17:18:26,062 raising WindowModel(0xa00002)
2016-08-22 17:18:26,062 move_pointer(2, (1902, 603))
2016-08-22 17:18:26,077 raising WindowModel(0xa00002)
2016-08-22 17:18:26,077 move_pointer(2, (1897, 599))
2016-08-22 17:18:26,104 add_video_refresh(rectangle[18, 150, 640, 363]) rectangle=rectangle[18, 90, 1084, 633]
2016-08-22 17:18:26,105 cancel_refresh_timer() timer=32200

[totaam]

2016-08-23 14:35:27: antoine changed owner from antoine to afarr

[totaam]

2016-08-23 14:35:27: antoine commented

---

Looks to me like this belongs in #800, does this go away if you turn off b-frames? (see #800#comment:16)

Does the framerate really drop by much? Can you measure it?
What does the paint debugging show? (are we still painting as video?)

[totaam]

2016-08-25 21:54:37: afarr commented

---

In fact, it looks like you are correct, the frames rendering apparently out of order only happens while b-frames are enabled - so I will copy those logs and new paint debugging information over to #800.

The framerate does seem to drop whether the b-frames are disabled or not though.

Using watch -n 1 "xpra info :13 | grep fps=" to capture the fps, I see an fps of about 23-25 once a video has a chance to "get settled" (using the default youtube video size on a google-chrome window of about 1300 x 500 px).

window.2.encoder.fps=25
window.2.video_subregion.fps=7.56691646576

After a long and vaguely tiring 5-10 seconds of vigorously mousing over the video, the framerate seems to be dropping to about 8-10 fps (and with -d paint outputting logs server and client side, I've seen it drop as low as 4).

window.2.encoder.fps=8
window.2.video_subregion.fps=7.56691646576

With the b-frames enabled, the fps seems to drop about the same (with and without the logging running), though it does seem to "recover" and improve a little bit faster.

I'm not sure what to make of the video_subregion.fps values being the same, though that does seem to suggest that we're still painting as video (I also see that whether b-frames are disabled or not)... and running with opengl_paint_box=1 the video region does seem to be accurately detected and encoding with h264, except for periodic painting of the region around the video as webp or rgb24 (which, again, I seem to be seeing with b-frames enabled or disabled equally).

I'm not sure if you want to re-purpose this ticket for the frame rate issue, or if I should close this and make a new one specific to that (if so, let me know if there's anything in particular to test for when I open a new one). In the meantime, I'll re-open #800 and paste some -d paint logs and the above logs into that.

[totaam]

2016-09-06 20:05:52: afarr changed status from new to closed

[totaam]

2016-09-06 20:05:52: afarr set resolution to invalid

[totaam]

2016-09-06 20:05:52: afarr commented

---

Ok, currently looks like the fps issue is also being looked at in #800.

Closing this as invalid.

[totaam]

2016-09-07 04:34:08: antoine commented

---

Moving the low fps issue to #1299.