Search Unity

GC.alloc called 8 million times

Discussion in 'Editor & General Support' started by mrCharli3, May 23, 2018.

  1. mrCharli3

    mrCharli3

    Joined:
    Mar 22, 2017
    Posts:
    976
    Was going through my profiler, and for some reason GC.alloc is called a ridiculous amount of times. According to profiler that is not even taking that long, but it feels really weird.



    As you can see, it originates with DefaultObjectSaver. Which is just a method that adds some data, it looks like this and is attached to every GameObject:

    Code (CSharp):
    1. private void Start()
    2.     {
    3.         EventManager.SaveWorldEvent += SaveFunction;
    4.     }
    5.  
    6.     private void OnDestroy()
    7.     {
    8.         EventManager.SaveWorldEvent -= SaveFunction;
    9.     }
    10.  
    11.     public void SaveFunction(object sender, EventArgs args)
    12.     {
    13.         SavedDefaultObject defaultObject = new SavedDefaultObject();
    14.         defaultObject.posX = transform.position.x;
    15.         defaultObject.posY = transform.position.y;
    16.         defaultObject.posZ = transform.position.z;
    17.         string replaced = gameObject.name.Replace("(Clone)", "");
    18.         defaultObject.gameObjectName = replaced;
    19.  
    20.         DataManager.instance.GetListForScene().savedDefaultObjects.Add(defaultObject);
    21.     }
    Am I missing something here? I mean this is called over 4000 times so I get that it takes 1400ms, but why is gc.alloc called so often?
     
  2. MartinTilo

    MartinTilo

    Unity Technologies

    Joined:
    Aug 16, 2017
    Posts:
    2,456
    Hi,
    Could you maybe deep profile this?

    I'm assuming EventManager.SaveWorldEvent is just declared as

    Code (CSharp):
    1. class EventManager
    2. {
    3.     public static DelegatType SaveWorldEvent;
    4. }
    and not as

    Code (CSharp):
    1. class EventManager
    2. {
    3.    
    4.     private static DelegatType saveWorldEvent
    5.     public static DelegatType SaveWorldEvent
    6.     {
    7.         add
    8.         {
    9.             //Some crazy logic here
    10.             saveWorldEvent+= value;
    11.         }
    12.         remove
    13.         {
    14.             saveWorldEvent -= value;
    15.         }
    16.     }
    17. }
    Registering an event does cause some allocations, as simply but, it is added to a list and that list might need to grow (there is some wrapping and joining happening as well iirc but the jist of it is, it allocates enough that I once implemented my own even lists so I could allocate the list once and registering and deregistering came allocation free)
    Now, registering one object, shouldn't cause this many allocations.

    If you have 8700740 DefaultObjectSaver MonoBehaviours (or anything inheriting from it) or nearly that number, then you've found the root of the problem. If the event list becomes this long, the list will grow like crazy and every growth is a reallocation and the memory has to be moved. (Also the above mentioned joining that is happening in events doesn't scale so nicely.)

    It could also be, that you're looking at the event being fired. When you assign a Method like that, it can happen that it will be automatically wrapped by the delegate type. When you debug, you could observe the event calling to first step into your Start method and then into your SaveFunction. It is therefore conceivable, that the Start() sample was somehow picked up in the wrapping delegate.
     
  3. MartinTilo

    MartinTilo

    Unity Technologies

    Joined:
    Aug 16, 2017
    Posts:
    2,456
  4. mrCharli3

    mrCharli3

    Joined:
    Mar 22, 2017
    Posts:
    976
    Thank you. I am trying to debug it with Deep profile, but as soon as I turn on deep profile, I can no longer find what I showed above. But it is there every time I just profile normally, not sure why that is.

    To answer your question I only have 4000-ish Objects with DefaultObjectSaver attached. So GC.alloc being called this much should not be happening as far as I can tell. It's not even from my SaveFuntion being called, it's just from these Start() being run.
     
  5. MartinTilo

    MartinTilo

    Unity Technologies

    Joined:
    Aug 16, 2017
    Posts:
    2,456
    When deep profiling, can you use the searchbar to search for your Start method, the save function, GC.Alloc and the event? If any of those are still present but just somewhere else, please take a screenshot of that (ideally with the searched cleared) and post it here. You could also save out your profiling data with the save button so I can have a look. You can PM me if you don't want or are not allowed to post this file publicly. (Not sure how much one could read out of that file but who knows, maybe there are some telling method names ;))
     
    mrCharli3 likes this.
  6. mrCharli3

    mrCharli3

    Joined:
    Mar 22, 2017
    Posts:
    976
    Since I cannot find any of it when I'm doing a deep profile (even when searching) Ill just send it to you (apparently you cannot attach .data files here, or they are too large).

    EDIT: apparently I cannot send them to you in PM either, says its too large. Surprisingly they are actually 200MB, seems really large.
     
  7. MartinTilo

    MartinTilo

    Unity Technologies

    Joined:
    Aug 16, 2017
    Posts:
    2,456
    Have you tried placing a CustomSampler with begin() and end() in your start and a different one in your SaveFunction? With these, you should be able to search for them and scrub over the frames to find it.

    Regarding the filesize: yes, it's a lot of data and the reason why we only store up to 300 frames. You could clear the profiling data before the moment that triggers the Start() and pause right after, then save. That should trim the file size a bit. Additionally, the files can be compressed rather well, so you could zip or 7zip it.
     
    mrCharli3 likes this.
  8. mrCharli3

    mrCharli3

    Joined:
    Mar 22, 2017
    Posts:
    976
    To be fair I'm no profiling expert but even with CustomSampler it just does not show up when deep profiling. I can't imagine I'm doing something wrong, not many places you can go wrong here. Quite confusing. I'll zip and send logs in a bit. Thanks for your help.

    EDIT: Attaching logs
     

    Attached Files:

  9. Whatever560

    Whatever560

    Joined:
    Jan 5, 2016
    Posts:
    518
    Hi, do you have any follow up on this ? I also have GC.Alloc called hundred of thousands of time in some of my coroutines.
     
  10. MartinTilo

    MartinTilo

    Unity Technologies

    Joined:
    Aug 16, 2017
    Posts:
    2,456
    Hi,
    Sorry for the delayed reply.

    So the issue here is with the way c# events work. They are multicast delegates and every time you add another listener, it throws it into the mix which produces GC.Allocs that get worse the more listeners there are. One solution is to write an EventList class where you subscribe your delegates in a list of listeners that you manage yourself. Then you can just preallocate that list to a reasonable size to avoid costly resizes as you add listeners.

    The reason you can't see the sample in deep profiling is because the frame it would show up in is so heavy, that the profiler runs out of buffer space while collecting samples for it. We're in the process of fixing this though.

    I can't reproduce the .Start() sample appearing underneath a coroutine sample, though. Are you loading a scene/ instantiating the objects from within a coroutine?

    What Unity version are you using? I'm assuming 2017.x?

    @Whatever560 you're issue is likely unrelated so it'd be good if you can share the code of those coroutines.
     
  11. Whatever560

    Whatever560

    Joined:
    Jan 5, 2016
    Posts:
    518
    @MartinTilo It was unlikely unrelated indeed. I just wanted to know if he had found some ways to debug these calls. I was hinted that doing a deep profile in the profiler allowed to debug codes in coroutines. I managed to resolve my issue.
     
  12. dumoulinantoine

    dumoulinantoine

    Joined:
    Jun 10, 2021
    Posts:
    2
    I actually encountered this issue in 2019.4.
    upload_2021-6-10_16-48-22.png
    I'm not sure if it's related, but as it happens on mouse pressed, it could actually be linked to Events.