For C# logging, how do I obtain the call stack dep

Question

I have created a wrapper for Log4net (which I may be dropping in favor of NLog; I haven't decided yet), and I indent the logged messages result to give an idea of calling structure. For example:

2011-04-03 00:20:30,271 [CT] DEBUG  -     Merlinia.ProcessManager.CentralThread.ProcessAdminCommand - ProcStart - User Info Repository
2011-04-03 00:20:30,271 [CT] DEBUG  -      Merlinia.ProcessManager.CentralThread.StartOneProcess - User Info Repository
2011-04-03 00:20:30,411 [CT] DEBUG  -       Merlinia.ProcessManager.CentralThread.SetProcessStatus - Process = User Info Repository, status = ProcStarting
2011-04-03 00:20:30,411 [CT] DEBUG  -        Merlinia.ProcessManager.CentralThread.SendProcessStatusInfo
2011-04-03 00:20:30,411 [CT] DEBUG  -         Merlinia.CommonClasses.MhlAdminLayer.SendToAllAdministrators - ProcessTable
2011-04-03 00:20:30,411 [CT] DEBUG  -          Merlinia.CommonClasses.MReflection.CopyToBinary
2011-04-03 00:20:30,411 [CT] DEBUG  -           Merlinia.CommonClasses.MReflection.CopyToBinary - False
2011-04-03 00:20:30,411 [CT] DEBUG  -          Merlinia.CommonClasses.MhlBasicLayer.SendToAllConnections - 228 - True - False
2011-04-03 00:20:30,411 [CT] DEBUG  -           Merlinia.CommonClasses.MmlNonThreaded.SendObject - 228
2011-04-03 00:20:30,411 [CT] DEBUG  -            Merlinia.CommonClasses.MllTcpSocket.SendMessage - 228 - True
2011-04-03 00:20:32,174 [10] DEBUG  -    Merlinia.CommonClasses.MReflection.CreateFromBinary
2011-04-03 00:20:32,174 [10] DEBUG  -     Merlinia.CommonClasses.MReflection.CopyFromBinary - Bytes = 71
2011-04-03 00:20:32,174 [CT] DEBUG  - Merlinia.ProcessManager.CentralThread.MessagingCallback - User Info Repository - ProcessInfoAndRequests
2011-04-03 00:20:32,174 [CT] DEBUG  -  Merlinia.ProcessManager.CentralThread.ProcessProcessInfoAndRequests - User Info Repository

I do this using System.Diagnostics.StackTrace and counting StackFrames.

Now here's the question: Is there any more efficient way of doing this? I only need to determine the (relative) call stack depth, i.e., is the current depth plus or minus what it was the last time my logging wrapper was called. (Note that I do not actually use the StackFrame objects - I get the method names otherwise.)

I'm hoping for some simple high-performance way of querying the call stack depth or stack usage.

Answer 1

After six and a half years of trusty service, I suddenly experienced that many of my programs were crashing in late 2017, after having applied an update from Microsoft that included changes to .Net Framework 4.5. That's what you get for writing code that depends on internal undocumented data structures in mscorlib.dll.

This version of the code works again, and is also designed to be slightly more robust in the face of possible future updates to mscorlib.dll - it hopefully just fails gracefully and always returns zero. But there are still no guarantees against future changes to mscorlib.dll resulting in future crashes in this code.

   /// <summary>
   /// This test program demonstrates a faster way of getting call stack depth by avoiding getting a 
   /// StackTrace object. But you can't get the calling method names this way.
   ///
   /// See http://stackoverflow.com/questions/5999177/for-c-logging-how-to-obtain-call-stack-depth-with-minimal-overhead
   /// and http://ayende.com/blog/3879/reducing-the-cost-of-getting-a-stack-trace
   ///
   /// Update, late 2017, .Net mscorlib.dll has been changed for .Net 4.5. In the code below the two 
   /// possibilities are called "old .Net" and "new .Net". The two versions can be tested by setting 
   /// the target for this project to either .Net Framework 2.0 or .Net Framework 4.5.
   /// </summary>
   class TestProgram
   {
      static void Main()
      {
         OneTimeSetup();

         int i = GetCallStackDepth();  // i = 10 on my test machine for old .Net, 12 for new .Net
         int j = AddOneToNesting();
         Console.WriteLine(j == i + 1 ? "Test succeeded!" : "Test failed!!!!!!!!");
         Console.ReadKey();
      }


      private delegate object DGetStackFrameHelper();

      private static DGetStackFrameHelper _getStackFrameHelper = null;

      private static FieldInfo _frameCount = null;


      private static void OneTimeSetup()
      {
         try
         {
            Type stackFrameHelperType =
                             typeof(object).Assembly.GetType("System.Diagnostics.StackFrameHelper");

            // ReSharper disable once PossibleNullReferenceException
            MethodInfo getStackFramesInternal =
               Type.GetType("System.Diagnostics.StackTrace, mscorlib").GetMethod(
                            "GetStackFramesInternal", BindingFlags.Static | BindingFlags.NonPublic);
            if (getStackFramesInternal == null)
               return;  // Unknown mscorlib implementation

            DynamicMethod dynamicMethod = new DynamicMethod(
                      "GetStackFrameHelper", typeof(object), new Type[0], typeof(StackTrace), true);

            ILGenerator generator = dynamicMethod.GetILGenerator();
            generator.DeclareLocal(stackFrameHelperType);

            bool newDotNet = false;

            ConstructorInfo constructorInfo =
                     stackFrameHelperType.GetConstructor(new Type[] {typeof(bool), typeof(Thread)});
            if (constructorInfo != null)
               generator.Emit(OpCodes.Ldc_I4_0);
            else
            {
               constructorInfo = stackFrameHelperType.GetConstructor(new Type[] {typeof(Thread)});
               if (constructorInfo == null)
                  return; // Unknown mscorlib implementation
               newDotNet = true;
            }

            generator.Emit(OpCodes.Ldnull);
            generator.Emit(OpCodes.Newobj, constructorInfo);
            generator.Emit(OpCodes.Stloc_0);
            generator.Emit(OpCodes.Ldloc_0);
            generator.Emit(OpCodes.Ldc_I4_0);

            if (newDotNet)
               generator.Emit(OpCodes.Ldc_I4_0);  // Extra parameter

            generator.Emit(OpCodes.Ldnull);
            generator.Emit(OpCodes.Call, getStackFramesInternal);
            generator.Emit(OpCodes.Ldloc_0);
            generator.Emit(OpCodes.Ret);

            _getStackFrameHelper =
                  (DGetStackFrameHelper) dynamicMethod.CreateDelegate(typeof(DGetStackFrameHelper));

            _frameCount = stackFrameHelperType.GetField("iFrameCount", 
                                                    BindingFlags.NonPublic | BindingFlags.Instance);
         }
         catch
         {}  // _frameCount remains null, indicating unknown mscorlib implementation
      }


      private static int GetCallStackDepth()
      {
         if (_frameCount == null)
            return 0;  // Unknown mscorlib implementation
         return (int)_frameCount.GetValue(_getStackFrameHelper());
      }


      private static int AddOneToNesting()
      {
         return GetCallStackDepth();
      }
   }

Answer 2

Simply use the StackTrace.FrameCount property, and compare it to the previously recorded FrameCount. FYI, FrameCount is probably the fastest method to retrieve the actual frame count, since it only returns the internal m_iNumOfFrames field back to you.

Answer 3

Thanks to Teoman Soygul and especially to Oren Eini, whose blog Teoman provided a link to.

The following is some "proof of concept" code that I think is the solution I'll be using - although I must admit I haven't done any timing tests.

   class TestProgram
   {
      static void Main(string[] args)
      {
         OneTimeSetup();

         int i = GetCallStackDepth();   // i = 10 on my test machine
         i = AddOneToNesting();         // Now i = 11
      }


      private delegate object DGetStackFrameHelper();

      private static DGetStackFrameHelper _getStackFrameHelper;

      private static FieldInfo _frameCount;


      private static void OneTimeSetup()
      {
         Type stackFrameHelperType =
            typeof(object).Assembly.GetType("System.Diagnostics.StackFrameHelper");


         MethodInfo getStackFramesInternal =
            Type.GetType("System.Diagnostics.StackTrace, mscorlib").GetMethod(
                            "GetStackFramesInternal", BindingFlags.Static | BindingFlags.NonPublic);


         DynamicMethod dynamicMethod = new DynamicMethod(
                      "GetStackFrameHelper", typeof(object), new Type[0], typeof(StackTrace), true);

         ILGenerator generator = dynamicMethod.GetILGenerator();
         generator.DeclareLocal(stackFrameHelperType);
         generator.Emit(OpCodes.Ldc_I4_0);
         generator.Emit(OpCodes.Ldnull);
         generator.Emit(OpCodes.Newobj,
                  stackFrameHelperType.GetConstructor(new Type[] { typeof(bool), typeof(Thread) }));
         generator.Emit(OpCodes.Stloc_0);
         generator.Emit(OpCodes.Ldloc_0);
         generator.Emit(OpCodes.Ldc_I4_0);
         generator.Emit(OpCodes.Ldnull);
         generator.Emit(OpCodes.Call, getStackFramesInternal);
         generator.Emit(OpCodes.Ldloc_0);
         generator.Emit(OpCodes.Ret);


         _getStackFrameHelper =
                   (DGetStackFrameHelper)dynamicMethod.CreateDelegate(typeof(DGetStackFrameHelper));


         _frameCount = stackFrameHelperType.GetField(
                                     "iFrameCount", BindingFlags.NonPublic | BindingFlags.Instance);
      }


      private static int GetCallStackDepth()
      {
         return (int)_frameCount.GetValue(_getStackFrameHelper());
      }


      private static int AddOneToNesting()
      {
         return GetCallStackDepth();
      }
   }

EDIT: This version does not work for .Net Framework 4.5 after an update of mscorlib.dll by Microsoft in late 2017. See another answer I've posted for a newer version. (I'm leaving this answer for the sake of posterity - and it does still work for .Net Framework 2.0 and 3.5.)