For C# logging, how do I obtain the call stack depth with minimal overhead?

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.

score 9 · Accepted Answer · edited Dec 23 '12 at 17:05

9

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.

edited Dec 23 '12 at 17:05

Peter Mortensen

30,738
21
105
131

answered May 14 '11 at 01:42

Teoman Soygul

25,584
6
69
80

1

Thanks for your answer. I may be wrong, but I'm assuming that when you create a StackTrace object that all of the StackFrame objects are also created. You're saying this is not the case? – RenniePet May 14 '11 at 01:56
3

new StackFrame() object is not that expensive if you don't use it but if you really need to top performance, read on to some twisted Reflection.Emit stuff: http://ayende.com/blog/3879/reducing-the-cost-of-getting-a-stack-trace – Teoman Soygul May 14 '11 at 02:09
Wow, I'm impressed. Also feeling like my abilities are not up to understanding what you've done. I'll try to analyze and understand it later when I have more time. But what does "Func – RenniePet May 14 '11 at 13:10
1

It's a C# 3.0 feature which is a shorthand generic delegate. `Func – Teoman Soygul May 14 '11 at 14:11
@Teoman, right, I mistakenly thought that was your blog, but still kudos to you for pointing me in that direction. I now have the code running, and have done a bit of research, and I do think this may be the solution I'm looking for. But I have one more question. I need to access the StackFrameHelper.iFrameCount field. Now, the Visual Studio debugger knows about this field and willingly displays it, no problem. But the Visual Studio C# compiler refuses to give me access because StackFrameHelper is "internal". Do you have a recommendation for how I should access that field? Thanks. – RenniePet May 15 '11 at 01:12
Using reflections of course. Search here for 'accessing internal properties via reflection'. – Teoman Soygul May 15 '11 at 01:29
OK, I've got it working, at least as a "proof of concept". Many, many thanks. I'm going to post my test code as an answer, as it looks best that way, right? But I've flagged your answer as the accepted answer. – RenniePet May 15 '11 at 02:14

RenniePet · Answer 2 · 2017-12-11T00:50:18.330

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();
      }
   }

RenniePet · Answer 3 · 2017-12-10T23:57:50.067

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.)

Not really, it's almost 100% Oren Eini's code, just regressed to .Net 2. — RenniePet, May 15 '11 at 10:30

score 0 · Answer 4 · answered Feb 18 '20 at 11:43

0

Environment.StackTrace.Split(Environment.NewLine).Length

answered Feb 18 '20 at 11:43

André Boonzaaijer

764
4
13

score 0 · Answer 5 · answered Dec 11 '20 at 10:16

If you do recursion to same method and just want to know how deep in the current method you are I am using this kind of check, although it might be not great for performance. I guess new StackTrace() could be stored somewhere to avoid recreation each time, but in my case it was not important, so I use it like this:

var callDepth = new StackTrace().GetFrames().Count(_ => _.GetMethod().Name == nameof(CallingMethod))

Just replace CallingMethod with the name of your method

For C# logging, how do I obtain the call stack depth with minimal overhead?

5 Answers5

Linked