Debug.Log fixes my script?

This is one of those 'back magic' times, but I have a script which suddenly stopped working. When I put in a couple of Debug.Log lines to see where it was stopping, it started working again. I finally have it down to two such lines which make it work, but I have no idea why they make it work.

I wondered if it were to do with delaying the execution of a later line, but I can't see anything which would cause that. Anyone know of something that could do this?

Code (csharp):

1.     // Update is called once per frame
2.     void Update ()
3.     {
4.         Debug.Log("Black magic A");
5.  
6.         if ((gameObject.transform.position.y != 0) || ((gameObject.transform.position.x > screenMax_X) && (gameObject.transform.position.x < screenMin_X)))
7.         {
8.             leftArrow.SetActive(false);
9.             rightArrow.SetActive(false);
10.             return;
11.         }
12.  
13.         if (gameObject.transform.position.x > screenMin_X)
14.             leftArrow.SetActive(true);
15.         if (gameObject.transform.position.x < screenMax_X)
16.             rightArrow.SetActive(true);
17.        
18.         if ((gameObject.transform.position.x == screenMax_X) && (scrollDirection == direction.right))
19.             rightArrow.SetActive(false);
20.         else if ((gameObject.transform.position.x == screenMin_X) && (scrollDirection == direction.left))
21.             leftArrow.SetActive(false);
22.         else if (gameObject.transform.position.x > screenMax_X)
23.             gameObject.transform.Translate(screenMax_X - gameObject.transform.position.x, 0, 0);
24.         else if (gameObject.transform.position.x < screenMin_X)
25.             gameObject.transform.Translate(screenMin_X - gameObject.transform.position.x, 0, 0);
26.         else
27.             gameObject.transform.Translate(10 * (int)scrollDirection * Time.deltaTime, 0, 0);
28.  
29.         Debug.Log("Black magic B");
30.  
31.         if (scrollDirection != direction.none)
32.         {
33.             //  Check which room we are in and display the correct name
34.             if ((gameObject.transform.position.x > currentRoom.max) || (gameObject.transform.position.x < currentRoom.min))
35.                 currentRoom = toolbox.currentRoom(gameObject.transform.position.x);
36.  
37.             roomName.text = currentRoom.name;
38.         }
39.     }

 

The behaviour without the Debug.Log lines is that if (gameObject.transform.position.x == screenMax_X) is true, nothing here runs. In theory, it's acting like (scrollDirection == direction.right) is always true, even when I can clearly see it is not, though considering the 'fix' here, that's not going to make much sense.

It's not even acting like (gameObject.transform.position.x == screenMax_X) && (scrollDirection == direction.right) is true though, since it's not running the line below this if statement.

 

With debug printing changing behaviour it very much looks like some sort of race condition.

I'd break up the logic into excessively small elements just to be damn sure it's correct. It's just past noon in the morning here, so I can't brain much yet, but I'd cache the transform early on and only reference the original when setting it, then insert returns where the logic dictates it can't expect more changes this frame (rearranging the order of conditionals if necessary).

Also use curly braces around every block of logic. There are rather famous, serious bugs caused by people using shorthand (see a certain SSL bug recently). Very explicit, verbose code can reveal logic errors.

 

That was my first thought as well. Unity uses a single thread for the handling of the Update method (or rather, it guarantees that only one thread is executing an Update function at time) . It does not say so in the script reference, however from my experience, it seems as though there is a yield in the Debug.Log functions, enabling the execution of code that is not waiting for I/O, as Debug.Log definitely is.

One thing you could do, is move this code to LateUpdate. That way it is guaranteed to be executed after all the other code with which there might be a race condition.

 

Yeah, my first thought was a race condition and Debug.Log delaying execution just long enough, but the actual issue is even more confusing. I used the Visual Studio debugger and it's mind-boggling...

For reasons beyond my comprehension, running Debug.Log in those places somehow affects the rounding of two values...

Without those lines, there's a rounding error which both prevents (gameObject.transform.position.x == screenMax_X) from being true and yet is so insignificant that "screenMax_X - gameObject.transform.position.x" seems to evaluate to zero.

Add in those Debug.Log lines and the rounding error goes away...

I tried explicitly defining the value as follows...

Code (csharp):

1. if (gameObject.transform.position.x > screenMax_X)
2.         {
3.             Vector3 newPosition = new Vector3(screenMax_X, gameObject.transform.position.y, gameObject.transform.position.z);
4.             gameObject.transform.position = newPosition;
5.         }

That still doesn't work for some reason. The debugger even helpfully tells me that the position.x is "17.1741314f" one frame after being set to "17.17413f" unless I run two lines which do nothing I can see beyond printing a string to the console.

Bizarre...

 

The fix, of course, was to round to 2 decimal places and leave the philosophy to other people...

 

The lesson here is: Don't compare float values for equality

http://docs.unity3d.com/ScriptReference/Mathf.Approximately.html

 

But why does Debug.Log make it work?

Very interested in Mathf.Approximately now that I know about it. This is why you shouldn't ask designers to do the coding; we do things like comparing floats without thinking about precision errors...

 

Probably completely coincidental

 

Yeah, I know. I'm 99% sure it's just a bizarre coincidence, but that's the boring answer.

 

That's another vote for race-condition. Depending on the version of VS and the Unity tools, logging performance can be terrible (Debug.Log also goes to the VS error window -- can't be turned off without adding an editor script in tools 2.0 but the current tools gives you an option).