TIC-80 icon indicating copy to clipboard operation
TIC-80 copied to clipboard

Time() bug? 1.0.2164 Pro

Open Morokiane opened this issue 2 years ago • 17 comments

There seems to be an issue with time(). The functions I have that are calling time() are much slower on the desktop version of TIC-80, but still work correctly on the web version.

Further testing is showing this is affecting MacOS on both M1 and Intel...and is happening in Linux. Runs as expected in Windows

Morokiane avatar May 03 '22 18:05 Morokiane

We have started to use clock() https://en.cppreference.com/w/c/chrono/clock std function here to measure time in 1.0, maybe you have a piece of code to profile it?

nesbox avatar May 04 '22 06:05 nesbox

This screenshot shows an FPS counter that utilizes time(). To the left is the desktop version FPS compared to the web version. The MacOS version stays around 22-26 fps while the web and Windows version will stay around 60. The cart is here Platform Engine

Screen Shot 2022-05-04 at 5 16 22 PM

Morokiane avatar May 04 '22 23:05 Morokiane

Could you pls go to the game menu and check VSYNC option, pls try to enable/disable it and see what happens?

nesbox avatar May 05 '22 06:05 nesbox

Same result with vsync off.

Morokiane avatar May 05 '22 23:05 Morokiane

Sorry to bother you, did you restart the app after disabling VSYNC?

nesbox avatar May 06 '22 13:05 nesbox

Yes.

Morokiane avatar May 06 '22 22:05 Morokiane

Confirming the same issue on Linux and MacOS (VSYNC on/off doesn't matter). The example program at https://github.com/nesbox/TIC-80/wiki/time shows that time progresses much slower.

massung avatar May 08 '22 15:05 massung

This also happens in Android build. Can be seen with the following cart:

-- title:  game title
-- author: game developer
-- desc:   short description
-- script: lua

pt=0

function TIC()
	dt=(time()-pt)/1000
	pt=time()
	cls(13)
	print(dt,0,0)
end

On the correct build it shows the value of ~0.02, but on Linux and Android it shows the value of ~0.001

andreyorst avatar Jun 02 '22 18:06 andreyorst

Notably, this bug does not occur on Windows. If we ask MSDN what clock does, it will tell us:

The clock function tells how much wall-clock time has passed since the CRT initialization during process start. Note that this function does not strictly conform to ISO C, which specifies net CPU time as the return value. To obtain CPU times, use the Win32 GetProcessTimes function. To determine the elapsed time in seconds, divide the value returned by the clock function by the macro CLOCKS_PER_SEC.

That might be our problem (although it doesn't explain why the web version also doesn't have this issue; maybe emscripten's C also returns wall time for clock()?).

MineRobber9000 avatar Jun 25 '22 03:06 MineRobber9000

We have started to use clock() https://en.cppreference.com/w/c/chrono/clock std function here to measure time in 1.0, maybe you have a piece of code to profile it?

From the docs:

Returns the approximate processor time used by the process

@nesbox This is NOT a time [elapsed] measurement function - ie "how much time has passed", this is a CPU measurement function "how much CPU time have I spent since starting".

If it works on the web I'd call that a bug... This should be reverted to the previous timekeeping. Using chrono/clock for our time API is just 100% wrong.

joshgoebel avatar Jun 25 '22 08:06 joshgoebel

If we can use C11 this looks reasonable... you'd have to keep a start variable... and then when you need the time do the math to get the difference (with nanosecond-ish precision)... should be good enough for ms usage.

https://en.cppreference.com/w/c/chrono/timespec_get

Or just revert back to the code we were using before...

joshgoebel avatar Jun 25 '22 09:06 joshgoebel

My vote is to include, no matter what version of TIC-80 we're building, some implementation of the Sokol time functions (stm_*). The Sokol time library is built such that no matter what platform we build for, it should do the right thing for that specific platform (QueryPerformanceCounter on Windows, mach_absolute_time on Mac, emscripten_get_now on Emscripten, and clock_gettime(CLOCK_MONOTONIC,&ts) on all other platforms, which should, in fact, return wall-clock time).

The main reason I suggest using the stm_* family of functions is because versions of TIC-80 built with Sokol have been using the Sokol timer for a while now, prior to 1.0, and nobody had an issue until we changed to using clock, which, as @joshgoebel pointed out (and as I attempted to point out in my comment, although he did a better job of it), is supposed to give CPU time, not wall-clock time.

Of course, failing that, we could just use clock_gettime(CLOCK_MONOTONIC,&ts) instead...

MineRobber9000 avatar Jun 27 '22 03:06 MineRobber9000

We should probably consider using the timekeeping mechanics of the library that has been requested at build time... and then abstract that behind a single generic timeMs function we own... ie, if someone was compiling against SDL they'd get https://wiki.libsdl.org/SDL_GetTicks if they were compiling against Sokol they'd get the stm_now/stm_ms, etc...

joshgoebel avatar Jun 27 '22 14:06 joshgoebel

In quick search I think this just affects core.c and only in 4 places, so one could probably easily whip up and test PR for thsi:

/home/jgoebel/git/TIC-80/src/core/core.c:
  207:     return (clock() - core->data->start) * 1000.0 / CLOCKS_PER_SEC;
  462:             data->start = clock();
  502:         core->pause.time.paused = clock();
  514:         core->data->start = core->pause.time.start + clock() - core->pause.time.paused;

joshgoebel avatar Jun 27 '22 15:06 joshgoebel

We should probably consider using the timekeeping mechanics of the library that has been requested at build time... and then abstract that behind a single generic timeMs function we own... ie, if someone was compiling against SDL they'd get https://wiki.libsdl.org/SDL_GetTicks if they were compiling against Sokol they'd get the stm_now/stm_ms, etc...

Actually, prior SDL builds seem to have used SDL_GetPerformanceCounter... which is just an abstraction over the same stuff Sokol's timer lib uses, since the right way to get time is the right way to get time is the right way to get time.

The main reason I suggested using Sokol's timer functions regardless of platform is that it would provide a consistent API to something that is not quite consistent between platforms (i.e; Windows expects you to do math with a QuadPart member on the object, Mac wants you to convert using a timebase, Emscripten just... hands you a value in seconds, and other systems want you to use a consistent calculation to turn a timespec struct into a nanosecond value that you can turn into milliseconds or whatever you need). Why make our own timeMs function that uses a library's timekeeping when we can just... use one that already exists and is proven to work?

MineRobber9000 avatar Jun 28 '22 04:06 MineRobber9000

I’m using version 1.0, not pro, and time()/1000 is almost 10 times faster than 1/60 in my Debian GNU/Linux. On another computer with the very same system, it’s more than 20 times faster.

I wrote this script:

-- script:  moon
export ^

local start, ticks

show = (y) =>
  w = print @, 240, 0, 0, true
  print @, (240-w)/2, y, 12, true

BOOT = ->
  start = tstamp!
  ticks = 0

TIC = ->
  cls 8
  ticks += 1

OVR = ->
  msg = "tstamp() %3d  "\format tstamp!-start
  show msg, 56
  msg = "time()   %5.1f"\format time!/100
  show msg, 64
  msg = "ticks    %5.1f"\format ticks/60
  show msg, 72

After about 5 minutes of running, I got the following result:

tstamp() 333 time() 254.5 (note I divided by 100 instead of 1000) ticks 333.7

There’s something very wrong with the time() implementation… 🤔

cacilhas avatar Jun 30 '22 20:06 cacilhas

Yep. I already explained it above. We just need a PR to fix it. Or eventually nesbox will get to it.

joshgoebel avatar Jun 30 '22 21:06 joshgoebel

Sorry to bother, but are there any plans on fixing this? The ticket is in the hotfix 1.0 board since May 8

I've tried to see if I'll be able to at least revert the parts of the code, to use an older method, but I'm lacking a lot of knowledge about the codebase, and reverting seemed to be not as easy to do, as there were a lot of changes in the overall code related to time AFAICT.

This seems like a pretty serious bug, basically making development only possible in a web version. Which is not the best way to do it, as the sound is lagging, and overall performance is usually better in the desktop build. Users are also locked to using the web version of games because the desktop build is 10 times slower due to this bug.

Not using delta time at all to compensate for framerate changes is an option, but a rather poor one. I can always use an older build, I guess, but this locks me to an outdated version of Fennel language which is not good either.

Thank you for the work on TIC-80! It's a really great project, and I'd love to see it become better.

andreyorst avatar Oct 04 '22 18:10 andreyorst

Audreyorst - I haven't tested extensively since I'm on MacOS...but when I tested on Windows it didn't "seem" to have this problem. It still is an issue for MacOS and Linux as if you build it from Windows they will have it.

Morokiane avatar Oct 04 '22 23:10 Morokiane

Audreyorst - I haven't tested extensively since I'm on MacOS...but when I tested on Windows it didn't "seem" to have this problem. It still is an issue for MacOS and Linux as if you build it from Windows they will have it.

Windows don't have this problem, yes. It's exclusive to Linux, macOS, and Android (not sure about iOS). Building executables on windows doesn't fix it for other systems either.

andreyorst avatar Oct 07 '22 19:10 andreyorst

Anyone comfortable building from source feel free to test my PR. It just restores the old behavior.

joshgoebel avatar Dec 11 '22 16:12 joshgoebel

Anyone comfortable building from source feel free to test my PR. It just restores the old behavior.

Yep, restores the old behavior.

Screenshot from 2022-12-11 19-02-35

joejoemars avatar Dec 11 '22 19:12 joejoemars