RakNet::GetTimeNS differs from results of SYSTEMTIME

[mysapient]

We're currently using version 3.7 of RakNet, and we're using RakNet::GetTime to calculate the delta frame timestep (in seconds) that's passed through our server program, and we've been noticing a few 'oddities' of late.

Code: [Select]

_tmain
...
float t;
RakNetTime CurrentTime = RakNet::GetTime();
RakNetTime LastTime = CurrentTime;

RakNetTimeUS RAK_DLL_EXPORT GetTimeNS( void );
while(1) {
LastTime = CurrentTime;
CurrentTime = RakNet::GetTime();
t = (float)CurrentTime - LastTime;
t/=1000.0f;
if (someFunc->Update(t)!=1)
break;
}
...

According to this post http://www.jenkinssoftware.com/forum/index.php?topic=2346.0, 8 months ago, "GetTimeNS is a bug and is depreciated.", but it still seems to be used thoroughly in RakNet, so I can only assume that it was depricated, rewritten, and resurrected (it's certainly changed alot) - but if I'm wrong please correct me.

[background to issue]
We've implemented a time of day (TOD) system in our game and as it currently stands gametime = realtime. In order to calculate the gametime when the server is first ran it grabs SYSTEMTIME, which it then converts to seconds then it adds the timestep to every tick - giving us a accurate representation of the current time without the SYSTEMTIME call overhead. Then whenever a client connects the server sends it's current gametime, which the client recieves and also adds the timestep to every tick. This allows us to keep the server and client on 'roughly' the same TOD without having to send a 'time packet' every so often. We noticed that when the server was left running overnight and you connected to it the next day the TOD would be incorrect, it would be 'out' by a number of hours!, so we added some logging info to print out what RakNet thinks the time is (by appending the RakNet calculated timestep to the initial SYSTEMTIME call), and what the SYSTEMTIME is actually is (by polling SYSTEMTIME every tick).
[/background to issue]

Server began running at 3:30am, by 8am (RakNetTime - RNT) it'd gotten to be -330seconds out (RakNet 5.5minutes slower than System), at which point RakNet slowly started to gain the time back and by 7pm (RNT) it'd gotten to be equal to the System again (0s difference) - but it kept going in that direction, at a steady pace, and over the next hour and fortyfive minutes it'd gained apporximately +0.5s per minute (making it +49s out), but then it suddently leaps forwards;
Note: These times are what RakNet thinks it should be and how many seconds more it is than the System
...
9.45pm +49s
9.46pm +91s
9.48pm +134s
9.49pm +177s
9.51pm +220s
9.52pm +263s
9.54pm +306s
9.55pm +349s
10.00pm +435s
11.00pm +1984s
12.00am +3537s
2.00am +6647s
3.30am +8981s          // Running for 24 hours
4.06am +9059s          // peak - then direction change
6.00am +8897s
8.00am +8725s
8.06am +8717s          // trough - change direction again
10.00am +8788s
...

.. as you can see during 'daytime' hours the time difference is +/- a few minutes, but between say 9.45pm and 4.06am, the time difference jumps, averaging a gain of 2.6s per second!, making our server 2.5 hours out from the actual time. I'm about to change our code over to use GetTickCount to calcuate the timestep instead of RakNet and repeat the overnight process, but I was just wanting to let you guys know about this (I don't know if anyone else has noticed something similar), it should be easy enough to setup a test program yourselves. I'll keep you updated as I find out more.


Andrew

Note: We've noticed this oddity on a number of machines so we don't think it's due to http://support.microsoft.com/kb/274323.

[Rak'kar]

Unfortunately, it sounds like a hardware issue. The microsecond resolution time is needed for doing LAN transfers. I'll add documentation that the time returned by that function won't always match GetTickCount()

[mysapient]

Thank Rak'kar

As a follow up, I changed the code to use GetTickCount as follows;

Code: [Select]

_tmain
...
DWORD last_tick= GetTickCount();
DWORD tick;
float tstep;

while(1) {
tick = GetTickCount();
tstep = (float)(tick - last_tick);
tstep /= 1000.0f;
if (someFunc->Update(tstep)!=1)
break;
last_tick = tick;
}


The highest difference it reached was +35s at 1.20pm (then it changed direction) and the lowest difference it reached was -161s at 4.00pm (then it changed direction again) It's now 7.50am and it's reading -64s, so while there's still some fluctuation, since it's only a couple of minutes it's probably acceptable (may need to add some correction). It'll prob take a bit more investigation on my part (after all, if I allow it to lose a minute or so each day, it'll soon add up)

I take it that the GetTimeNS function isn't depricated then (as the other post stated?), it just does some more custom functionality now?

Thanks

Andrew

[Rak'kar]

It's just misnamed. You are supposed to use GetTimeUS

[mysapient]

That's fine, we're not explicitly calling it anywhere, I just noticed that it was called from alot of places internally in the RakNet code, and since GetTimeUS is just a macro which calls GetTimeNS (same goes for GetTimeMS -> GetTime (which inturn calls GetTimeNS)) then, imho, there's still something slightly odd about the underlying functionality, whatever it ends up being called. As I said we had this oddity on all the machines we've tested it on so far, which are very different from one another;

Desktop: Microsoft Windows Server 2003, Intel(R) Xeon(R) CPU 3060 @ 2.40 Ghz, 2GB RAM
Laptop: Microsoft Vista, Pertium(R) Dual Core CPU T4200 @ 2Ghz, 3GB RAM

But like I said, we're getting better results now we're using GetTickCount instead, I'm just worried that there may be something intenally going awry since the underlying code is still very much in use.

Andrew