Unity may lose frames in stacktrace: tests

I noticed that sometimes unity misses frames when crash occurs. So I decided to read code and do some tests.


Internally, Unity catches crashes and logs them using Debug.LogException as you will see below. I described how it works in previous article

Suppose code:

public class SomeCrashingScript : MonoBehaviour
{
    public SomeOtherCrashingScript otherScript;

    // button click listener
    public void Crash1()
    {
        A();
    }

    private void A()
    {
        B();
    }

    private void B()
    {
        int[] elements = new int[5];
        int b = elements[2];
        string stackTrace = new StackTrace(0, true).ToString();
        UiLogger.Trace("stackTrace:\n" + stackTrace);
        int c = b + elements[6]; // IndexOutOfRangeException here
        int d = c + elements[1];
    }
}

Output:

stackTrace:
   at SomeCrashingScript.B() in C:\Playroom\UnityProjects\playunity\RxTest\Assets\Game\InternalApi\Crash\SomeCrashingScript.cs:line 24
   at SomeCrashingScript.A() in C:\Playroom\UnityProjects\playunity\RxTest\Assets\Game\InternalApi\Crash\SomeCrashingScript.cs:line 17
   at SomeCrashingScript.Crash1() in C:\Playroom\UnityProjects\playunity\RxTest\Assets\Game\InternalApi\Crash\SomeCrashingScript.cs:line 12
   at UnityEngine.Events.InvokableCall.Invoke(System.Object[] args) in C:\buildslave\unity\build\Runtime\Export\UnityEvent.cs:line 153
   at UnityEngine.Events.InvokableCallList.Invoke(System.Object[] parameters) in C:\buildslave\unity\build\Runtime\Export\UnityEvent.cs:line 634
   at UnityEngine.Events.UnityEventBase.Invoke(System.Object[] parameters) in C:\buildslave\unity\build\Runtime\Export\UnityEvent.cs:line 769
   at UnityEngine.Events.UnityEvent.Invoke() in C:\buildslave\unity\build\Runtime\Export\UnityEvent_0.cs:line 53
   at UnityEngine.UI.Button.Press() in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\UI\Core\Button.cs:line 35
   at UnityEngine.UI.Button.OnPointerClick(UnityEngine.EventSystems.PointerEventData eventData) in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\UI\Core\Button.cs:line 44
   at UnityEngine.EventSystems.ExecuteEvents.Execute(IPointerClickHandler handler, UnityEngine.EventSystems.BaseEventData eventData) in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\ExecuteEvents.cs:line 52
   at UnityEngine.EventSystems.ExecuteEvents.Execute(UnityEngine.GameObject target, UnityEngine.EventSystems.BaseEventData eventData, UnityEngine.EventSystems.EventFunction`1 functor) in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\ExecuteEvents.cs:line 269
   at UnityEngine.EventSystems.StandaloneInputModule.ProcessMousePress(UnityEngine.EventSystems.MouseButtonEventData data) in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\InputModules\StandaloneInputModule.cs:line 531
   at UnityEngine.EventSystems.StandaloneInputModule.ProcessMouseEvent(Int32 id) in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\InputModules\StandaloneInputModule.cs:line 430
   at UnityEngine.EventSystems.StandaloneInputModule.ProcessMouseEvent() in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\InputModules\StandaloneInputModule.cs:line 410
   at UnityEngine.EventSystems.StandaloneInputModule.Process() in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\InputModules\StandaloneInputModule.cs:line 184
   at UnityEngine.EventSystems.EventSystem.Update() in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\EventSystem.cs:line 287

And that's the info Unity gives us about exception:

OnLogMessageReceived
condition: IndexOutOfRangeException: Array index is out of range.
stacktrace:
SomeCrashingScript.B () (at Assets/Game/InternalApi/Crash/SomeCrashingScript.cs:26)
SomeCrashingScript.A () (at Assets/Game/InternalApi/Crash/SomeCrashingScript.cs:17)
SomeCrashingScript.Crash1 () (at Assets/Game/InternalApi/Crash/SomeCrashingScript.cs:12)
UnityEngine.Events.InvokableCall.Invoke (System.Object[] args) (at C:/buildslave/unity/build/Runtime/Export/UnityEvent.cs:153)
UnityEngine.Events.InvokableCallList.Invoke (System.Object[] parameters) (at C:/buildslave/unity/build/Runtime/Export/UnityEvent.cs:634)
UnityEngine.Events.UnityEventBase.Invoke (System.Object[] parameters) (at C:/buildslave/unity/build/Runtime/Export/UnityEvent.cs:769)
UnityEngine.Events.UnityEvent.Invoke () (at C:/buildslave/unity/build/Runtime/Export/UnityEvent_0.cs:53)
UnityEngine.UI.Button.Press () (at C:/buildslave/unity/build/Extensions/guisystem/UnityEngine.UI/UI/Core/Button.cs:35)
UnityEngine.UI.Button.OnPointerClick (UnityEngine.EventSystems.PointerEventData eventData) (at C:/buildslave/unity/build/Extensions/guisystem/UnityEngine.UI/UI/Core/Button.cs:44)
UnityEngine.EventSystems.ExecuteEvents.Execute (IPointerClickHandler handler, UnityEngine.EventSystems.BaseEventData eventData) (at C:/buildslave/unity/build/Extensions/guisystem/UnityEngine.UI/EventSystem/ExecuteEvents.cs:52)
UnityEngine.EventSystems.ExecuteEvents.Execute[IPointerClickHandler] (UnityEngine.GameObject target, UnityEngine.EventSystems.BaseEventData eventData, UnityEngine.EventSystems.EventFunction`1 functor) (at C:/buildslave/unity/build/Extensions/guisystem/UnityEngine.UI/EventSystem/ExecuteEvents.cs:269)
UnityEngine.EventSystems.EventSystem:Update()

type: Exception

As you see, Unity's stack is 4 frames shorter - there are no calls between ExecuteEvents.Execute and EventSystem.Update(). Let's see the code of ExecuteEvents.Execute:

static class ExecuteEvents
{
 public static bool Execute<T>(GameObject target, BaseEventData eventData, EventFunction<T> functor) where T : IEventSystemHandler
 {
     var internalHandlers = s_HandlerListPool.Get();
     GetEventList<T>(target, internalHandlers);

     for (var i = 0; i < internalHandlers.Count; i++)
     {
         T arg;
         try
         {
             arg = (T)internalHandlers[i];
         }
         catch (Exception e)
         {
             var temp = internalHandlers[i];
             Debug.LogException(new Exception(string.Format("Type {0} expected {1} received.", typeof(T).Name, temp.GetType().Name), e));
             continue;
         }

         try
         {
             functor(arg, eventData);
         }
         catch (Exception e)
         {
             Debug.LogException(e);
         }
     }

     var handlerCount = internalHandlers.Count;
     s_HandlerListPool.Release(internalHandlers);
     return handlerCount > 0;
 }
}

As you see, Unity catches our exception occured in SomeCrashingScript.B() and calls Debug.LogException() on it. And we know that e.stackTrace will contain only the calls between the throw and catch sites. It's between SomeCrashingScript.B and ExecuteEvents.Execute. And we know that Unity's Debug.LogException may add some parent frames. Here we see, that it adds only EventSystem:Update and misses all 4 StandaloneInputModule frames.

In conclusion, Unity internally catches exceptions and logs them with Debug.LogException. So, we do have all frames between throw and catch sites, but may miss frames that are parent to method, with Debug.LogException call.

Note, that because of C#'s method inlining  stack may not contain methods, that you have in code.

By the way, if exception not caght in ExecuteEvents.Execute, it will still be logged. For example, if we make a dirty hack and replace UnityEngine.Debug.logger with null:

var field = typeof(UnityEngine.Debug).GetField("s_Logger", BindingFlags.Static | BindingFlags.NonPublic);
field.SetValue(null, null);

We will still get exception logged through Unity's Application.logMessageReceivedThreaded:

OnLogMessageReceived
condition: NullReferenceException: Object reference not set to an instance of an object
stacktrace:
UnityEngine.Debug.LogException (System.Exception exception) (at C:/buildslave/unity/build/artifacts/generated/common/runtime/DebugBindings.gen.cs:146)
UnityEngine.EventSystems.ExecuteEvents.Execute[IPointerClickHandler] (UnityEngine.GameObject target, UnityEngine.EventSystems.BaseEventData eventData, UnityEngine.EventSystems.EventFunction`1 functor) (at C:/buildslave/unity/build/Extensions/guisystem/UnityEngine.UI/EventSystem/ExecuteEvents.cs:273)
UnityEngine.EventSystems.StandaloneInputModule.ProcessMousePress (UnityEngine.EventSystems.MouseButtonEventData data) (at C:/buildslave/unity/build/Extensions/guisystem/UnityEngine.UI/EventSystem/InputModules/StandaloneInputModule.cs:531)
UnityEngine.EventSystems.StandaloneInputModule.ProcessMouseEvent (Int32 id) (at C:/buildslave/unity/build/Extensions/guisystem/UnityEngine.UI/EventSystem/InputModules/StandaloneInputModule.cs:430)
UnityEngine.EventSystems.StandaloneInputModule.ProcessMouseEvent () (at C:/buildslave/unity/build/Extensions/guisystem/UnityEngine.UI/EventSystem/InputModules/StandaloneInputModule.cs:410)
UnityEngine.EventSystems.StandaloneInputModule.Process () (at C:/buildslave/unity/build/Extensions/guisystem/UnityEngine.UI/EventSystem/InputModules/StandaloneInputModule.cs:184)
UnityEngine.EventSystems.EventSystem.Update () (at C:/buildslave/unity/build/Extensions/guisystem/UnityEngine.UI/EventSystem/EventSystem.cs:287)

type: Exception

So, in conclusion, not only Debug.LogException is used in Unity framework when logging catched exceptions.

Will set a breakpoint in Application.logMessageReceivedThreaded callback method to find out how it is logged using stacktrace:

Void UnityCrashesReporter:OnLogMessageReceivedThreaded (String, String, LogType)+0x1 at C:\Playroom\UnityProjects\playunity\RxTest\Assets\Plugins\DeepTest\InternalApi\UnityCrashesReporter.cs:43 C#
Void UnityEngine.Application:CallLogCallback (String, String, LogType, Boolean)+0x2e at C:\buildslave\unity\build\artifacts\generated\common\runtime\ApplicationBindings.gen.cs:468 C#

We see, that it is called by Application.CallLogCallback, which have an attribute [RequiredByNativeCode] meaning, so looks like that code is called from c++ code.

Note: tests were done in editor and android-release 4.4.2 (of course on android we have one difference - there were no file info, it's release without debug info after all)