8
\$\begingroup\$

I got really tired of having this code in all of my classes and methods:

public class SomeClass {

    private static final Logger LOGGER = Logger.getLogger(SomeClass.class);

    //...

    public int someMethod() {

        final String methodName = "someMethod()";
        LOGGER.debug("Entering " + methodName);

        int returnValue = 0;

        //...

        LOGGER.debug("Exiting " + methodName + +", returning " + returnValue);
        return returnValue;
    }
}

... so I created the following utility class which would allow me to just call LoggingUtil.logMethodEntrance():

public class LoggingUtil {

    private static final Logger LOGGER = Logger.getLogger(LoggingUtil.class);
    private static final int GET_CALLING_METHOD_NAME_DEPTH = 3;

    public static void logMethodEntrance() {
        if(LOGGER.isDebugEnabled()) {
            LOGGER.debug("Entering " + getCallingMethodName());
        }
    }

    private static String getCallingMethodName() {
        return Thread.currentThread().getStackTrace()[GET_CALLING_METHOD_NAME_DEPTH].getMethodName() + "()";
    }
}

This was the first iteration. I put it here so you could understand the general concept. Before you mention that the isDebugEnabled() call isn't necessary to prevent the logging, the reason it's there is because the getStackTrace() method has notoriously poor performance and I don't want it called unless it's actually going to be used.

Now I wanted to add on to this basic framework and make it more powerful/dynamic by overloading the method and allowing the user to pass in a Priority if they don't want it to be DEBUG.

Normally, I would chain the methods like the following:

private static final Level DEFAULT_LOGGING_LEVEL = Level.DEBUG;

public static void logMethodEntrance() {
    logMethodEntrance(DEFAULT_LOGGING_LEVEL);
}

public static void logMethodEntrance(Priority level) {
    if(LOGGER.isEnabledFor(level)) {
        LOGGER.log(level, "Entering " + getCallingMethodName());
    }
}

The problem with this is that there's no way for the getCallingMethodName() method to know how deep to search in the stack for the appropriate "calling method". If the calling code invoked logMethodEntrance(), it will be one off from if they called logMethodEntrance(Level.INFO).

I thought about passing down an int that described the stack depth to look for the method name, but it ended up boiling down to all of them passing a 1 down to the common method call. So this is what I wound up going with in my final implementation:

public class LoggingUtil {

    private static final Logger LOGGER = Logger.getLogger(LoggingUtil.class);
    private static final Object METHOD_SIGNATURE_BREAKER = new Object();
    private static final Level DEFAULT_LOGGING_LEVEL = Level.DEBUG;
    private static final int GET_CALLING_METHOD_NAME_DEPTH = 4;



    public static void logMethodEntrance() {
        logMethodEntrance(DEFAULT_LOGGING_LEVEL, METHOD_SIGNATURE_BREAKER);
    }

    public static void logMethodEntrance(Priority level) {
        logMethodEntrance(level, METHOD_SIGNATURE_BREAKER);
    }

    private static void logMethodEntrance(Priority level, Object signature) {
        if(LOGGER.isEnabledFor(level)) {
            LOGGER.log(level, "Entering " + getCallingMethodName());
        }
    }

    private static String getCallingMethodName() {
        return Thread.currentThread().getStackTrace()[GET_CALLING_METHOD_NAME_DEPTH].getMethodName() + "()";
    }

}

I'm not particularly happy with this solution, but it does work fine. The issue is even more noticeable in the logMethodExit() method set, which I allow the calling code to either use with no arguments, use with Priority, use with a T returnValue, or supply both.

The METHOD_SIGNATURE_BREAKER object only exists to allow a further method overload. What I mean is that there's no actual need for it, except that I have to have another parameter supplied to the common private method in order for it to exist. (i.e., I can't have it as below):

public static void logMethodEntrance() {}
public static void logMethodEntrance(Priority level) {}
private static void logMethodEntrance(Priority level) {}

Passing down null seemed even dirtier without the constant. I'm not willing to copy and paste code around or duplicate it. I fully believe that if you need to make a code change to fix a bug or something that you should only have to do it in one place. Ideally, I'd like to find a way to chain the methods downward, but I don't see how to do that well and preserve the getCallingMethodName()'s functionality. So, any great ideas?

\$\endgroup\$
  • \$\begingroup\$ Is there a reason you picked that over just giving the method a different name? \$\endgroup\$ – Ben Aaronson Mar 1 '14 at 1:00
  • \$\begingroup\$ @BenAaronson ... Yeah, I realized that would've been easier as I was typing the question, haha. But it would be nice if someone has a solution where the getCallingMethodName() method can dynamically get the right one and allow the methods to be chained together. It would make the code cleaner, I think, than relying on a separate private version. \$\endgroup\$ – asteri Mar 1 '14 at 1:03
  • \$\begingroup\$ I don't know about all the logging framework but in log4j I don't need to specify myself the class or the method name, I just need to change the pattern layout. I guess they used the same slow component, but you don't need any new classes at least. This won't fit all you need, but could be a good start. \$\endgroup\$ – Marc-Andre Mar 1 '14 at 1:41
  • \$\begingroup\$ @Marc-Andre Yeah, this is using log4j. I actually didn't know that you could configure it to give you the method name in the logging statements (thought it was only the class name). \$\endgroup\$ – asteri Mar 1 '14 at 5:06
  • \$\begingroup\$ Check AOP too if you don't know about it already: stackoverflow.com/q/12732069/843804 \$\endgroup\$ – palacsint Mar 1 '14 at 11:31
3
\$\begingroup\$

Separate answer because this is taking a completely different tack.

Instead of the knee-jerk reaction to the getStackTrace(), consider the following other issues...

Logging in Java has been a complicated area for the past number of years.... there's so many different Logger utilities, all with slightly different interfaces:

You seem to be using Apache's log4j API.

What you should consider is how other API's have solved this problem.

For example, java.util.Logging has the following two methods:

To me this indicates that the best way to manage this problem is 'the hard way' of typing in the method name. Using the stack-trace is not used by any popular system.

Now, a second issue is that Logging is enabled, configured, and diverted based on the 'key' used for the log message. This is typically set as the full class package.Name. Your code is losing that information, and using just the one Logger instance for the LogUtils class. Thus, there is no way to configure the method entry/exit logging for just one class in your system.

For your LoggingUtil class I would consider the method:

public static final void logMethodEntrance(final Logger logger,
           final String class, final String method) {...}

Inside that method I would still check logger.isDebugEnabled() before working....

Additionally, one of the features that is missing in apache's log4j is the ability to do String-formatted messages... which are so useful in slf4j...

String-formatted methods are useful for things like the following... in your code you have (before your 'fix'):

    LOGGER.debug("Entering " + methodName);

    int returnValue = 0;

    //...

    LOGGER.debug("Exiting " + methodName + +", returning " + returnValue);

Now, that first debug is doing the String-concatenation before the LOGGER can decide whether debug is enabled, or not. This means that you are doing the String-concatenation even when debug is not enabled.

If the LOGGER supported a 'formatted' debug method, it could be called like:

LOGGER.debug("Entering %s", methodName);

and the LOGGER could check to see whether isDebugEnabled() before building the actual message (string formatting) with String.format("Entering %s", methodName).

This 'formatted' log messages is one of the best features available in Logger APIs, and, as far as I am concerned, it is the 'winning' feature for when deciding which API to use...

cough slf4j cough

Unfortunately slf4j does not support the method entry/exit calls.

What a mess.

If you are determined to have a LogUtilities static class, I would recommend the following:

public static final void logMethodEntrance(final Logger logger,
           final String class, final String method) {...}

public static final void logMethodEntrance(final Logger logger,
           final String class, final String method, Object...params) {...}

public static final void logMethodExit(final Logger logger,
           final String class, final String method) {...}

public static final void log(final Logger logger, String format, Object...values) { ... }

public static final void debug(final Logger logger, String format, Object...values) { ... }

public static final void trace(final Logger logger, String format, Object...values) { ... }
\$\endgroup\$
  • \$\begingroup\$ Thanks for all your different perspectives. Really helped me work through the issue. It sucks that there's no good, generic way to do this, but you've outlined very well the reasons why. \$\endgroup\$ – asteri Mar 2 '14 at 18:15
6
\$\begingroup\$

I have been through this loop (quite recently, actually), for a rather large project in a very commercial environment.

Frankly, it's not sustainable.

Let me run through some of the issues:

  • getStackTrace() is not just slow, it is molasses, and it affects all threads on the JVM, not just the current one.
  • Different versions of Java (same vendor, different versions, or different vendors, etc.) will need to have a different value for GET_CALLING_METHOD_NAME_DEPTH
  • did I mention that getStackTrace was slow?
  • You will be logging the method name, but the class used for the Log output will be LoggingUtil, not the class the method was called on.
  • did I mention that getStackTrace was slow?
  • the performance of getStackTrace is proportional to the depth of the stack. Testing with shallow stacks is pointless if someone then uses your code in a GUI, or Tomcat, or whatever... which have traces a mile long.... god forbid you do recursion!!!

To put things in perspective, on a 64-core computer (128 hardware threads), a program that was able to run at 80% CPU (i.e. 100 hardward-threads running at 100%) was reduced to about 3% CPU when about 1000 traces were taken each second.

This sort of performance is highly dependant on the JVM version, and the vendor. Stack traces are considered to be part of exception handling, and building the trace is not supposed to be fast.

Questions about Trace versions (FYI, this may, or may not help you):

echo && cat STrace.java && java -version && java STrace

public class STrace {
    public static void main(String[] args) {
        for (StackTraceElement ste : Thread.currentThread().getStackTrace()) {
            System.out.println(ste);
        }
    }
}
java version "1.7.0"
Java(TM) SE Runtime Environment (build pxp6470_27-20131115_04)
IBM J9 VM (build 2.7, JRE 1.7.0 Linux ppc64-64 Compressed References 20131114_175264 (JIT enabled, AOT enabled)
J9VM - R27_Java727_GA_20131114_0833_B175264
JIT  - tr.r13.java_20131113_50523
GC   - R27_Java727_GA_20131114_0833_B175264_CMPRSS
J9CL - 20131114_175264)
JCL - 20131113_01 based on Oracle 7u45-b18
java.lang.Thread.getStackTraceImpl(Native Method)
java.lang.Thread.getStackTrace(Thread.java:1203)
STrace.main(STrace.java:3)
\$\endgroup\$
  • \$\begingroup\$ Interesting. I knew the method call was slow, and like I said, that's why I make sure DEBUG is enabled before going through the trouble. DEBUG isn't enabled in any kind of production setting, of course. The most interesting part to me is that you say it slows down all threads. I'd think it only affects the current one. \$\endgroup\$ – asteri Mar 1 '14 at 1:06
  • \$\begingroup\$ Also, can you explain why different versions of Java would need to have a different GET_CALLING_METHOD_NAME_DEPTH? It seems like, regardless of the version, there will always be a certain amount of calls on the stack between the call and the desired method, right? \$\endgroup\$ – asteri Mar 1 '14 at 1:10
  • 1
    \$\begingroup\$ @JeffGohlke See this answer for "more" information stackoverflow.com/a/442773 \$\endgroup\$ – Marc-Andre Mar 1 '14 at 1:25

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.