#1981 closed defect (fixed)
FT: Old Mine Road slowdowns
| Reported by: | eriktorbjorn | Owned by: | fingolfin |
|---|---|---|---|
| Priority: | normal | Component: | Engine: SCUMM |
| Version: | Keywords: | ||
| Cc: | Game: | Full Throttle |
Description
While looking at bug #1173161 ("FT: Old Mine Road CTD"), I noticed that the latest development versions of ScummVM tend to slow down a lot just before an encounter on the Old Mine Road. Possibly at other points, too.
I don't have any good savegame, but using boot param 550 to get to the highway and then going from there to the mine road ought to be good enough.
The current theory is that it may have something to do with locking and isSoundHandleActive(), but I haven't yet done anything to verify that.
Ticket imported from: #1174927. Ticket imported from: bugs/1981.
Attachments (3)
Change History (28)
comment:1 by , 19 years ago
comment:2 by , 19 years ago
Odd, the problem seems much less pronounced today. Perhaps it was compounded by the "invalid seek" bug?
It doesn't appear to be completely gone, though...
comment:3 by , 19 years ago
I removed two usages of isSoundHandleActive in the SMUSH code -- maybe that will help this issue, not sure.
comment:4 by , 19 years ago
Unfortunately, it still slows down for me. But at least it's one possible culprit less to worry about.
comment:5 by , 19 years ago
I tried inserting some debugging code to see if locking a mutex took any measurable time, but even during the worst slowdowns it usually took less than 10 ms, according to getMillis().
Maybe the problem is simply that the other applications I'm running on this computer aren't as idle as I would have thought. I'll try shutting them down later today and see what happens.
comment:6 by , 19 years ago
Nope, even with everything else shut down there were still slowdowns. Strange. Not only is this computer a lot faster than my Linux box, I was using the 1x scaper.
comment:7 by , 19 years ago
I inserted some debugging code in SmushPlayer::updateScreen() and SmushPlayer::play(). From what I understand, play() is executed by the main thread and updateScreen() is executed from the SMUSH thread.
It's the play() function that actually updates the screen. The updateScreen() function is the one that calls copyRectToScreen() and tells the main thread that there is a new frame that should be drawn as soon as possible.
This is what my debugging messages looked like during one slowdown:
New frame after 91 ms (update took 2 ms) updateScreen() after 98 ms (update took 0 ms) New frame after 97 ms (update took 3 ms) updateScreen() after 122 ms (update took 0 ms) New frame after 123 ms (update took 2 ms) updateScreen() after 143 ms (update took 0 ms) New frame after 143 ms (update took 2 ms) updateScreen() after 116 ms (update took 0 ms) updateScreen() after 97 ms (update took 0 ms) updateScreen() after 99 ms (update took 0 ms) updateScreen() after 104 ms (update took 0 ms) updateScreen() after 99 ms (update took 0 ms) updateScreen() after 108 ms (update took 0 ms) updateScreen() after 101 ms (update took 0 ms) updateScreen() after 101 ms (update took 1 ms) updateScreen() after 106 ms (update took 0 ms) updateScreen() after 100 ms (update took 0 ms) updateScreen() after 98 ms (update took 0 ms) updateScreen() after 97 ms (update took 0 ms) updateScreen() after 108 ms (update took 1 ms) updateScreen() after 101 ms (update took 0 ms) updateScreen() after 102 ms (update took 0 ms) New frame after 1556 ms (update took 3 ms) updateScreen() after 102 ms (update took 0 ms) updateScreen() after 99 ms (update took 0 ms) updateScreen() after 103 ms (update took 0 ms) updateScreen() after 98 ms (update took 0 ms) updateScreen() after 98 ms (update took 0 ms) updateScreen() after 98 ms (update took 0 ms) updateScreen() after 103 ms (update took 0 ms) updateScreen() after 98 ms (update took 0 ms) updateScreen() after 99 ms (update took 1 ms) updateScreen() after 105 ms (update took 0 ms) updateScreen() after 125 ms (update took 0 ms) New frame after 1123 ms (update took 2 ms) updateScreen() after 46 ms (update took 0 ms) New frame after 48 ms (update took 3 ms) updateScreen() after 23 ms (update took 0 ms) New frame after 17 ms (update took 2 ms) updateScreen() after 83 ms (update took 0 ms) New frame after 81 ms (update took 4 ms)
In other words, it looks to me as if the SMUSH thread was decoding frames just fine, but the main thread - for whatever reason - couldn't keep up.
During my test runs with boot param 550, the slowdown always happened at the same spot: when you're approaching another biker - Father Torque, in this case - on the old mine road. (I.e. it's still running the same background movie.)
comment:8 by , 19 years ago
It's worth noting that the actual updates (i.e. the calls to copyRectToScreen() and updateScreen() in the backend) usually took no measurable time.
I added some more debugging code to the main loop in play(), and that's where things started to look really weird. For instance, during one delay of about 1.2 seconds between the drawing of two frames, I timed a call to parseEvents() taking almost 390 ms and a call to delayMillis(10) taking about 760 ms. Which would mean that those two calls accounted for most of the time spent during that iteration of the loop.
This is obviously completely unreasonable figures. It could be a bug in my debug messages of course, but I'm more tempted to believe that there's a third thread (the audio thread, perhaps?) doing something naughty, like busy-waiting or something.
comment:9 by , 19 years ago
When you approach another biker, INSANE uses how I call it "approach animation". I.e. in some frames there is SKIP chunk and bunch of pictures and it determines by logic which particular frame to draw. See Insane::procSKIP(). Maybe it happens that smuch player *does* draw all frames just doesn't blit them to screen when some frame is skipped which leads to the slowdowns. But I didn't check actual code.
comment:10 by , 19 years ago
As I said, it looks to me as if it draws all the frames, i.e. it calls copyRectToScreen(), but the main thread doesn't update the screen frequently enough.
And if my debugging messages are correct, it's sometimes spending far too much time in functions like pollEvents() and delayMillis(), which makes no sense at all. The only thing I can think of is that some other thread is doing some kind of busy-waiting, stealing the processing time from the main thread.
comment:11 by , 19 years ago
But which thread should that be? Also, your debug output shows that the SMUSH thread (or rather, "timer") is still running fine, so why would the main thread not get enough CPU time, but the SMUSH thread does? No mutex is locked by the main thread either, unless something inside pollEvents() or delayMillis() did, and that shouldn't be the case either, AFAICT.
comment:12 by , 19 years ago
I don't know. The only other thread I can think of would be the audio thread, and I don't see why that should be involved in this case. But I can't see what would make the play() function slow down either. I mean, it's basically just an infinite loop that should spend most of its time parsing events, processing keyboard input and sleeping.
Oddly enough, today I only get occasional frame skips where yesterday it might skip a whole bunch of frames.
comment:13 by , 19 years ago
Any news on this?
A nice profiling tool, which allows recording thread activites, woud be really helpful for this I guess. I.e. so you can see which other threads were active during these long delays, and what they were doing, roughly...
comment:14 by , 19 years ago
I haven't really looked at it recently. Unfortunately I've only seen it on Windows where I don't have all the tools at my disposal that I have on my Linux box.
comment:15 by , 19 years ago
I discussed this some more with sev today, and we tentatively decided that perhaps the problem is the way the SMUSH player handles files. Right now it opens/closes files dozens of times every second. Maybe even more than that. I'm told that under Windows this is a relatively expensive operation, due to complex file access rights handling, but I wouldn't know for sure.
Specifically, it's the FileChunk class that opens/closes a file every time one is created/destroyed. I made an experimental change to a local version of ScummVM to keep the file open, and that did seem to fix the slowdowns. Though it doesn't explain why the slowdowns happened at these particular moments.
I'm not happy enough with my changes to commit my change because
a) During the mine fight a lot of different SMUSH files will be opened, and currently they won't be closed until the main SMUSH object is destroyed.
b) It's possible that doing this breaks things if several objects assume they each have one private handle to the file. I didn't notice any such breakage, though.
c) There may be a better way of doing this.
Still, I've attached my patch in case someone wants to experiment with it.
comment:16 by , 19 years ago
I don't have time to look at your patch, so I dunno if this is being handled by it already, but... a typical problem is also when multiple threads (as is the case with SMUSH+INSANE) try to access the same file; this was the original reason to use multiple file handles, I think. At least I think that's how it used to be, maybe things are different now or maybe I misremember; I'll have to look into the code when I have some spare time (=not at this moment, maybe weekend?)
IMO, the problem is the FileChunk class as such; the abstraction it provides is neat, but makes it very hard to optimize and analyze (regarding thread safety etc.) the whole chunk handling in the SMUSH code. We may have to rethink how that works.
comment:17 by , 19 years ago
I thought the file access in SMUSH/INSANE was done by one thread, while the main thread only dealt with updating the screen etc. But I'll gladly admit I'm not overly familiar with this code.
With the patch a file will probably be opened by the main thread and then accessed by the SMUSH thread, but that'd be easy to fix. (The main thread only opens it to make sure it exists anyway, so I should probably have used the exists() method instead.)
comment:18 by , 19 years ago
See patch #1227243 -- the changes in there try to move all file access to a single thread. I am not sure whether I succeeded, and I might have introduced more problems; but with that patch applied, we would be one step close to optimizing the file access in SMUSH :-)
<https://sourceforge.net/tracker/index.php?func=detail&aid= 1227243&group_id=37116&atid=418822>
by , 19 years ago
| Attachment: | smush2.patch added |
|---|
comment:19 by , 19 years ago
With my SMUSH threading changes in CVS, we can revert to using a single ScummFile object for chunks and subchunks. At least in theory.
The attached patch should (?) improve the behaviour in this bug; the risk is that it returns some of the old crashes/bugs (namely, if I missed any place where it accesses the files from a thread other than the main thread).
Actually, the code could be improved a bit more by reducing the number of seek operations: it is not necessary to constantly reseek. Rather, whenever we delete a sub-block, we should just tell the parent block to "reseek".
comment:20 by , 19 years ago
Well, that does seem to fix the slowdowns.
Without the patch, the CPU load meter hovers around 30% while just cruising on the mine road, and rises sharply - sometimes to over 90% - during the slowdowns.
With the patch, the CPU meter rarely rose above 10%.
This is very unscientific, I know, but I'd say the patch helps performance quite a bit on this particular Windows XP box.
comment:21 by , 19 years ago
Very good. Anod not that unscientific, I think :-). Thanks erik.
My only concern now is that this might bring back some of the old strange crashes in INSANE/SMUSH...
by , 19 years ago
| Attachment: | smush3.patch added |
|---|
comment:22 by , 19 years ago
Here's another version of my patch, which tries to avoid unnecessary seeks, too.
comment:23 by , 19 years ago
Appears to be working. I've played around a bit on the mine road and watched the Full Throttle Intro (since that, if I understand it correctly, is made up from a whole lot of different SMUSH movies).
I've only tried it under Windows, though, and most of the old, strange crashes (that I know of) happened under the X Window System.
On the other hand, we've never promised the development version to be stable, so it's probably better to make this kind of changes well before a stable release. (We're not planning one at the moment, are we?)
comment:25 by , 19 years ago
| Owner: | set to |
|---|---|
| Resolution: | → fixed |
| Status: | new → closed |
For some reason, I can't reproduce this on my Linux box but I don't know if it's because of differences in the Linux and Windows versions, or if it's because I run Linux on a much slower computer.