Does anyone what the underlying implementation is of this? Is it just a call to uptimeMillis()? I’m running into some odd timing behaviour on my app and trying to narrow down what might be causing it.
[import]uid: 44812 topic_id: 14768 reply_id: 314768[/import]
Brian,
On Android, the Lua system.getTimer() calls the C function gettimeofday(), which returns current time as number of seconds since the Unix time epoch of 1970. This value is returned as a decimal number (ie: floating point) where the whole number part is is seconds and the fractional part is in microseconds.
On the Mac simulator and iOS, the system.getTimer() calls the mach_absolute_time() function which I believe returns number of seconds since application or operating system startup.
So what kind of issues are you running into? Are you trying to calculate time differences and the result are coming out wrong? [import]uid: 32256 topic_id: 14768 reply_id: 54598[/import]
The issue is that every now and then the system.getTimer() return value goes a little wonky and thus my timed game thinks it’s game over even though only a little time has elapsed. It’s not easy to reproduce but it happens maybe every 20 or so games.
Assuming it’s not my bug (which it very possibly is), I’m trying to narrow down other potential issues so I can at least monitor those. For example, behaviour of system.getTimer() when the app is sent to the background and resumed, or when the phone enters a sleep state.
My understanding is that the timer is monotonically increasing and only accounts for when the app is running, thus I don’t have to trap system resume/update events in order to track the delta times.
[import]uid: 44812 topic_id: 14768 reply_id: 54599[/import]
Actually, I noticed in my logs that when I come out of restore
D/SystemClock( 1158): Setting time of day to sec=1315347088
Is it possible that there are adjustments happening to the system clock and that can shift things around?
[import]uid: 44812 topic_id: 14768 reply_id: 54600[/import]
Hello Brian,
The Android implementation of system.getTimer() is based off of the system clock, which is prone to clock changes. Per our documentation, it is supposed to only count up like you said. I’ll list this as a bug on our end, because I can see this causing issues when the system clock is shifted forward or backward in time.
That said, I wouldn’t expect huge time differences when Android updates its system clock (unless of course you have a hardware problem). Perhaps your code can’t handle negative time differences between calls to getTimer()?
[import]uid: 32256 topic_id: 14768 reply_id: 54604[/import]
Well it’s entirely likely I don’t handle negative time deltas because, well, I didn’t think that was supposed to happen =)
Android’s SDK supposedly has uptimeMillis() which is supposed to provide a monotonically increasing millisecond timer, however I think it’s only ms resolution, not us resolution, so it may not suit your needs.
I’m doing a pretty simple time logic, and it’s possible I’m doing it with the wrong assumptions, but it’s just a form of:
level\_start = system.getTimer()
done = false
while not done
now = system.getTimer()
if now - level\_start \> DURATION then
done = true
end
end
The actual code also factors in pause duration, etc. but it does not do anything special for suspend/resume.
On occasion the exit condition is hit with crazy values, but I think it only happens when I suspend the app for a while and come back. If I could narrow it down a bit then I’d have more information but I don’t have a strong repro case.
[import]uid: 44812 topic_id: 14768 reply_id: 54609[/import]
Hi Brian,
I don’t see how slight clock changes can break your code. The worst a slight clock change can do is make the game end a little early or late. However, a huge clock change, such as when it switches between timezones would affect your game… which I doubt is the case here.
Something else must be going wrong. I recommend that you add some Lua print() statements to your script to print what the time is when starting the game and the current time it thinks it is when the game ends. You can see the printed logs entries via Android tool “adb logcat”. [import]uid: 32256 topic_id: 14768 reply_id: 54616[/import]
Hey Joshua,
Upon further research I think there may be a bug in your Android implementation.
I have a simple test app that traps “system” events of “applicationSuspend” and “applicationResume”. On suspend I mark the time and on resume I print out the amount of time “in suspension”.
For short durations (a few minutes or less) I get a very short time, e.g. 50ms or less. This would indicate to me that slept time is not counted against the app.
But when I leave the app suspended for a very long period of time, say an hour or more, I get HUGE times reported. I think this is the source of my problems.
Trapping and printing out the data, my app printed (when running on a Droid):
I/Corona ( 4760): Suspended at 74258.211
(stuff removed)
I/Corona ( 4760): Resumed at 756750.87, slept 682492.66ms
This seems to be fairly reproducible.
I thought maybe the system updating the clock was causing this, but I manually forced a clock update by toggling Automatic Time Update in Settings (and confirmed with logcat) and the interval was correct.
My new hypothesis is that after some duration of time in suspension that either gettimeofday() is returning something crazy or we’re hitting an edge case in your implementation.
I’ll see if I can figure out a solid repro case by testing longer and longer intervals.
[import]uid: 44812 topic_id: 14768 reply_id: 54630[/import]
Well, there’s my negative time! I left my app suspended for about an hour:
I/Corona ( 4760): Suspended at 1125073.945
(about an hour elapses then I resume my app)
I/Corona ( 4760): Resumed at 737541.40, slept -387532.55ms
Are you just calling gettimeofday() at startup and saving that off in a long variable somewhere as secs*1000+usec/1000 then computing a delta from that? How do you account for time while suspended?
[import]uid: 44812 topic_id: 14768 reply_id: 54638[/import]
This time I let it go for 43 minutes, check out the crazy values returned. Also note the kernel timezone update and setting time of day messages from the system – again, not sure if that’s relevant or not.
I/Corona ( 4989): Suspended at 15086.49, wall Tue Sep 6 22:09:22 2011
D/AlarmManagerService( 1078): Kernel timezone updated to 240 minutes west of GMT
D/SystemClock( 1158): Setting time of day to sec=1315363964
I/Corona ( 4989): Resumed at 18446744072040840.00, slept 18446744072025752.00ms, wall time: Tue Sep 6 22:52:53 2011
In case you’re curious, that returned time in hex:
0x199999998FA75920
If we assumed that it’s milliseconds, then the usecond value would be:
0xFFFFFFD925B42500
[import]uid: 44812 topic_id: 14768 reply_id: 54653[/import]
Hello Brian,
The system.getTimer() is “supposed” to pause when the app is suspended and resume ticking once the app is resumed. There is clearly a bug in the Android suspend/resume implementation that we need to address. This bug just made it to the top of our list and we’ll look into it tomorrow. Thank you for reporting it and I apologize for the confusion.
[import]uid: 32256 topic_id: 14768 reply_id: 54658[/import]
Thanks Joshua. I bet it’s an easy fix if someone just looks at the code, corner cases are usually like that =)
I’ll continue spamming this thread with additional information just so you guys have as much data as possible in case you can’t repro it on your side. I’m using build 609 on Win7/64 testing on a Droid without wireless (bad ESN).
I’m going to test overnight with automatic time adjustments disabled to see if that’s definitely a trigger not.
At a 15 minute interval it still wasn’t happening, but it happened at 42 minutes, so I guess I’ll binary search until I can figure out the interval of time required to make it happen.
[import]uid: 44812 topic_id: 14768 reply_id: 54660[/import]
I actually greatly appreciate the information that you are posting here. So please, spam away. 
The suspend/resume code for the timer appears to be shared on all platforms, so this may be an issue with the simulator as well. I haven’t tested it for myself yet. I’ll do so tomorrow.
I also noticed that the getTimer() implementation for Windows is wrongly based on the system clock instead of system ticks. That’s going to have to change too. [import]uid: 32256 topic_id: 14768 reply_id: 54661[/import]
I can’t get the simulator to even recognize suspend/resume – when I alt-tab away my event handler doesn’t fire on the simulator.
[import]uid: 44812 topic_id: 14768 reply_id: 54664[/import]
Okay, with automatic time adjustments OFF, it still happened, so we can eliminate that as a factor.
I/Corona ( 5121): Suspended at 50822.88, wall Tue Sep 6 23:58:29 2011
I/Corona ( 5121): Resumed at 18446744071597620.00, slept 18446744071546796.00ms, wall time: Wed Sep 7 00:47:21 2011
So it’s probably a pretty obvious bug in your code. If you want to send it to me I’m more than happy to look at it (I write profilers for a living so, uh, time issues are something I’m pretty intimately aware of =) ).
If your code is in C/C++ (which I’m guessing is true since you said it’s shared across platforms) I’m going to guess it’s a sign extension issue or something similar.
[import]uid: 44812 topic_id: 14768 reply_id: 54673[/import]
Tested with a 36 minute duration and it didn’t work.
I/Corona ( 5424): Suspended at 6331.30 Wed Sep 7 10:39:51 2011
I/Corona ( 5424): Resumed at 2178084.32, slept 2171753.02ms, Wed Sep 7 11:16:03 2011
My theory is that it’s wrapping/failing at 35 minutes due to 32-bit truncation/sign extension or something similar.
0x7FFFFFFF = 2147483647
Assuming you’re using timevals and thus useconds as your measurement of time, then if you’re storing or calculating useconds in a signed 32-bit value then:
2147.483647 seconds = 35.7914 minutes
Since it goes totally crazy instead of just wrapping I’m guessing that the suspended time is probably stored correctly but when integrated into your system.getTimer() calculation it fails. That should be easy to repro by setting it to a 32-bit value directly and seeing what happens. [import]uid: 44812 topic_id: 14768 reply_id: 54721[/import]
Just tested with a 30 minute interval and it worked. I’m not going to continue to binary search to tighter intervals, but given the data so far it looks like definitely a 32-bit sign issue in your system.getTimer() calculations.
[import]uid: 44812 topic_id: 14768 reply_id: 54723[/import]
Brian,
There are options to suspend/resume your app within the simulator via the “Hardware” menu.
Oh, and thanks for the additional tests. We’ll be looking into this issue today. [import]uid: 32256 topic_id: 14768 reply_id: 54751[/import]
Ah, okay. I think the docs for the events state that if the simulator is sent to the background that it happens. I’ll see if I can repro with the simulator. [import]uid: 44812 topic_id: 14768 reply_id: 54753[/import]
The simulator is not supposed to suspend the app if the window no longer has the focus. Can you give me the URL to the doc that states this please? It will need to be corrected. [import]uid: 32256 topic_id: 14768 reply_id: 54755[/import]