Unity3d Mac Webplayer - Timestamp Inconsistency

[Deleted User]
edited August 2010 in DotNet
I am using NPeer.ServerTimeInMilliSeconds for prediction, but it acts strangely on the Mac webplayer.

Approximately every 100ms the reported server time is off by -2000ms, then it goes back to normal.

I do see a comment in the code that says "use tcp for webplayer on MacOS!". But I want to use UDP, and so far this is the only problem I have seen (10.5 Leopard). Maybe Tiger acts different...

Anyway, I have a workaround for this issue:
using DE.Exitgames.Neutron.Client;

public class PhotonHelper
{
	static private long lastTimestamp = 0;

	public static long GetServerTimestamp(NPeer nPeer)
	{
		if (lastTimestamp > nPeer.ServerTimeInMilliSeconds)
		{
			return nPeer.ServerTimeInMilliSeconds + 2000;
		}
		lastTimestamp = nPeer.ServerTimeInMilliSeconds;	
		return lastTimestamp;
	}
}

Then I can send the timestamp with the rest of the movement info:
evInfo.Add((System.Object)STATUS_PLAYER_TIMESTAMP, (long)PhotonHelper.GetServerTimestamp(nPeer));

Comments

  • Is it always "exactly" off by 2sec? Very weird.
    It also sounds like this happens only on the Mac webplayer but not on other systems. Can you confirm this?

    We'll take a look.
  • It is strange. I just added some code to the Unity Demo app to illustrate the issue.

    I added some code to the Update function in usePhoton.cs
    // Update is called once per frame
    	static long lastTimestamp = 0;
    	static long lastBadTimestamp = 0;
    	void Update ()
    	{
    		if( lastTimestamp > nPeer.ServerTimeInMilliSeconds )
    		{
    			long timeSinceLastBadTimestamp = nPeer.ServerTimeInMilliSeconds - lastBadTimestamp + (long)(Time.deltaTime*1000);
    
    			long diff = nPeer.ServerTimeInMilliSeconds - lastTimestamp - (long)(Time.deltaTime*1000);
    
    			Debug.LogError("Timestamp off by: " + diff + " Last bad time stamp: " + timeSinceLastBadTimestamp );
    
    			lastBadTimestamp = nPeer.ServerTimeInMilliSeconds;
    		}
    		lastTimestamp = nPeer.ServerTimeInMilliSeconds;
    

    In Unity Time.deltaTime is the number of seconds since the last Update was called.

    The output looks like this:

    Timestamp off by: -1999 Last bad time stamp: 1006
    Timestamp off by: -1999 Last bad time stamp: 1005
    Timestamp off by: -1999 Last bad time stamp: 1009
    Timestamp off by: -1999 Last bad time stamp: 1011

    So every 1 second, the timestamp is off by 2 seconds for a single frame. Strange stuff. You can actually visually see it if you look at the serverTime printout on the GUI too.

    This does not happen on my Win7 computer, only on the Mac in the editor and webplayer.

    MacBook Pro Specs:
    Mac OS X 10.5.8
    Processor 2.4 GHz Intel Core 2 Duo
    Memory 3 GB 667 MHz DDR2 SDRAM
    GeForce 8600M GT

    Let me know if you need any more info. At least there is a workaround, and so far UDP seems to work fine on Mac.
  • Thanks for the details.

    The property ServerTimeInMilliSeconds is this simple:
    get { return (long)(Environment.TickCount + peerBase.serverTimeOffset); }
    

    And serverTimeOffset is set everytime a ACK is received from the other side (this includes the sent-time for the command it ACKs). We add roundtripTime/2 and substract the TickCount. That's all there is. Could for some reason Environment.TickCount be off?

    As there is a temp workaround and we're preparing stuff for a conference, I will have to move this to mid/end of next week. Sorry.
  • Environment.TickCount is the culprit.
    long lastTick = 0;
    	void OnGUI ()
    	{
    		GUI.Label(new Rect(10,100, 250, 20), "serverTime in ms: " + (Environment.TickCount));
    		
    		if( lastTick > Environment.TickCount )
    		{
    			Debug.LogError( "Tick from the past: " + (Environment.TickCount - lastTick) );
    		}
    		
    		lastTick = Environment.TickCount;
    	}
    

    I don't see any reference to a Mono bug that would cause this. Perhaps it is just my computer somehow... I only have the one Mac for testing on.
  • Interesting stuff - I can reproduce this on my Mac Pro, in the Unity Editor. Looks pretty much like the behaviour you described: One "bad tick" every second.

    I can't reproduce this in .NET 3.5 (in a Virtual Machine running on my Mac). I also can't reproduce this inside Mono 2.4.2.1 (directly on the Mac). It seems this only occurs in Unity, and very likely in Mono 1.2.5 (which is the version Unity currently uses ... something that hopefully will change very soon; 1.2.5 is known to be "a bit buggy and kinda old").

    Unfortunately, I don't have Mono 1.2.5 at hand for testing this with the plain Mono version (but it should be possible to find that old version in some archives, install and test it ... it should also be possible to directly use the version that comes with Unity but I don't have the time ATM to get this up and running ... when trying /Applications/Unity/Unity.app/Contents/Frameworks/MonoCompiler.framework/mono to run my app, I get an error that mscorlib.dll can't be found; in the worst case it should be possible to fix this by mimicking the path that mono-version wants with some trick-folders and symlinks).

    Here's my little test-application (that's a plain .NET / Mono application ... I've only compiled it with .NET but that shouldn't make a difference):
        class Program {
            static void Main(string[] args) {
                long lastTick = 0;
                long lastMajorTick = 0;
    
                int past = 0;
                int present = 0;
                int future = 0;
    
                while (true) {
                    if (lastTick > Environment.TickCount) {
                        past++;
                    }
    
                    if (lastTick < Environment.TickCount) {
                        future++;
                    }
    
                    if (lastTick == Environment.TickCount) {
                        present++;
                    }
    
                    if (lastMajorTick + 1000 < Environment.TickCount) {
                        System.Console.Out.WriteLine(string.Format("Major Tick: {0}, {1}, {2}", past, present, future));
                        past = 0;
                        present = 0;
                        future = 0;
                        lastMajorTick = Environment.TickCount;
                    }
    
                    lastTick = Environment.TickCount;
                }
            }
        }
    
    I'm attaching the compiled version of this ... in Mono, you can simply run this by entering the following in the commandline:
    mono TestEnvironmentTicks.exe
    
    You can exit the app with Ctrl-C (like in the old days ;-) ).
  • I don't have access to our office Mac now:
    Can you verify that the test (OnGUI()) is not called (for some reason) twice (by two threads)?
  • As Unity is mostly single-threaded, that shouldn't be the case. OnGUI is called multiple times per frame (in different "modes") - but that should be consecutively from one single thread.

    A little test supports that assumption: When I put the section that Doug posted into a lock-block, I still get the same behavior (lock is on a static object and starts before GUI.Label and ends after lastTick = System.Environment.TickCount; - so if there were multiple calls, that whole section would be executed in atomic manner which should remove any such side-effects).

    To be super-safe, I've moved that same code into Update() (which is only called once per frame), and I still get the "-2s every second" effect. I'd still love to see my little test-case run in Mono 1.2.5 to see if that behavior can reproduced "outside of Unity". Any volunteers? ;-)
  • Wow good stuff Jashan. Thanks for testing this out on your Mac. :)
  • Well, I tested Mono 1.2.5 but on Win XP. No "past" counts.
    On Monday or so, I can check in the office.
    Download link (if anyone else volunteers): http://ftp.novell.com/pub/mono/archive/1.2.5/download/
  • Cool - thanks for testing this and thanks for the download link! I'll test this on my Mac later, when I'm back home.
  • Ok - got it!

    From what I can tell, this is a Mono 1.2.5 bug that happens on the Mac. With my test-case implementation, it only occurred sporadically - but it did occur under Mono 1.2.5, 1.2.6 and 1.9.1 but not in 2.4.2.1 or 2.6.1. I've added an optional "Thread.Sleep(1)" in my code and am now running 5 seconds per print-out instead of 1 second - this way, the problem occurs more reliably. Also the app automatically stops after 31 seconds. You may want to recheck it with this new version under Mono 1.2.5 on Windows to see if this bug also occurs under Mono for Windows.

    Here's the good news: You can actually fix this even with Mono 1.2.5 by using Stopwatch instead of Environment.TickCount. One thing to be careful with: Environment.TickCount is different from Stopwatch.ElapsedTicks! Stopwatch.ElapsedTicks really returns the ticks (which is a lot more than milliseconds), so if you replace this, you better use Stopwatch.ElapsedMilliseconds (which is "more or less" the same as Environment.TickCount ... see also: Stopwatch.ElapsedTicks).

    Environment.TickCount also has an anomaly every 49.8 days; I'm not sure if Stopwatch has the same issue but it's probably good to make sure this doesn't throw off a server, see also Environment..::.TickCount. Ah - watch out: Stopwatch.ElapsedMilliseconds returns long instead of int - so that anomaly probably doesn't occur there; but you need to be aware that you're now dealing with long instead of int (if you just build the diff that shouldn't matter, you can do the diff with longs and then cast to int: (int) (a - b) ... just if you're using the actual value anywhere this would require some changes).

    I've added Stopwatch as an alternative way to check this in my little repro-project (see attached file) and with that, I can't reproduce the issue any longer - even in Mono 1.2.5 on the Mac. So there is a way to properly fix this without having to wait for UT to get Unity up to a recent Mono version, yay ;-)

    So here's some results and other stuff I found out while playing with this:

    The parameter "1" is the number of milliseconds to "sleep" at the end of each iteration. I'm not really sure why this makes a difference - the error occurred also without it; but less frequently. Here's some test-results (first with "1", then without; this is both on the Mac with Mono 1.2.5). The parameter "sw" (3rd test-result) is just "any second parameter" which activates using the stopwatch instead of Environment.TickCount, as you can see, using Stopwatch.ElapsedMilliseconds instead of Environment.TickCount solves the issue also for Mono 1.2.5 on the Mac:

    $ mono TestEnvironmentTicks.exe 1
    Checking System.Environment.TickCount for 30 seconds; one msg per 5 seconds
    
    Major Tick 1:	03x backwards (=error!),	01x same time,	2917x future
    Major Tick 2:	05x backwards (=error!),	01x same time,	4917x future
    Major Tick 3:	05x backwards (=error!),	01x same time,	4915x future
    Major Tick 4:	05x backwards (=error!),	01x same time,	4910x future
    Major Tick 5:	05x backwards (=error!),	01x same time,	4916x future
    Major Tick 6:	05x backwards (=error!),	00x same time,	4918x future
    
    DONE!
    

    $ mono TestEnvironmentTicks.exe
    Checking System.Environment.TickCount for 30 seconds; one msg per 5 seconds
    
    Major Tick 1:	01x backwards (=error!),	4827526x same time,	2081x future
    Major Tick 2:	02x backwards (=error!),	7824178x same time,	3347x future
    Major Tick 3:	02x backwards (=error!),	7731087x same time,	3319x future
    Major Tick 4:	02x backwards (=error!),	7767446x same time,	3307x future
    Major Tick 5:	01x backwards (=error!),	7778878x same time,	3343x future
    Major Tick 6:	03x backwards (=error!),	7730197x same time,	3321x future
    
    DONE!
    

    $ mono TestEnvironmentTicks.exe 1 sw
    Checking CurrentTicks for 30 seconds; one msg per 5 seconds
    Sleep: 1
    Stopwatch: True
    
    Major Tick 1:	00x backwards (=error!),	00x same time,	4872x future
    Major Tick 2:	00x backwards (=error!),	02x same time,	4902x future
    Major Tick 3:	00x backwards (=error!),	00x same time,	4909x future
    Major Tick 4:	00x backwards (=error!),	02x same time,	4899x future
    Major Tick 5:	00x backwards (=error!),	00x same time,	4905x future
    Major Tick 6:	00x backwards (=error!),	00x same time,	4903x future
    
    DONE!
    

    Here's the result with Mono 2.4.2.1 on my Mac:

    $ mono TestEnvironmentTicks.exe 1
    Checking System.Environment.TickCount for 30 seconds; one msg per 5 seconds
    
    Major Tick 1:	00x backwards (=error!),	00x same time,	4903x future
    Major Tick 2:	00x backwards (=error!),	02x same time,	4906x future
    Major Tick 3:	00x backwards (=error!),	02x same time,	4919x future
    Major Tick 4:	00x backwards (=error!),	00x same time,	4920x future
    Major Tick 5:	00x backwards (=error!),	02x same time,	4915x future
    Major Tick 6:	00x backwards (=error!),	00x same time,	4920x future
    
    DONE!
    

    So, IMHO, this clearly shows that it's a Mono bug that was fixed between 1.9.1 and 2.4.2.1 (in 1.9.1 it still occured but I haven't tried any versions between those two because I think it doesn't really matter ;-) ).

    I've included my Visual Studio project - feel free to use this for testing or implementing a fix for the Mono-bug that throws off Photon's timing (actually, I think using Stopwatch is probably a "cleaner" approach than using Environment.TickCount anyways ... see e.g. Environment.TickCount vs DateTime.Now for some discussion on this).

    Switching Mono version on the Mac

    On my Mac, I now have a lot of different Mono versions and I also know how to easily switch the version (if multiple versions are installed; this is on the Mac, probably also under Linux - but under Linux the paths might be different):

    Go to the folder: /Library/Frameworks/Mono.framework/Versions

    There, you can list the installed version with the ls -l command (the "-l" option shows details - which is helpful because it'll show you where "Current" links).

    Then, you can simply overwrite the "Current" symlink with:
    rm Current
    ln -s 1.2.5 Current
    
    This assumes that you have 1.2.5 installed; and you have to be logged in as admin (which you can do with "su -").

    You can then check if it worked by:
    mono -V
    
  • Oh wait! :-( argh ... :-( ...

    a) Stopwatch resides in System.dll - so for Web players this means extra download size (unless they're using System.dll anyways). That's unpleasant - Environment lives in mscorlib.dll which is always included anyways (I think that's even already available from the Web player plugin).

    b) Stopwatch doesn't seem to exist in Unity iPhone. And even *if* it existed, it wouldn't be available to Unity iPhone Basic users as System.dll can only be used by Unity iPhone Advanced. There's probably a reason Stopwatch isn't available (or maybe I'm doing something wrong) ... I've checked back with UT on that.

    The good news: I can't reproduce the issue on the iPhone ... so for the iPhone, Environment.TickCount should do just fine ;-)
  • Thats the unpleasant fact I guess.
    But I think its better to have an unpleasant solution as no solution at all until Unity 3 will move up to the new mono.
  • jashan wrote:
    it wouldn't be available to Unity iPhone Basic users as System.dll can only be used by Unity iPhone Advanced. There's probably a reason Stopwatch isn't available (or maybe I'm doing something wrong) ... I've checked back with UT on that.
    Looking forward to hear an update on this from UT.

    The worst thing about this is that we are using TickCount internally in the lib when we receive a timestamp, so you can add it anytime. Switching (internally) to Stopwatch would have the negative impact described. Leaving TickCount in is also not the best idea as it could be the wrong time. Just adding (alternative) properties that use the Stopwatch will add System.dll as download if the Properties don't get stripped by Unity.

    My question: could you live with the workaround you have already? Or should we provide an alternative lib?
  • Tobias wrote:
    My question: could you live with the workaround you have already? Or should we provide an alternative lib?

    For me the workaround is fine. Now that we have the issue documented here it shouldn't be such a time investment for other developers that run across this problem.
  • Tobias wrote:
    My question: could you live with the workaround you have already? Or should we provide an alternative lib?

    Thats fine for me.
    As it is a matter of time until the workaround "returns to nirvana" I don't see a need for an alternative lib that then potentially is completely out of place
  • Tobias wrote:
    jashan wrote:
    it wouldn't be available to Unity iPhone Basic users as System.dll can only be used by Unity iPhone Advanced. There's probably a reason Stopwatch isn't available (or maybe I'm doing something wrong) ... I've checked back with UT on that.
    Looking forward to hear an update on this from UT.

    I'll post an update when I get an update. ;-)
    Tobias wrote:
    My question: could you live with the workaround you have already? Or should we provide an alternative lib?

    I think the workaround should be sufficient. One consideration might be to integrate the workaround into the lib so that other users don't run into it (might save some people some time and headaches), and I think it also shouldn't hurt (nevertheless, it could probably be removed once Mono 1.2.5 is finally history).

    However, keep in mind that Environment.TickCount also has this "49.8 day anomaly". This may create very sporadic bugs on servers (I doubt anyone ever runs into this on a client). On servers, using Stopwatch shouldn't create any disadvantages. But maybe you're not even using this in the server implementation anyways.

    I'm just mentioning this because it's the kind of thing that's really easy to fix when you run across it in the documentation or via code-review - but it might be really difficult to isolate this issue when you run into it as bug (takes about one and a half months before you even get a chance to reproduce it ;-) ).
  • Has anyone found a solution that works with webplayers?

    I struggled over it in the Photon 2 release and as diagnostics is a system level thing it wont work (pinvoke error)
  • Tobias
    Tobias admin
    edited August 2010
    I assume this the TickCount is buggy up to Unity 2.6.1. and there is just the workaround.
    Unity 3 uses a new Mono version and I can't reproduce this error there. Neither in OSX Webplayer, nor in iPhone or Windows.
    At least in the long run, this is fixed.

    Is anyone here in dire need of a fix for Unity 2.6.1?
  • indeed still 2.6.1 but I hoped that you potentially added some logic to prevent the server from providing data that is obivously bs ;)

    I added some logic to the event handling that will just kill out all that traveled in from the back of time.

    Not tested with u3 yet as the contract work is based on 2.6.1
  • As far as I understand, this is not a server issue but a Mono/OSx one and purely client side. The server is not affected.

    I edited my previous post: it's at least verified that Unity 3 WebPlayer in OSx does not have this bug anymore.
  • I'm aware that the root is in monos osx implementation, but the functionality and data is provided through the PhotonPeer, which is why I hoped that there is at least a failsafe solution now to cover for this problem :)

    But I'll hunt for a solution, likely a combination of last time caching and comparable failsafe logic :)

    thanks for your time tobias :)