Profiling shows that one of many instances has an Update that takes way more time than the others

Hi,
I have a Unity game running on iPhone. I’m doing profiling at the moment and I’m seeing something strange. I have 20 instances of a Block object (custom MonoBehaviour). I see that the Update function takes quite a lot of time (something like 20-30ms). When I click on the line to see the per-object breakdown, I can see that the first instance in that list takes almost all these 20-30ms and I wonder why because there’s no clear explanation of this, no special cases that would explain this. When that happens (it’s quite often in the profile record) it’s always the first instance shown that takes that much time…

has anyone encountered this before ? Could it just be a side effect of using profiling (I don’t have any Profiler.BeginSample in this Update function has they proved the problem was not coming from the function itself)

Another thing is that in the breakdown list, the objects “names” are not shown, I have a nice N/A in front of each line, which prevents me from seeing which actual object could be causing this. Is it impossible to have the objects names when profiling iPhone ?

If you need clarifications on some of the points I’ve described, don’t hesitate.
Thanks in advance for your time !

I can’t say that I know the exact ins-and-outs of this, but this will have something to do with the way Unity caches objects. It’s a very common thing to see that multiple instances of the same class take the longest to run something the first time they are called during each runloop (this is usually mostly noticeable when instantiating but happens elsewhere too), but after that they take a lot longer. Are you able to paste in or at least describe what your Block object is doing during its Update()? If we can see the code for that it might give us some idea as to why it is happening in that specific situation. It could be something simple like a GetComponent that the first time it’s called during that one runloop it runs normally then in subsequent calls it’s faster because it has been cached, things like that… Although I’m not sure, actually, whether or not GetComponent does get cached, but it’s an example of something that Unity may be speeding up internally.

It’s not abnormal behaviour, though. It’s something you will see all the time. If it is slowing down your framerate noticeably, though, it may be worth splitting the method down into multiple passes (say, a coroutine that runs over multiple frames) if possible to lower the time it takes on its non-cached run.

I did some sample tests this afternoon, and this is what I get for example :
[1107-Capture+d’écran+2012-06-02+à+21.15.34.png|1107]

As you asked, this is the corresponding Update code in Block :

void Update(){

	Profiler.BeginSample("Block_"+id);
	
	
	if(creationDelay <= 0){
		Profiler.BeginSample("Enabling renderer");
		gameObject.renderer.enabled = true;
		creationDelay = 0;
		Profiler.EndSample();
	}
		
	if(visible && creationDelay == 0){ // normalement c'est useless
		
		Profiler.BeginSample("processScroll");
		processScroll();
		Profiler.EndSample();
		
		if(state == FALL){
			speed -= 0.03f;
			y += speed * Time.deltaTime;
			
			Profiler.BeginSample("testToKill");
			if(y < -radius){
				Profiler.BeginSample("Kill");
				kill();
				Profiler.EndSample();
			}
			Profiler.EndSample();
			
		}else{
			
			Profiler.BeginSample("State change test");
			if(type == BLOC){
				if(sprite.clipId == idleAnimId){
					if(state == CREATE){
						state = IDLE;
					}
				}
			}
			Profiler.EndSample();
			
			if(waitDamage > 0)	waitDamage -= Time.deltaTime;
			
			Profiler.BeginSample("Test Bounds");
			if(transform.collider.bounds.Intersects(god.player.transform.collider.bounds))
			{
				//Debug.Log("block "+id+" colliding with avatar after scrolling (avatar speed y: "+god.player.physic.speed.y+")");
				Profiler.BeginSample("CancelLastMove");
				god.player.physic.cancelLastMove(wasCollidingPreviousFrame);
				Profiler.EndSample();
				
				god.player.physic.speed.y = 0;
				wasCollidingPreviousFrame = true;
			}else{
				wasCollidingPreviousFrame = false;
			}
			Profiler.EndSample();
		}
	}
	creationDelay -= Time.deltaTime;
	
	Profiler.EndSample();
}

So there’s two behaviours I see in the profiling :

  1. updates that takes quite a lot outside themselves (can really seem to be able to track down where…)
  2. updates that takes almost all the time in themselves but not in the code portions I profiled which should be tracking the entire function.

Thank you for the insight about the caching and I think I’m gonna take another approach and maybe it will be coroutines, if it can be applied to this special case…