Details

    • Type: New Feature New Feature
    • Status: Open
    • Priority: Major Major
    • Resolution: Unresolved
    • Affects Version/s: 1.1.2
    • Fix Version/s: None
    • Labels:
      None

      Description

      Presently, in Apache Commons, the most common way to get a logger is to do something like:

      public class MyClass

      { private static Log log = LogFactory.getLog(MyClass.class); }

      Notice how MyClass.class (or alternatively a string name) is passed as a parameter. The annoying aspect of this is that sometimes the class name doesn't get updated when doing copy/paste operations. A desirable alternative might be:

      public class MyClass

      { private static Log log = LogFactory.getLog(); //class name inferred from call stack }

      With such an approach there are two possible concerns I can foresee:

      • Call stack inspection isn't terribly fast. However since Loggers are generally initialized only once, when the class is first loaded, performance isn't likely to be a major problem.
      • Commons-logging is Java 1.1 compatible. Thus care must be taken to ensure compatibility isn't broken.
      • Commons-logging doesn't depend on commons-lang, and thus the utilities in commons-lang cannot be used.

      In Java 1.4, the call stack is easily obtained using Thread.getCallStack(). Prior to Java 1.4, the only way to obtain the call stack is to inspect the stack trace of an exception.

      1. LogFactory.java
        82 kB
        Doug Bateman
      2. CallStackUtil.java.0
        7 kB
        Doug Bateman
      3. CallStackUtil.java.1
        9 kB
        Doug Bateman
      4. CallStackUtil.java.2
        8 kB
        Doug Bateman
      5. CallStackTestCase.java
        3 kB
        Doug Bateman

        Activity

        Hide
        Doug Bateman added a comment -

        Attached is a sample implementation.

        Show
        Doug Bateman added a comment - Attached is a sample implementation.
        Hide
        Doug Bateman added a comment -

        Updated sample implementation.

        Addresses Sebb's input that Thread.getStackTrace() requires Java 1.5 where as Throwable.getStackTrace() requires Java 1.4.

        Also fixes a typo at isAtLeastJava14 = true;

        Show
        Doug Bateman added a comment - Updated sample implementation. Addresses Sebb's input that Thread.getStackTrace() requires Java 1.5 where as Throwable.getStackTrace() requires Java 1.4. Also fixes a typo at isAtLeastJava14 = true;
        Hide
        Doug Bateman added a comment -

        Updated to include the proper Apache license header.

        Show
        Doug Bateman added a comment - Updated to include the proper Apache license header.
        Hide
        Doug Bateman added a comment -

        Same thing, as a patch file.

        Show
        Doug Bateman added a comment - Same thing, as a patch file.
        Hide
        Doug Bateman added a comment -

        And now making sure I check the "Grant License" box.

        Show
        Doug Bateman added a comment - And now making sure I check the "Grant License" box.
        Hide
        Sebb added a comment -

        The patch file contains a spurious update to svn:ignore.

        The .java files appear to duplicate the content of the patch files.

        Also, the static fields in CallStackUtil need to be final, apart from isAtLeastJava14 which needs to be volatile for safe publication across threads.

        It would be useful to use Thread.getStackTrace() if available, as that is likely to be quicker.

        The Javadoc needs to document that the returned classname can be null.
        What happens to the logger in this case?

        It's not immediately obvious why the getCallerJava14 method needs to scan the stack trace twice.
        Surely one can just add a fixed offset to the depth to find the caller stack frame?

        Also, Commons generally does not use @author tags, as ASF code is a collaborative effort.
        Attribution can be added to the <contributors> section of the POM instead, and/or release notes.

        Show
        Sebb added a comment - The patch file contains a spurious update to svn:ignore. The .java files appear to duplicate the content of the patch files. Also, the static fields in CallStackUtil need to be final, apart from isAtLeastJava14 which needs to be volatile for safe publication across threads. It would be useful to use Thread.getStackTrace() if available, as that is likely to be quicker. The Javadoc needs to document that the returned classname can be null. What happens to the logger in this case? It's not immediately obvious why the getCallerJava14 method needs to scan the stack trace twice. Surely one can just add a fixed offset to the depth to find the caller stack frame? Also, Commons generally does not use @author tags, as ASF code is a collaborative effort. Attribution can be added to the <contributors> section of the POM instead, and/or release notes.
        Hide
        Doug Bateman added a comment - - edited

        Hey Sebastian,

        Yeah, the patch file does have a spurious update to svn:ignore. It adds ".settings/" to the list. Eclipse complains and that directory has been included in commons-lang and commons-io, but overlooked in commons-logging. However, you're right, that's really a separate issue. So consider it gone.

        The .java files do duplicate the .patch file. Normally I'd just give the .patch file, but since we were having a discussion in channel I included the .java files too for ease of reading. For the update, which would you prefer... Java files for patch files?

        I'll remove the @author tag. I was about to take it out, but noticed all the other files still had them.

        Regarding the null return by CallStackUtil, it's really a non-issue since it can never happen. The only place getCallerClassName(1) is used is inside of LogFactory.getLog(). And LogFactory.getLog() is guaranteed to have an immediate caller (depth=1), otherwise it never would have been called in the first place. Nobody else can use CallStackUtil because it is package scope... It didn't seem relevant to the public API for logging... and if it was ever to be published, it probably should be in commons-lang. I suppose I could have just made private methods inside of LogFactory, but I didn't want to add the clutter and package scope seemed appropriate. That aside, the JavaDoc does actually discuss meaning of a null return, however I'll update the docs to make it a bit more obvious.

        The non-final fields were strictly a matter of simplicity, since the compiler objects to a possible double assignment to the file in the try and again in the catch. It objects even when using separate try/catch blocks for each set. However, I can work around that by using local variables in the initializer, so that's what I'll do.

        CallStackUtil.getCallerJava14() doesn't actually scan the trace twice. The i counter only ever increases. First it scans to find the invocation to the "CallStackUtil" methods on the stack (to skip past the reflection calls), and then it scans further until it's past the "CallStackUtil" methods. Leaving the interesting part of the call stack, which is then read at the requested depth. getCallerJava10() actually works the same way. It just uses "stackTrace.lastIndexOf()" to accomplish this, since it's reading the stack as a string.

        I too wanted to use Thread.getStackTrace(). However I noticed in the JavaDoc that it can throw SecurityExceptions, while Throwable.getStackTrace() does not. I have no idea why they decided to allow that in one but not the other. And of course Thread.getStackTrace() isn't available until Java 5.0 instead of 1.4. So following the "keep it simple" rule, I decided to use Throwable.getStackTrace(). I don't imagine the performance difference is measurable since Throwable.getStackTrace() likely uses the exact same native code underneath. And the extra object allocation is insignificant in comparison to the use of Java reflection. If after all this, you still think I should add support for Java 5.0's Thread.getStackTrace() I'm happy to do add it.

        I made isAtLeastJava14 non-volatile deliberately as well. In actuality, it could probably be made final, since I cant imagine a case where those catch blocks would ever be hit, except maybe in the case of a SecurityException. I had simply decided to make the implementation fault tolerant in the event I was wrong. I didn't make it volatile because I wanted to avoid the memory flush. If a thread has a stale copy of the flag no harm is done... that stale copy would always have the value true (from the static initializer which is synchronized by the classloader). And that just means the catch blocks would be hit again, and that thread would catch the exception and set it's cached copy to false as well... no memory flush required. I should probably comment that though, since it is unintuitive.

        I'll submit an update. Would you prefer it as java files or a single patch file?

        Show
        Doug Bateman added a comment - - edited Hey Sebastian, Yeah, the patch file does have a spurious update to svn:ignore. It adds ".settings/" to the list. Eclipse complains and that directory has been included in commons-lang and commons-io, but overlooked in commons-logging. However, you're right, that's really a separate issue. So consider it gone. The .java files do duplicate the .patch file. Normally I'd just give the .patch file, but since we were having a discussion in channel I included the .java files too for ease of reading. For the update, which would you prefer... Java files for patch files? I'll remove the @author tag. I was about to take it out, but noticed all the other files still had them. Regarding the null return by CallStackUtil, it's really a non-issue since it can never happen. The only place getCallerClassName(1) is used is inside of LogFactory.getLog(). And LogFactory.getLog() is guaranteed to have an immediate caller (depth=1), otherwise it never would have been called in the first place. Nobody else can use CallStackUtil because it is package scope... It didn't seem relevant to the public API for logging... and if it was ever to be published, it probably should be in commons-lang. I suppose I could have just made private methods inside of LogFactory, but I didn't want to add the clutter and package scope seemed appropriate. That aside, the JavaDoc does actually discuss meaning of a null return, however I'll update the docs to make it a bit more obvious. The non-final fields were strictly a matter of simplicity, since the compiler objects to a possible double assignment to the file in the try and again in the catch. It objects even when using separate try/catch blocks for each set. However, I can work around that by using local variables in the initializer, so that's what I'll do. CallStackUtil.getCallerJava14() doesn't actually scan the trace twice. The i counter only ever increases. First it scans to find the invocation to the "CallStackUtil" methods on the stack (to skip past the reflection calls), and then it scans further until it's past the "CallStackUtil" methods. Leaving the interesting part of the call stack, which is then read at the requested depth. getCallerJava10() actually works the same way. It just uses "stackTrace.lastIndexOf()" to accomplish this, since it's reading the stack as a string. I too wanted to use Thread.getStackTrace(). However I noticed in the JavaDoc that it can throw SecurityExceptions, while Throwable.getStackTrace() does not. I have no idea why they decided to allow that in one but not the other. And of course Thread.getStackTrace() isn't available until Java 5.0 instead of 1.4. So following the "keep it simple" rule, I decided to use Throwable.getStackTrace(). I don't imagine the performance difference is measurable since Throwable.getStackTrace() likely uses the exact same native code underneath. And the extra object allocation is insignificant in comparison to the use of Java reflection. If after all this, you still think I should add support for Java 5.0's Thread.getStackTrace() I'm happy to do add it. I made isAtLeastJava14 non-volatile deliberately as well. In actuality, it could probably be made final, since I cant imagine a case where those catch blocks would ever be hit, except maybe in the case of a SecurityException. I had simply decided to make the implementation fault tolerant in the event I was wrong. I didn't make it volatile because I wanted to avoid the memory flush. If a thread has a stale copy of the flag no harm is done... that stale copy would always have the value true (from the static initializer which is synchronized by the classloader). And that just means the catch blocks would be hit again, and that thread would catch the exception and set it's cached copy to false as well... no memory flush required. I should probably comment that though, since it is unintuitive. I'll submit an update. Would you prefer it as java files or a single patch file?
        Hide
        Doug Bateman added a comment -

        Attached is a revised version, with the changes discussed above.

        Show
        Doug Bateman added a comment - Attached is a revised version, with the changes discussed above.
        Hide
        Doug Bateman added a comment -

        Attached is a copy of the Java files. They duplicate what's in the CallStackUtil.patch. They are included strictly for ease of reading. Feel free to remove these is they aren't desirable.

        Show
        Doug Bateman added a comment - Attached is a copy of the Java files. They duplicate what's in the CallStackUtil.patch. They are included strictly for ease of reading. Feel free to remove these is they aren't desirable.
        Hide
        Sebb added a comment -

        Thanks for the revised files.

        It was not clear originally why there were two copies of the changes, but you have explained that now so no need to delete the .java files.

        It's a pity that the getCallerJava14 method has to scan the stack at all.
        But the reflection implementation may vary in nesting depth between releases and JVMs.
        However one could perhaps optimise the code by skipping the first few stack frames which are known to be present.

        BTW, Thread#getStackTrace() uses Throwable#getStackTrace() for the current thread (at least in Sun Java 1.5) so you are correct that there is no point using the Thread method.

        Show
        Sebb added a comment - Thanks for the revised files. It was not clear originally why there were two copies of the changes, but you have explained that now so no need to delete the .java files. It's a pity that the getCallerJava14 method has to scan the stack at all. But the reflection implementation may vary in nesting depth between releases and JVMs. However one could perhaps optimise the code by skipping the first few stack frames which are known to be present. BTW, Thread#getStackTrace() uses Throwable#getStackTrace() for the current thread (at least in Sun Java 1.5) so you are correct that there is no point using the Thread method.
        Hide
        Sebb added a comment -

        One could further optimise the code by calculating the index depth once.
        Even if it varies between JVMs, it will remain constant for a given run.

        Show
        Sebb added a comment - One could further optimise the code by calculating the index depth once. Even if it varies between JVMs, it will remain constant for a given run.
        Hide
        Doug Bateman added a comment -

        Based on your feedback, here are 3 new versions available for you to choose.

        Version 0 is basically what you've seen before. I fixed a few comments.
        Version 1 scans the call stack once, and then stores the indexes as constants.
        Version 2 simply asserts it should drop 2 stack frames and avoids much of the scanning.

        Good news is reflection stopped being an issue once we replaced the reflection call to Thread.getStackTrace() with the non-reflection call to Throwable.fillInStackTrace(). This is what makes version 2 possible.

        However, I'm not sure how standard Throwable.fillInStackTrace() and Throwable.printStackTrace(err) are across JVM versions and vendors. For example, are either "fillInStackTrace() or "printStackTrace()" included? Generally no. But could there be a JVM out there which did? Was the exact behavior clearly defined as early as Java 1.1? Hence I worry about Version 2 making too many assumptions and prefer version 1.

        Show
        Doug Bateman added a comment - Based on your feedback, here are 3 new versions available for you to choose. Version 0 is basically what you've seen before. I fixed a few comments. Version 1 scans the call stack once, and then stores the indexes as constants. Version 2 simply asserts it should drop 2 stack frames and avoids much of the scanning. Good news is reflection stopped being an issue once we replaced the reflection call to Thread.getStackTrace() with the non-reflection call to Throwable.fillInStackTrace(). This is what makes version 2 possible. However, I'm not sure how standard Throwable.fillInStackTrace() and Throwable.printStackTrace(err) are across JVM versions and vendors. For example, are either "fillInStackTrace() or "printStackTrace()" included? Generally no. But could there be a JVM out there which did? Was the exact behavior clearly defined as early as Java 1.1? Hence I worry about Version 2 making too many assumptions and prefer version 1.
        Hide
        Doug Bateman added a comment -

        P.S. I'm not certain how much performance when scanning is really an issue when it comes to getting the logger. After all, reflection is still used to invoke StackTraceElement.getClassName() for Java 1.4+. Simplicity should probably count for a little here too. (Although I'm not convinced any of the implementations are truly simpler than the others.)

        Show
        Doug Bateman added a comment - P.S. I'm not certain how much performance when scanning is really an issue when it comes to getting the logger. After all, reflection is still used to invoke StackTraceElement.getClassName() for Java 1.4+. Simplicity should probably count for a little here too. (Although I'm not convinced any of the implementations are truly simpler than the others.)
        Hide
        Doug Bateman added a comment -

        I forgot to test the latest code I sent you using Java 1.3 and below. The stack trace parsing isn't correct as a result of my having parsing aggressively rather than lazily. I will fix it and repost along with a corresponding upgrade to my test cases.

        Meanwhile, which of the 3 styles I posted do you prefer? That will allow me to focus my energy on the one you choose.

        Show
        Doug Bateman added a comment - I forgot to test the latest code I sent you using Java 1.3 and below. The stack trace parsing isn't correct as a result of my having parsing aggressively rather than lazily. I will fix it and repost along with a corresponding upgrade to my test cases. Meanwhile, which of the 3 styles I posted do you prefer? That will allow me to focus my energy on the one you choose.
        Hide
        Sebb added a comment -

        As far as I can tell, reflection is not now used to generate the stack trace, so the depth of the stack frame should be fixed and therefore does not need to be calculated.

        The only code that depends on Java1.4+ is the code that uses Throwable.getStackTrace() to make it easier to parse the stack frames.

        So I think the code can be simplified further:

        1) generate the trace (at known stack depth offset)
        2) extract the class name using whatever methods are available to the running code.

        Show
        Sebb added a comment - As far as I can tell, reflection is not now used to generate the stack trace, so the depth of the stack frame should be fixed and therefore does not need to be calculated. The only code that depends on Java1.4+ is the code that uses Throwable.getStackTrace() to make it easier to parse the stack frames. So I think the code can be simplified further: 1) generate the trace (at known stack depth offset) 2) extract the class name using whatever methods are available to the running code.
        Hide
        Doug Bateman added a comment -

        It's not quite that simple, because the output of Throwable.printStackTrace(stream) isn't standard. For one thing, it varies based on the availability of line numbers. So it is very important that the length of the header be calculated dynamically, at least once.

        Doing that calculation in getStackHeaderCharCount() doesn't work, because that method signature doesn't match getCallerJava11(int). So what it means is that I've got to call "public static int getCallerJava11(depth)" itself to calculate the stack size up front.... and that means I'm using that public function even before the final field STACK_HEADER_CHAR_COUNT is even initialized. It's messy.

        However, fortunately I think it's still workable. I can rely on the fact that static-initializers are synchronized by the class loader, so I need not worry about race conditions caused by having a public static method reading a static field prior to initialization. And I can rely on the non-initialized field having the default value zero prior to it's initialization. Otherwise it would be a real nightmare.

        Anyway, I've got to finish installing these updates. For the Java 1.4 version, I take it you prefer Example CallStackUtil.java.2 where I simply assert STACK_HEADER_FRAME_COUNT=2, (e.g. drop 2 frames and then read at depth) rather than doing any dynamic calculations. Is that correct?

        Show
        Doug Bateman added a comment - It's not quite that simple, because the output of Throwable.printStackTrace(stream) isn't standard. For one thing, it varies based on the availability of line numbers. So it is very important that the length of the header be calculated dynamically, at least once. Doing that calculation in getStackHeaderCharCount() doesn't work, because that method signature doesn't match getCallerJava11(int). So what it means is that I've got to call "public static int getCallerJava11(depth)" itself to calculate the stack size up front.... and that means I'm using that public function even before the final field STACK_HEADER_CHAR_COUNT is even initialized. It's messy. However, fortunately I think it's still workable. I can rely on the fact that static-initializers are synchronized by the class loader, so I need not worry about race conditions caused by having a public static method reading a static field prior to initialization. And I can rely on the non-initialized field having the default value zero prior to it's initialization. Otherwise it would be a real nightmare. Anyway, I've got to finish installing these updates. For the Java 1.4 version, I take it you prefer Example CallStackUtil.java.2 where I simply assert STACK_HEADER_FRAME_COUNT=2, (e.g. drop 2 frames and then read at depth) rather than doing any dynamic calculations. Is that correct?
        Hide
        Doug Bateman added a comment -

        The other concern I have that even the Java 1.4 approach of using Throwable.getStackTrace() may have variations across JVMs. Hence I feel it's better to calculate once rather than assume a hard coded constant.

        Specifically, the Java 1.4.2 JavaDoc for Throwable.getStackTrace() reads:

        "Some virtual machines may, under some circumstances, omit one or more stack frames from the stack trace. In the extreme case, a virtual machine that has no stack trace information concerning this throwable is permitted to return a zero-length array from this method. Generally speaking, the array returned by this method will contain one element for every frame that would be printed by printStackTrace. "

        And even Throwable.fillInStackTrace() doesn't specify what is considered the top of the call stack. It only takes one JVM vendor to do things differently to throw a wrench in the works. For example, a JVM vendor might include Throwable.fillInStackTrace() itself in the call stack returned, even though the Sun JRE does not.

        This is why I prefer the approach of actually calculating it once in a static initializer. It avoids the issue. However, we could do the simple approach by waiting to see if it becomes a reported issue before introducing added complexity. And developers encountering problems can always revert to using the Logger.getLogger(name) approach.

        Show
        Doug Bateman added a comment - The other concern I have that even the Java 1.4 approach of using Throwable.getStackTrace() may have variations across JVMs. Hence I feel it's better to calculate once rather than assume a hard coded constant. Specifically, the Java 1.4.2 JavaDoc for Throwable.getStackTrace() reads: "Some virtual machines may, under some circumstances, omit one or more stack frames from the stack trace. In the extreme case, a virtual machine that has no stack trace information concerning this throwable is permitted to return a zero-length array from this method. Generally speaking, the array returned by this method will contain one element for every frame that would be printed by printStackTrace. " And even Throwable.fillInStackTrace() doesn't specify what is considered the top of the call stack. It only takes one JVM vendor to do things differently to throw a wrench in the works. For example, a JVM vendor might include Throwable.fillInStackTrace() itself in the call stack returned, even though the Sun JRE does not. This is why I prefer the approach of actually calculating it once in a static initializer. It avoids the issue. However, we could do the simple approach by waiting to see if it becomes a reported issue before introducing added complexity. And developers encountering problems can always revert to using the Logger.getLogger(name) approach.
        Hide
        Sebb added a comment -

        As I read it, the dropped frames are not due to getStackTrace() per se, but that fillInStackTrace() may drop frames at run-time - which of course affects getStackTrace().

        Also, dropped frames are a run-time issue, so although the static initialisation may store the correct offset, the run-time frame may be too short.
        This means that the code should be able to handle this, e.g. by returning the string "UNKNOWN" rather than the null string, which may cause an NPE.

        The static initialiser only needs to count the number of frames for a known stack trace - it does not need to analyse their content.
        The method getStackHeaderFrameCount() can be simplified a lot.

        Show
        Sebb added a comment - As I read it, the dropped frames are not due to getStackTrace() per se, but that fillInStackTrace() may drop frames at run-time - which of course affects getStackTrace(). Also, dropped frames are a run-time issue, so although the static initialisation may store the correct offset, the run-time frame may be too short. This means that the code should be able to handle this, e.g. by returning the string " UNKNOWN " rather than the null string, which may cause an NPE. The static initialiser only needs to count the number of frames for a known stack trace - it does not need to analyse their content. The method getStackHeaderFrameCount() can be simplified a lot.
        Hide
        Doug Bateman added a comment -

        I still don't know which of the 3 versions you're reading.

        Show
        Doug Bateman added a comment - I still don't know which of the 3 versions you're reading.

          People

          • Assignee:
            Unassigned
            Reporter:
            Doug Bateman
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:

              Time Tracking

              Estimated:
              Original Estimate - 0.5h
              0.5h
              Remaining:
              Remaining Estimate - 0.5h
              0.5h
              Logged:
              Time Spent - Not Specified
              Not Specified

                Development