AIRig.Update - Loading.ReadObject calls' increasing tax on framerate

[SaurianParticipant]

I’ve been encountering runtime problems with the AIRig Update function calling ‘Loading.ReadObject’ (and Loading.FindInThreadedActivationQueue’) with increasing frequency. I’ve been trying to figure out why it’s happening, but am totally stumped. I’ve found some patterns in its increases, though I’m not sure how to make sense of them.
At first, the number of Loading.ReadObject calls is roughly equal to the # of AI in the scene x 3 x # of times Instantiate/Destroy has been called on an AI (for despawn/respawning; I know I should be object pooling ideally, but for my current purposes Instantiate/Destroy is much more preferable).
Here is a profiler screenshot after one Instantiate/Destroy, with 50 AI total in the scene (50 x 3 x 1):

And after two (50 x 3 x 2):

And after roughly 150 (50 x 3 x 170):

I emphasize “roughly” above because, after a while, the number of de/re-spawns no longer matches the result of dividing the number of calls by (# of AI x 3), though the result is still a whole number:

I am pretty baffled by this, although even more baffled by how consistent it seems. There are frames when the number of calls isn’t divisible by (# AI x 3), although these situations are usually right after an AI has been destroyed and before another has been instantiated. As to where the number 3 comes from, my only hunch is that may have to do with the three visual sensors I’m using in my behavior tree:

I checked the API for the Update method in AIRig, but it didn’t give me any clues. Clearly it seems like some AI component, either rigs / sensors / entities aren’t being removed from the scene correctly, but I am a bit stumped and am not quite sure where I should be searching for the solution to this bug. I’ve been thinking I should write a custom visual sensor that checks for all three desired aspects in one MatchAspectName call rather than 3 separate ones, although I’d imagine that would simply make reduce the coefficient from 3 to 1, which is an improvement but not a solution.

Any help is greatly appreciated, thank you!

[SigilKeymaster]

So I was trying to create a test for this and I was unable to reproduce the problem. That doesn’t mean anything in particular, just makes it a little harder on us.

Some general info: Loading.ReadObject seems to be something internal to Unity as there aren’t any functions like that in RAIN, and I can’t find any in Unity. It does seem to popup for some people out there when loading levels and assets, but that isn’t particular to RAIN though. Most performance problems tend to show up under AIRig.Update due to the fact that we do pretty much everything within that Update (movement, behavior, all the custom actions, raycasting for sensors, etc). That doesn’t really help you though, so here are a few ideas to try to hunt down the problem:

Disable line of sight on the visual sensors (only mentioning that because RaycastAll was also showing up in the profiler).
Try profiling in a standalone build and see if the calls change, a few people mentioned they only had issues in the editor (instructions here).
Some people mentioned materials, so if you have any custom material/shader code in a custom action or custom AI element, perhaps comment it out real quick.
Add Profiler BeginSample/EndSample statements to any custom actions or custom AI elements, to see if the ReadObject is happening there.

You can also talk to jester@rivaltheory.com and send us a sample project with the problem, or the entire project if need be, and I can take a look at it for you.

[SaurianParticipant]

Thank you so much for the fast, thorough response! I’ll do some experiments with Profiler sampling and see if I can’t find the culprit (and post it here, of course); otherwise I’ll send you an e-mail soon.

[SaurianParticipant]

I think I found the reason why it’s happening — aspects aren’t being properly unregistered from the SensorManager even though their parent GameObjects have been destroyed. It’s strange, I added the following code

RAIN.Entities.Aspects.RAINAspect a = g.GetComponentInChildren<EntityRig>().Entity.Aspects[0];
				Debug.Log ("Attempting to despawn " + a.AspectName + " aspect with type " + a.AspectType);
				Debug.Log ("SensorManager contains aspect "+ RAIN.Perception.Sensors.SensorManager.Instance.GetAspects(a.AspectType).Contains(a).ToString());
				RAIN.Perception.Sensors.SensorManager.Instance.Unregister(a, a.AspectType);
				Debug.Log ("SensorManager contains aspect "+ RAIN.Perception.Sensors.SensorManager.Instance.GetAspects(a.AspectType).Contains(a).ToString());

To verify that aspects are being unregistered, and the final debug line confirms that they are. However, in an Update call I check the size of SensorManager.Instance.GetAspects(“visual”) and it’s continually increasing, and in an OnApplicationQuit call from a different script I run this code:

foreach(RAIN.Entities.Aspects.RAINAspect a in RAIN.Perception.Sensors.SensorManager.Instance.GetAspects("visual")){
				Debug.Log (a.AspectName + " " + a.Entity.Form.ToString() + " " + a.Entity.Form.activeSelf.ToString() + a.Entity.Form.activeInHierarchy.ToString());
			}

which, as I suspected, prints a small number of logs correctly before throwing “MissingReferenceException: The object of type ‘GameObject’ has been destroyed but you are still trying to access it.”

Still investigating…

[SigilKeymaster]

Well aspects failing to unregister would definitely cause a slowdown after awhile (not sure if it is the same as the ReadObject issue, but perhaps they are related). In the normal run of things, when OnAwake is called the Entity will register any aspects with the sensor manager, and when OnDestroy is called they will be unregistered.

The only exceptions I can think of is if the Entity is not active (Is Active in the advanced tab). If that value is changed in the editor while playing it is possible things would get out of sync, but that’s a very particular case.

I will run some tests and see if I can replicate and find that particular problem.

[SigilKeymaster]

Alright, so after testing I still can’t seem to replicate this problem. My tests were just of normal instancing, calling AddAspect, RemoveAspect, and destroying (I can post the code). In all of my cases the aspects were properly being registered and unregistered. I could not get the “still trying to access” error at all though, although I couldn’t really test for it, and that definitely indicates a registered aspect that has a Form that was destroyed.

The only way I can think of an Entity getting into that kind of state (where the Form is destroyed but the aspects are still registered) is if the Entity is no longer parented to the Form it is pointing at.

[SaurianParticipant]

I’ll leave the debug lines in and send the project to jester@rivaltheory.com

[SigilKeymaster]

Didn’t even think to ask what version of RAIN you are using. There was an issue with an earlier version of RAIN, probably around 2.1.3.0, that failed to unregister aspects in OnDestroy, the call was just not there. Seems this version also has issues checking for updates, as that was not working for me either.

Sorry about all that, no red flags came up while we were talking and I failed to remember the sensor bug. I dropped an older (2.1.5.0) but still newer version of RAIN in and the Aspect count issue went away, the AI seemed no worse for the upgrade either.

A few options:

Workaround the issue and manually unregister all of the aspects before it gets destroyed. You could make a small component script to attach to any Entity, or handle it in your Spawner.

You could upgrade all the way to the latest version which we released today on the site (2.1.8.0) but you’d have to overhaul your CustomVisualSensor a bit to use the new system. We’ve deprecated filters in their current form, although they will still work right now, and setup a simpler way to create custom sensors, which can replicate the filtering you need at that point. Prime might have to jump in for the particulars on that though, as I am still unfamiliar with the latest changes.

If need be we can also get you an intermediary build, something after 2.1.3.0, although if you can bring the project up to the latest I’d recommend it, just for the bug fixes.

[SaurianParticipant]

Ah, that’s great news, I’ll update immediately; thanks!
(I wasn’t using that Custom Visual Sensor, that was just practice, so it shouldn’t be a problem.)
I’ll write back here if I run into any more problems.

[SigilKeymaster]

Should also say, I did manage to bring the project up to the latest 2.1.8.0 version. I did have to mess with the CustomVisualSensor to get it to completely compile, but after that everything seemed to work. I don’t know all of the subtleties of your project though.

[Author]

Posts