[SOLVED] "Fast as possible" not working

[filbo]

In current git 4.0.0.0 prerelease (ecc1df8f5863b1cba6ba4d71bd5053e9a376e702):

"Play as fast as possible with display" (Play,Play,Eject buttons, or "551" according to the keys I gave in http://artsoft.org/forum/viewtopic.php?p=13373) no longer works. A third ">" appears on the tape deck screen, but play does not speed up beyond "fast forward".

[Holger]

Oops! Indeed! And I also know why... (This has something to do with the newly added "global animations", that are something like a superset of the "toons" from previous versions, and that are not really announced or documented yet.)

This bug should be fixed soon. (Will let you know as soon as the fix is done and pushed to the Git repository.)

[filbo]

Excellent. See my reply to my other bug thread, which is really mostly about this.

In fact today I failed to reproduce any instances of the "flickery" problem, so now I'm confused. Will keep an eye out for that and post details about rendering modes etc., when/if it happens again. (And maybe I'll even manage to do so on that thread, where it'd at least be under the right title.... :)

[Holger]

OK, that bug should be fixed now. Please "git pull && make run" and check if it works for you.

[filbo]

Fixed, thanks!

Bunch of mini-benchmarks, all run on this Gateway NV57H with Intel i3-2310M 2.1GHz CPU, 8GiB RAM, i3-internal graphics (equal to 2/3 of a Commodore-64).

I tested lots of different modes with four binaries.

Old "fast" binaries from bb8e355174a3ab8cc4b422dbb040f0e048d2995b (I think):

• rocksndiamonds-20160319-SDL1
  rocksndiamonds-20160319-SDL2

New "fast again" binaries from d0409bd76aa84a8745ec2ea6d8a5480c8bea0bcd (after recent synchronization fix):

• rocksndiamonds-20160419-SDL1
  rocksndiamonds-20160419-SDL2

I varied the following parameters:

• ZOOM% -- 100% or 60% (the smallest I could reliably read the game clock with antialiasing disabled) (SDL2-only)
  Small Game Graphics (SGG) -- ON or OFF
  Antialiasing (AA) -- none, linear or anisotropic (SDL2-only)
  Special Rendering (SR) -- OFF, bitmap, target, or double (20160419-SDL2-only)

All runs were playbacks of the same tape of level "EMC cosmos mine 10, level 6" ("/usr/share/games/rocksndiamonds/levels/Emerald Mine Club/emc_cosmos_mine_10/6"), hand-timed to 10 seconds (accurate to ~.2s). With keyboard focus on game window, watch digital clock on desktop; when it ticks over to :x[05], hit '551' as fast as possible; when desktop clock ticks over to :x+1[05], hit ESC; copy down game clock. (Also: when hitting '551', pay attention to reaction time, i.e. "how close to actual tickover did I start hitting it?"; when waiting for the 10s-later second to tick, try to hit ESC at about the same partial-second. This is how I can say ~.2s accuracy. All runs are actually somewhat less than 10s of full speed operation since that doesn't start until I hit the 3rd key; but I type '551' at about the same cadence each time, so the actual lengths are all similar, probably clustered around 9.3s +/- .2s.)

Noted times are elapsed game clock seconds over ~10s realtime; higher is faster. Due to hand-measuring methodology, single differences of 5-10 game clock seconds are probably not meaningful.

Code: Select all

rocksndiamonds-20160319-SDL1:

   125 100% SGG:on
   128 100% SGG:off

rocksndiamonds-20160319-SDL2:

   167 100% SGG:on  AA:none
   157 100% SGG:on  AA:linear
   160 100% SGG:on  AA:anisotropic

   172 100% SGG:off AA:none
   154 100% SGG:off AA:linear
   157 100% SGG:off AA:anisotropic

   130  60% SGG:on  AA:none
   130  60% SGG:on  AA:linear
   129  60% SGG:on  AA:anisotropic

   130  60% SGG:off AA:none
   141  60% SGG:off AA:linear
   124  60% SGG:off AA:anisotropic

rocksndiamonds-20160419-SDL1:

    95 100% SGG:on
    93 100% SGG:off
    (about 75% as fast as 20160319-SDL1)

rocksndiamonds-20160419-SDL2:

   156 100% SGG:on  AA:none        SR:off
   158 100% SGG:on  AA:linear      SR:off
   165 100% SGG:on  AA:anisotropic SR:off
   (same as 20160319-SDL2) (*1a)

   117 100% SGG:on  AA:none        SR:bitmap
   105 100% SGG:on  AA:linear      SR:bitmap
   112 100% SGG:on  AA:anisotropic SR:bitmap
   (about 70% as fast as 20160319-SDL2)

   148 100% SGG:on  AA:none        SR:target
   158 100% SGG:on  AA:linear      SR:target
   162 100% SGG:on  AA:anisotropic SR:target
   (about same as 20160319-SDL2)

   139 100% SGG:on  AA:none        SR:double
   140 100% SGG:on  AA:linear      SR:double
   141 100% SGG:on  AA:anisotropic SR:double
   (about 85% as fast as 20160319-SDL2)

   178 100% SGG:off AA:none        SR:off
   158 100% SGG:off AA:linear      SR:off
   173 100% SGG:off AA:anisotropic SR:off
   (about 105% as fast then 20160319-SDL2) (*1b)

   119 100% SGG:off AA:none        SR:bitmap
   101 100% SGG:off AA:linear      SR:bitmap
    96 100% SGG:off AA:anisotropic SR:bitmap
   (about 65% as fast as 20160319-SDL2)

   158 100% SGG:off AA:none        SR:target
   161 100% SGG:off AA:linear      SR:target
   157 100% SGG:off AA:anisotropic SR:target
   (about same as 20160319-SDL2)

   141 100% SGG:off AA:none        SR:double
   140 100% SGG:off AA:linear      SR:double
   138 100% SGG:off AA:anisotropic SR:double
   (about 85% as fast as 20160319-SDL2)

   144  60% SGG:on  AA:none        SR:off
   146  60% SGG:on  AA:linear      SR:off
   144  60% SGG:on  AA:anisotropic SR:off
   (about 110% as fast as 20160319-SDL2)

    95  60% SGG:on  AA:none        SR:bitmap
   108  60% SGG:on  AA:linear      SR:bitmap
   107  60% SGG:on  AA:anisotropic SR:bitmap
   (about 80% as fast as 20160319-SDL2) (*2a)

   144  60% SGG:on  AA:none        SR:target
   129  60% SGG:on  AA:linear      SR:target
   128  60% SGG:on  AA:anisotropic SR:target
   (tiny bit faster than 20160319-SDL2)

   144  60% SGG:on  AA:none        SR:double
   140  60% SGG:on  AA:linear      SR:double
   143  60% SGG:on  AA:anisotropic SR:double
   (about 110% as fast as 20160319-SDL2)

   145  60% SGG:off AA:none        SR:off
   133  60% SGG:off AA:linear      SR:off
   145  60% SGG:off AA:anisotropic SR:off
   (about 105% as fast as 20160319-SDL2)

   119  60% SGG:off AA:none        SR:bitmap
   119  60% SGG:off AA:linear      SR:bitmap
   116  60% SGG:off AA:anisotropic SR:bitmap
   (about 90% as fast as 20160319-SDL2) (*2b)

   125  60% SGG:off AA:none        SR:target
   130  60% SGG:off AA:linear      SR:target
   132  60% SGG:off AA:anisotropic SR:target
   (tiny bit slower than 20160319-SDL2)

   138  60% SGG:off AA:none        SR:double
   141  60% SGG:off AA:linear      SR:double
   140  60% SGG:off AA:anisotropic SR:double
   (about 105% as fast as 20160319-SDL2)

ALSO tested a little bit with "EMC graphics preference" EMC vs. AGA, but this made no visual difference on this level and didn't seem to affect speed, so I didn't try lots of combinations (nor record results).

In general, SGG and antialias settings didn't seem to have a great deal of effect on speed -- mostly not noticeable, with some small exceptions. (*1a)/(*1b) and (*2a)/(*2b) are pairs where it seems like SGG slightly affects speed.

Choice of "Special Rendering" mode definitely has an effect.

Overall performance -- on this one tested hardware/OS -- seems repaired, sometimes even faster if "right" rendering parameters are chosen.

Final note: if I were to have stumbled through all these benchmarks on the immediately prior binaries (rocksndiamonds-20160418-SDL{1,2}) -- all results would have been "10". Something was broken in game sync logic, causing it to never run faster than realtime.

Final final note! I did a set of quick tests with '51' -- play as fast as possible without display. The 20160419 and 20160319 binaries both completed this level (310s total game time) in 3 seconds, 100x realtime. Interestingly, 20160418 binaries took 6s (50x realtime). During this playback mode the only thing changing on the display is the game clock; even the TIME counter (seconds remaining from initial allotment) is static. Apparently, with the sync bug, just updating the game clock 310 times costs 3s of realtime!

[Holger]

Thanks a lot for this detailed benchmarks! Very helpful, really!

(310s total game time) in 3 seconds, 100x realtime. Interestingly, 20160418 binaries took 6s (50x realtime).

That's interesting. 310 seconds game time while updating the display every second (which now also contains the standard frame delay of 20 ms) means 310 * 20 ms == 6.2 seconds real playing time.

Using half of that time (~3.1s) most probably means that the frame delay was set down to 10 ms immediately before (by activating the visible fast-forward mode before going on to the invisible as-fast-as-possible mode, which does not change the frame delay anymore). Looks like there's still some room for improvement (by setting the frame delay to 0 ms in as-fast-as-possible mode).

[filbo]

Running today's binary, I see a new misbehavior with "Fast as possible, no display" ('51' / Play, Eject):

Process grows without limit! Maybe you're taking a snapshot every frame and not purging any of them?

I was playing back a level with about 250s game time. Time incremented smoothly up to (say) 150s, then it started getting very slow and jerky; then I noticed even my mouse was slow and jerky! But on a rerun, it was fine.

Then I tried a level with ~400s game time and the same problem occurred.

Then I noticed that according to `top`, about 1GiB had been pushed out to swap. Normally swap occupancy on this machine is flat 0.

Each time I ran a bigger level, more parts of the desktop etc. got pushed out to swap; then RnD was able to run that size of playback without further swap, so now it ran fast and I couldn't reproduce the problem until I went to the next longer level.

I think this is new today, but I may have been fooled while testing older binaries (by the "already gobbled that much swap" effect, which I didn't quite grok until I started writing it up).

I'm guessing, but haven't actually played out, that if I were to go interactively play a level of such length, it would again gobble up that much memory. I wouldn't see such extreme jerkiness since the attempted rate of pushing out to swap would be 100x slower (1:1 game:realtime, vs. the fastest no-display mode). But the rest of my desktop would still be getting sucked into molasses...

[filbo]

Ok, definitely not recently new behavior. Working backwards in my binaries, 20150626-SDL1 drove me to swap; 20150619-SDL1 did not. `git log` shows snapshot work around then.

So this is something we already discussed and you perhaps intended to go off and thin out in-core snapshots, but haven't done that yet.

Not sure why I didn't notice it before now. Perhaps because I have too many tabs open in Chrome right now, so machine is already under some memory stress...

[Holger]

One quick question: Which setting do you have selected for "game engine snapshot mode" (setup/game)?

Anything other than "off" would currently indeed eat memory for breakfast when (re)playing long levels. (Or does this even happen with the "off" setting?)

But I do not understand why this should have started with that engine snapshot related commit you mentioned. Definitely have to check for myself what's going on here!

[filbo]

It was on "every move"; just changed it to "every collect" and will try to see if that keeps it down to sane sizes.

I'm not actually using the snapshot stuff at all, so really all I'm doing by having it on is testing things like this for you :)

Ok, I'm now deleting another 30+ lines of reply, copying them over to a new post, because they're really tangential to the current bug report...

[Holger]

(Marking this thread as "solved" now.)