https://bugs.winehq.org/show_bug.cgi?id=50733
Bug ID: 50733 Summary: MUSICUS!: ending videos play are extremely choppy Product: Wine Version: 6.3 Hardware: x86-64 OS: Linux Status: UNCONFIRMED Severity: normal Priority: P2 Component: winegstreamer Assignee: wine-bugs@winehq.org Reporter: pernegger@gmail.com Distribution: ---
When testing if 6.3 fixed #50686 I noticed another performance issue / regression: MUSICUS!'s MPEG1 ending videos are extremely choppy in 6.3. They're not very dynamic in the first place, so it's hard to tell what's wrong, but the audio (ending song) is fine, and the video (lyrics) are more or less in sync, so I'd say lots of frames are getting dropped, but I couldn't swear the whole thing isn't running a tad slow, too.
6.0 is *much* better. If I open the video in VLC directly, it is a bit smoother still, but without a direct comparison I wouldn't have noticed. This is on a Ryzen 7 3900X [Ubuntu 18.04.5].
(Then I remembered that I had this issue on my "laptop", too. That's a Surface Go 2 [Ubuntu 20.04], currently. Only it was *much* worse, totally unwatchable, we're talking a new frame every other second, maybe. I chalked it up to the machine being too slow, but maybe not. It's not just MUSICUS!, either, I retrospect one or two other (older) visual novels showed similar symptoms -- I just assumed the videos were crap at the time. Note that this bug is strictly about MUSICUS!, when that test case is fixed, I'll happily go back and test the other stuff, the tangent is just meant to illustrate that hardware performance may play a role in how noticeable it is.)
[#50239 has slightly different symptoms, and most importantly, I'm using MUSICUS!'s 64-bit exe.]
The regular terminal output has nothing, please advise on how to get suitable debug logs.
https://bugs.winehq.org/show_bug.cgi?id=50733
Zebediah Figura z.figura12@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |z.figura12@gmail.com Keywords| |regression
--- Comment #1 from Zebediah Figura z.figura12@gmail.com --- Can you please attach a log with WINEDEBUG=+quartz,+strmbase,+gstreamer,+timestamp GST_DEBUG=6?
A bisect would also be helpful, if you have the time and ability.
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #2 from pernegger@gmail.com --- Created attachment 69496 --> https://bugs.winehq.org/attachment.cgi?id=69496 log using WINEDEBUG=+quartz,+strmbase,+gstreamer,+timestamp GST_DEBUG=6 [1/4]
With these debug options, I get a few seconds of stuttering audio for a few seconds, then it cuts out entirely. The video drops more and more frames, soon it's 10+ seconds between displayed ones.
[The file is split into 4 parts because of the size limit, just cat it together before decompression.]
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #3 from pernegger@gmail.com --- Created attachment 69497 --> https://bugs.winehq.org/attachment.cgi?id=69497 log using WINEDEBUG=+quartz,+strmbase,+gstreamer,+timestamp GST_DEBUG=6 [2/4]
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #4 from pernegger@gmail.com --- Created attachment 69498 --> https://bugs.winehq.org/attachment.cgi?id=69498 log using WINEDEBUG=+quartz,+strmbase,+gstreamer,+timestamp GST_DEBUG=6 [3/4]
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #5 from pernegger@gmail.com --- Created attachment 69499 --> https://bugs.winehq.org/attachment.cgi?id=69499 log using WINEDEBUG=+quartz,+strmbase,+gstreamer,+timestamp GST_DEBUG=6 [4/4]
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #6 from Zebediah Figura z.figura12@gmail.com --- Yeah, that may have been too much logging. Can you try turning the 6 down to 5?
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #7 from pernegger@gmail.com --- Created attachment 69537 --> https://bugs.winehq.org/attachment.cgi?id=69537 log using WINEDEBUG=+quartz,+strmbase,+gstreamer,+timestamp GST_DEBUG=5
Of course, there you go. Sorry for spamming the server, I should've asked whether you really wanted all that.
The behaviour with these options isn't markedly different from running without them, BTW. Much better chance the log actually shows just the problem, and not overload due to the logging, too.
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #8 from Zebediah Figura z.figura12@gmail.com --- (In reply to pernegger from comment #7)
Created attachment 69537 [details] log using WINEDEBUG=+quartz,+strmbase,+gstreamer,+timestamp GST_DEBUG=5
Of course, there you go. Sorry for spamming the server, I should've asked whether you really wanted all that.
Nah, I probably would have said yes regardless. I just ended up seeing weird lags in the log that made me suspect that terminal buffering or something was interfering with any useful information. Usually I do debug with GST_DEBUG=6, even for latency issues, since the relevant bottlenecks are still pretty evident.
The video frame timings are very weird, but I can't tell if that's inherent to the file format. Can you please attach a log with GST_DEBUG=5 using `gst-play-1.0` to play the video? It should be at a path like base/movie/ed_c.mpg.
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #9 from Zebediah Figura z.figura12@gmail.com --- Actually, maybe never mind, I think the problem is we're dropping most of the frames due to QoS (and I misread the log and thought we weren't doing that, but we definitely are). My guess is that 9c138562fe broke this (since I'm not sure what else could have), because now we're not sending QoS events serialized with samples anymore.
I don't like that explanation, though. GStreamer should be able to handle that. Could you possibly attach a log of 6.0, with the same channels (and GST_DEBUG=5 is enough)?
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #10 from pernegger@gmail.com --- Created attachment 69578 --> https://bugs.winehq.org/attachment.cgi?id=69578 wine-6.0 log using WINEDEBUG=+quartz,+strmbase,+gstreamer,+timestamp GST_DEBUG=5
Here's the wine-6.0 log for comparison. As before, playback wasn't a 100 % right, either, but nothing you'd notice if you didn't open the file in a video player to compare directly. As if frame times were slightly skewed, the pans are a tad mushier, too. 6.0 is alright (but it used to be flawless, even on much slower boxes).
I also tried playing it in gst-play-1.0, that looks flawless, too. There's a log if do you want it after all, but I'd have to upload it in two parts.
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #11 from Zebediah Figura z.figura12@gmail.com --- So 6.0 is dropping about as many frames, which makes it unfortunately difficult to tell what's going wrong.
Still, from examination, I've managed to find some serious issues with our QoS management, and I've submitted some fixes, committed as https://source.winehq.org/git/wine.git/commitdiff/d99912aa65d63973af64f130659ecc36cce82e0d. Please retest with current git or with 6.4 when it is released (scheduled for this Friday).
https://bugs.winehq.org/show_bug.cgi?id=50733
castaneai castaneai@castaneai.net changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |castaneai@castaneai.net
--- Comment #12 from castaneai castaneai@castaneai.net --- Created attachment 69597 --> https://bugs.winehq.org/attachment.cgi?id=69597 minimal reproduction of slow MPEG-1 playback
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #13 from castaneai castaneai@castaneai.net --- Created attachment 69598 --> https://bugs.winehq.org/attachment.cgi?id=69598 GStreamer processing time with GstShark
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #14 from castaneai castaneai@castaneai.net --- Hi. I found a similar problem.
I have attached a minimal application that reproduces this problem. This application uses DirectShow's RenderFile API to play the MPEG file in the first argument.
https://bugs.winehq.org/attachment.cgi?id=69597
It can be reproduced by unzipping it and running the following command
wine mpegplaytest.exe sample_640x360.mpeg
It is terribly slow in Wine 6.3. Wine 6.0 is slightly better, but slower than gst-play.
In addition, I measured the processing time in the pipeline. The results show that mpegvparse0 seems to slow down the whole process.
https://bugs.winehq.org/attachment.cgi?id=69598
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #15 from castaneai castaneai@castaneai.net --- Unfortunately, this problem is also reproduced in the current Git master branch (580413032c61bc142078d08efb1d1167fe385a97).
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #16 from castaneai castaneai@castaneai.net --- Created attachment 69599 --> https://bugs.winehq.org/attachment.cgi?id=69599 gst-play processing time
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #17 from castaneai castaneai@castaneai.net --- Playing the same MPEG-1 video file with the gst-play-1.0 command works very well. There is no delay. The result of measuring the processing time is as follows.
https://bugs.winehq.org/attachment.cgi?id=69599
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #18 from pernegger@gmail.com --- For the record, 6.4 is still horrible.
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #19 from Zebediah Figura z.figura12@gmail.com --- (In reply to pernegger from comment #18)
For the record, 6.4 is still horrible.
Thanks for testing. Can you please attach a new log then? Same channels, GST_DEBUG=5.
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #20 from castaneai castaneai@castaneai.net --- Created attachment 69625 --> https://bugs.winehq.org/attachment.cgi?id=69625 strmbase jitter report
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #21 from castaneai castaneai@castaneai.net --- I looked into this issue further. I got the current latest git master (23ffd0a7986421958c23cffce138afa389209920) and output the report of perform_qos.
The attached log shows that jitter is over 400ms regularly.
https://bugs.winehq.org/attachment.cgi?id=69625
The problem appears to be caused by the DirectShow's clock.
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #22 from pernegger@gmail.com --- Created attachment 69626 --> https://bugs.winehq.org/attachment.cgi?id=69626 wine-6.4 log using WINEDEBUG=+quartz,strmbase,+gstreamer,+timestamp GST_DEBUG=5+
(In reply to Zebediah Figura from comment #19)
Thanks for testing. Can you please attach a new log then?
Certainly, there you go.
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #23 from Zebediah Figura z.figura12@gmail.com --- (In reply to castaneai from comment #21)
I looked into this issue further. I got the current latest git master (23ffd0a7986421958c23cffce138afa389209920) and output the report of perform_qos.
The attached log shows that jitter is over 400ms regularly.
https://bugs.winehq.org/attachment.cgi?id=69625
The problem appears to be caused by the DirectShow's clock.
The jitter is negative, which means that the samples are arriving early (i.e. in time).
mpegpsdemux clips seeks (including seeks to the start of the stream) to a fixed segment that spans from the PTS of the first sample to the last, and both may be nonzero. In the case of MUSICUS!, the first PTS is about 0.39294. We incorrectly use the buffer PTS to report QoS events when we should be using the running time, so mpegpsdemux perpetually thinks that the last sample to arrive was stamped later than the one it is currently processing.
I was able to reproduce a similar problem with an MPEG-1 system file, though I didn't test with earlier Wine. My guess is that the bug was introduced by a3e7cfd4d7, and should be fixed by https://source.winehq.org/patches/data/201821.
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #24 from castaneai castaneai@castaneai.net --- (In reply to Zebediah Figura from comment #23)
(In reply to castaneai from comment #21)
I looked into this issue further. I got the current latest git master (23ffd0a7986421958c23cffce138afa389209920) and output the report of perform_qos.
The attached log shows that jitter is over 400ms regularly.
https://bugs.winehq.org/attachment.cgi?id=69625
The problem appears to be caused by the DirectShow's clock.
The jitter is negative, which means that the samples are arriving early (i.e. in time).
mpegpsdemux clips seeks (including seeks to the start of the stream) to a fixed segment that spans from the PTS of the first sample to the last, and both may be nonzero. In the case of MUSICUS!, the first PTS is about 0.39294. We incorrectly use the buffer PTS to report QoS events when we should be using the running time, so mpegpsdemux perpetually thinks that the last sample to arrive was stamped later than the one it is currently processing.
I was able to reproduce a similar problem with an MPEG-1 system file, though I didn't test with earlier Wine. My guess is that the bug was introduced by a3e7cfd4d7, and should be fixed by https://source.winehq.org/patches/data/201821.
Thank you very much. I applied your patch and the MPEG-1 playback worked fine!
https://bugs.winehq.org/show_bug.cgi?id=50733
--- Comment #25 from pernegger@gmail.com --- Created attachment 69820 --> https://bugs.winehq.org/attachment.cgi?id=69820 wine-6.6 log using WINEDEBUG=+quartz,strmbase,+gstreamer,+timestamp GST_DEBUG=5
Couldn't test 6.5 because of bug #50874, apologies.
6.6 is much better [log attached]. Subjectively: still not perfectly smooth, slight choppiness in the audio now & then, too -- but I'd say it's back at 6.0 levels, so, serviceable.
Meaning, the degradation that triggered this specific bug report has been dealt with, so I could see closing it. On the other hand, it could be better, and I could swear MPEG1 playback has already worked flawlessly in the past ... your call.
Either way, thank you for getting it back into usable shape so quickly!
https://bugs.winehq.org/show_bug.cgi?id=50733
Zebediah Figura z.figura12@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Fixed by SHA1| |5e222064ab27266c0f44ec39868 | |72f611772ff10 Resolution|--- |FIXED Status|UNCONFIRMED |RESOLVED
--- Comment #26 from Zebediah Figura z.figura12@gmail.com --- Marking this as fixed then; thanks for testing.
It's possible that there is another, more minor performance regression. Please feel free to file a separate bug report for that.
https://bugs.winehq.org/show_bug.cgi?id=50733
Alexandre Julliard julliard@winehq.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |CLOSED
--- Comment #27 from Alexandre Julliard julliard@winehq.org --- Closing bugs fixed in 6.7.
-
WineHQ Bugzilla