Search Unity

  1. We are migrating the Unity Forums to Unity Discussions. On July 12, the Unity Forums will become read-only.

    Please, do not make any changes to your username or email addresses at id.unity.com during this transition time.

    It's still possible to reply to existing private message conversations during the migration, but any new replies you post will be missing after the main migration is complete. We'll do our best to migrate these messages in a follow-up step.

    On July 15, Unity Discussions will become read-only until July 18, when the new design and the migrated forum contents will go live.


    Read our full announcement for more information and let us know if you have any questions.

Debug.Log Stacktrace Spam

Discussion in 'Editor & General Support' started by MrLucid72, Aug 24, 2017.

  1. Julien-Lynge

    Julien-Lynge

    Joined:
    Nov 5, 2010
    Posts:
    146
    Oh, and another absolutely minor request: Can you modify StackTraceUtility.ExtractStackTrace() to accept an optional skipFrames argument? E.g.:
    Code (CSharp):
    1.  
    2.     [SecuritySafeCritical]
    3.     [RequiredByNativeCode]
    4.     public static string ExtractStackTrace(int skipFrames = 1)
    5.     {
    6.         StackTrace stackTrace = new StackTrace(skipFrames, fNeedFileInfo: true);
    7.         return ExtractFormattedStackTrace(stackTrace).ToString();
    8.     }
     
    rarepop99 likes this.
  2. Julien-Lynge

    Julien-Lynge

    Joined:
    Nov 5, 2010
    Posts:
    146
    And last but not least, here's an example of how you can override the default Debug.Log (if you wanted to add your own filtering or decoration logic) and get the stack trace you want. As stated above, you can click on the script references in the Console to go to the appropriate line of code (at least as I've tested in 2019). However, you can't double click on the message itself to go to the first line of code. Almost there!

    To use: just call Debug.Log() as you normally would. Instead of using UnityEngine.Debug.Log, it will use this version instead.

    Code (CSharp):
    1. using System;
    2. using System.Diagnostics;
    3. using System.Globalization;
    4. using System.Reflection;
    5. using UnityEngine;
    6.  
    7. namespace [YourNamespace]
    8. {
    9.     public class Debug : UnityEngine.Debug
    10.     {
    11.         private static (ILogHandler logHandler, MethodInfo method) internalLog = default;
    12.  
    13.         static Debug()
    14.         {
    15.             Type stackTraceType = typeof(StackTraceUtility);
    16.             var extractFormattedStackTrace = stackTraceType.GetMethod("ExtractFormattedStackTrace", System.Reflection.BindingFlags.Static | System.Reflection.BindingFlags.Public | System.Reflection.BindingFlags.NonPublic);
    17.             ExtractFormattedStackTrace = (skipFrames) =>
    18.             {
    19.                 StackTrace stackTrace = new StackTrace(skipFrames, fNeedFileInfo: true);
    20.                 return extractFormattedStackTrace.Invoke(null, new object[] { stackTrace }) as string;
    21.             };
    22.         }
    23.  
    24.         private delegate string GenericReturnDelegate(int skipFrames);
    25.         private static readonly GenericReturnDelegate ExtractFormattedStackTrace = null;
    26.  
    27.         private static ILogger Logger
    28.         {
    29.             get { return UnityEngine.Debug.unityLogger; }
    30.         }
    31.  
    32.         private static ILogHandler LogHandler
    33.         {
    34.             get { return Logger.logHandler; }
    35.         }
    36.  
    37.         public static new void Log(object message, UnityEngine.Object context = null)
    38.         {
    39.             if (Logger.IsLogTypeAllowed(LogType.Log))
    40.             {
    41.                 string formattedMessagePlusStackTrace = GetString(message);
    42.                 formattedMessagePlusStackTrace += "\n" + ExtractFormattedStackTrace(2);
    43.                 CallInternalLogForCurrentLogger(LogType.Log, formattedMessagePlusStackTrace, context);
    44.             }
    45.         }
    46.  
    47.         private static void CallInternalLogForCurrentLogger(LogType logType, string message, UnityEngine.Object context)
    48.         {
    49.             if (internalLog.logHandler != LogHandler)
    50.             {
    51.                 Type type = LogHandler.GetType();
    52.                 var method = type.GetMethod("Internal_Log", System.Reflection.BindingFlags.Static | System.Reflection.BindingFlags.Public | System.Reflection.BindingFlags.NonPublic);
    53.                 internalLog = (LogHandler, method);
    54.             }
    55.  
    56.             internalLog.method.Invoke(null, new object[] { LogType.Log, LogOption.NoStacktrace, message, context });
    57.         }
    58.  
    59.         //Pulled from UnityEngine.CoreModule
    60.         private static string GetString(object message)
    61.         {
    62.             if (message == null)
    63.             {
    64.                 return "Null";
    65.             }
    66.             IFormattable formattable = message as IFormattable;
    67.             if (formattable != null)
    68.             {
    69.                 return formattable.ToString(null, CultureInfo.InvariantCulture);
    70.             }
    71.             return message.ToString();
    72.         }
    73.     }
    74. }
    75.  
     
    Last edited: Jun 25, 2020
  3. rarepop99

    rarepop99

    Unity Technologies

    Joined:
    Sep 5, 2019
    Posts:
    54
    @Julien-Lynge - What you mentioned makes a lot of sense and I will consider it for a future feature/change in this area :)
     
  4. cgrow67

    cgrow67

    Joined:
    May 31, 2016
    Posts:
    52
    The problem with Unity's logs is that they build a stack trace which uses Reflection and Reflection is very slow. Therefore we will use Debug.LogFormat and pass the LogOption.NoStacktrace to prevent this.

    So, now we all say thank you to Roslyn.
    If your using Roslyn you can write debug wrapper like this.

    Code (CSharp):
    1.  
    2.     public static class Logger
    3.     {
    4.         // usage : Logger.Log("Something Happened");
    5.         //            : Logger.Log($" Log some variable { i }");
    6.         //
    7.         public static void Log(string msg, [CallerMemberName] string methodName = null, [CallerFilePath] string fileName = null, [CallerLineNumber] int lineNo = -1)
    8.         {
    9.             msg= $"{fileName},{methodName},{lineNo},{msg??"NULL"}");
    10.             UnityEngine.Debug.LogFormat( LogType.Log, LogOption.NoStacktrace, null, "{0}", msg ?? "NULL" );
    11.         }
    12.     }
    Sadly, in 2020.1 LogFormat requires a format string.
    The Attributes parameters passed to methodName, fileName and lineNo are created by the compiler (Rosyln) and passed as literals. .You call the method with only a single string. Because this is done at compile time there is zero reflection, no slow down and yet you still get some call information.
    The only down side is that your executables could get a bit larger.
     
  5. Peter77

    Peter77

    QA Jesus

    Joined:
    Jun 12, 2013
    Posts:
    6,650
    You can configure that in Player Settings > Other Settings:
     
  6. MrLucid72

    MrLucid72

    Joined:
    Jan 12, 2016
    Posts:
    1,008
    As discussed many times before, we want debug data - we do not want redundant stacks to the log itself that seem to be completely separate from any other stacktrace (on its own paragraph; not part of the stacktrace).
     
  7. Peter77

    Peter77

    QA Jesus

    Joined:
    Jun 12, 2013
    Posts:
    6,650
    My answer is to the quoted text in my post, nothing else. The context is important and in this context, I'm pretty sure the answer is correct. ;)
     
    Last edited: Oct 4, 2020
  8. cgrow67

    cgrow67

    Joined:
    May 31, 2016
    Posts:
    52
    Yes, you are correct that you can disable the stack trace in the editor.
    I wanted to show that you can control the stack trace behavior in code as well.
    I also wanted to show that you can get caller information for free via attributes without using the expensive stack tracing
    Realistically 99 percent of the time you just want to know what line caused the error not how you got there.
    With some minor change you could get both.
    I really wish I could offer a clickable link to the code from the attributes also.
     
  9. MrLucid72

    MrLucid72

    Joined:
    Jan 12, 2016
    Posts:
    1,008
    @Rarepops You still around bud? You mentioned this in January -- Soo... :ahem: .... how's it going? :p
     
  10. rarepop99

    rarepop99

    Unity Technologies

    Joined:
    Sep 5, 2019
    Posts:
    54
    Hi, sorry for the late reply, it was fixed around that time as far as I know? What seems to be the problem? :D

    Right now it shows (Filename: Something Line: SomeLine) under each Debug.log* as long as there is something to show. (Before it was empty). If it's empty, it won't show it. This will only work when ScriptOnly and Full stacktraces are checked :D
     
  11. Stoann

    Stoann

    Joined:
    Dec 4, 2017
    Posts:
    2
    @Rarepops The issue was that Unity spams the line (Filename: C:\buildslave\unity\build\Runtime/Export/Debug/Debug.bindings.h Line: 35) below each Debug.Log() entry, which is still happening in Unity 2020.1.13f1.
     
  12. glenneroo

    glenneroo

    Joined:
    Oct 27, 2016
    Posts:
    233
    Still happening in 2019.4.18f1. Here is the first instance in my adb logcat output (which is Unity's code):

    01-18 22:28:51.225 15197 15220 I Unity : XRGeneral Settings awakening...
    01-18 22:28:51.225 15197 15220 I Unity : UnityEngine.DebugLogHandler:Internal_Log(LogType, LogOption, String, Object)
    01-18 22:28:51.225 15197 15220 I Unity : UnityEngine.DebugLogHandler:LogFormat(LogType, Object, String, Object[])
    01-18 22:28:51.225 15197 15220 I Unity : UnityEngine.Logger:Log(LogType, Object)
    01-18 22:28:51.225 15197 15220 I Unity : UnityEngine.Debug:Log(Object)
    01-18 22:28:51.225 15197 15220 I Unity : UnityEngine.XR.Management.XRGeneralSettings:Awake()
    01-18 22:28:51.225 15197 15220 I Unity :
    01-18 22:28:51.225 15197 15220 I Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)

    Another example from my own Debug.Log() call:

    01-18 22:28:56.351 15197 15220 I Unity : Startup called.
    01-18 22:28:56.351 15197 15220 I Unity : UnityEngine.DebugLogHandler:Internal_Log(LogType, LogOption, String, Object)
    01-18 22:28:56.351 15197 15220 I Unity : UnityEngine.DebugLogHandler:LogFormat(LogType, Object, String, Object[])
    01-18 22:28:56.351 15197 15220 I Unity : UnityEngine.Logger:LogFormat(LogType, String, Object[])
    01-18 22:28:56.351 15197 15220 I Unity : UnityEngine.Debug:LogFormat(String, Object[])
    01-18 22:28:56.351 15197 15220 I Unity : <Start>d__22:MoveNext()
    01-18 22:28:56.351 15197 15220 I Unity : UnityEngine.SetupCoroutine:InvokeMoveNext(IEnumerator, IntPtr)
    01-18 22:28:56.351 15197 15220 I Unity :
    01-18 22:28:56.351 15197 15220 I Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
     
  13. rarepop99

    rarepop99

    Unity Technologies

    Joined:
    Sep 5, 2019
    Posts:
    54

    Could you please open a bug report with repro steps? Thanks! :)
     
  14. glenneroo

    glenneroo

    Joined:
    Oct 27, 2016
    Posts:
    233
    Done!
     
    unity_pCIVw7qaOJJy9g likes this.
  15. dominykasm

    dominykasm

    Unity Technologies

    Joined:
    May 27, 2018
    Posts:
    70
    Check this one out https://issuetracker.unity3d.com/issues/debug-dot-log-outputs-unnecesarry-lines-in-editor-log. It previously said that it was fixed in 2020.1 which was wrong as the fix was never backported to that stream to my knowledge. I updated the report as the issue is fixed in 2020.2. Please let us know if it still reproes in 2020.2+.
     
    glenneroo likes this.
  16. passingby2021

    passingby2021

    Joined:
    Feb 11, 2021
    Posts:
    1
    Running under Unity v2020.1.2.8073916

    I've read this whole thread.
    (Filename: C:\buildslave\unity\build\Runtime/Export/Debug/Debug.bindings.h Line: 35)

    And I was like huh, this is strange.
    (Filename: C:\buildslave\unity\build\Runtime/Export/Debug/Debug.bindings.h Line: 35)

    Why does the log file still look like this?
    (Filename: C:\buildslave\unity\build\Runtime/Export/Debug/Debug.bindings.h Line: 35)

    (Filename: C:\buildslave\unity\build\Runtime/Export/Debug/Debug.bindings.h Line: 35)

    (Filename: C:\buildslave\unity\build\Runtime/Export/Debug/Debug.bindings.h Line: 35)

    (Filename: C:\buildslave\unity\build\Runtime/Export/Debug/Debug.bindings.h Line: 35)

    PS
    I am not a Unity developer. I'm a user who is trying to debug a mod made for a game made in Unity.
     
  17. glenneroo

    glenneroo

    Joined:
    Oct 27, 2016
    Posts:
    233
    You forgot to read the post above yours:
     
  18. cgrow67

    cgrow67

    Joined:
    May 31, 2016
    Posts:
    52
    The point of my post was that you can get some stack data without paying the Reflection price.
    Disabling this removes all information and leaves you blind.
     
  19. Squoktapus

    Squoktapus

    Joined:
    Feb 9, 2014
    Posts:
    5
    Bump, still a problem.

    I want my log message, not the rest. It's also a big pain on device logs too, e.g. Android logcat.

    9024: [2022-06-16T13:59:58Z - Unity] My log message that I'm in interested in.
    9025: [2022-06-16T13:59:58Z - Unity] UnityEngine.StackTraceUtility:ExtractStackTrace ()
    9026: [2022-06-16T13:59:58Z - Unity] UnityEngine.DebugLogHandler:LogFormat (UnityEngine.LogType,UnityEngine.Object,string,object[])
    9027: [2022-06-16T13:59:58Z - Unity] UnityEngine.Logger:Log (UnityEngine.LogType,object)
    9028: [2022-06-16T13:59:58Z - Unity] UnityEngine.Debug:Log (object)
    ...

    @Unity think of the disk space you'll save on your cloud builds!
    (As well as all the developers you'll cease to annoy, but that doesn't appear to be a motivator)
     
    Last edited: Jun 21, 2022
  20. rarepop99

    rarepop99

    Unity Technologies

    Joined:
    Sep 5, 2019
    Posts:
    54
    Hi, I am not sure I understand the issue. You're saying you only want the message without any stacktrace on Android?
     
  21. SugoiDev

    SugoiDev

    Joined:
    Mar 27, 2013
    Posts:
    395
    I think what we all want is the ability to just exclude certain methods from the actual trace.
    When I'm debugging, I certainly don't need to see StackTraceUtility:ExtractStackTrace or UnityEngine.Debug:Log on every message.
    The "extra" noise is MOST of the logs, which makes it harder to actually parse them when you're reading.
    I resorted to post-process my logs for reading, but it would be much nicer to have it done in the engine itself.
     
  22. MrLucid72

    MrLucid72

    Joined:
    Jan 12, 2016
    Posts:
    1,008
    7+ years later and this thread is still the most relevant. Sigh... Slightly less bloaty
    UnityEngine.Debug:Log (object)

    Should I be surprised?
    UnityEngine.Debug:Log (object)

    Come on, Unity
    UnityEngine.Debug:Log (object)

    Imagine if our forums had this spam, too
    UnityEngine.Debug:Log (object)

    It's quite hard to read when you're looking at thousands per day
    UnityEngine.Debug:Log (object)

    ---
    Imagine if this post, instead, looked like:

    7+ years later and this thread is still the most relevant. Sigh... Slightly less bloaty
    Should I be surprised?
    Come on, Unity
    Imagine if our forums had this spam, too
    It's quite hard to read when you're looking at thousands per day