10

Basically I have a logging statement inside of a method. Whenever the method is called, I want to easily call the name of the method, and append it to the logging statement. This is done to minimize the number of hard coded lines in my application. Is this possible to do it cheaply?

Jacob Mccain
  • 103
  • 1
  • 4
  • 1
    I don't think there's a good method that can be used at runtime to do that, but you could probably annotate the methods that need this functionality and then write an annotation processor that gets incorporated into your build process. At runtime it would work almost identically to hard coding the name of the method, but you wouldn't actually have to hard code anything. – Mike Deck Jul 14 '11 at 19:47
  • possible duplicate of [Getting the name of the current executing method](http://stackoverflow.com/questions/442747/getting-the-name-of-the-current-executing-method) – bmargulies Dec 28 '11 at 12:23

4 Answers4

15

No, not cheaply. The expensive and only way of doing it is with a StackTrace method call. Best to just hardcode it.

bluish
  • 26,356
  • 27
  • 122
  • 180
TravMan
  • 332
  • 2
  • 7
  • Well, that's too bad. Don't know why java can't do this cheaply yet. – Jacob Mccain Jul 14 '11 at 19:40
  • AspectJ was designed to deal with issues like this – antlersoft Jul 14 '11 at 19:43
  • How would I use AspectJ to do something like this? closest method I can find is "getSourceMethod()" – Jacob Mccain Jul 14 '11 at 19:49
  • 1
    why *should there* be a cheap way to do this? A "cheap" way to do this would need to keep track of the current method name whenever a new method/stackframe is entered/left, which would be an unnecessary expense 99.9% of the time. It would also be troublesome when the JIT compiler inlines certain methods. – matt b Jul 14 '11 at 19:52
  • Yep, considering inlining methods (which is aggressively done by a modern JIT for optimizing reasons), this would be quite expensive for a quite rare case - why would one need extensive logging on an optimized release build? If one really needs this stuff, just annotate the methods and generate that stuff at compile time - easy and no overhead apart from the logging. – Voo Jul 14 '11 at 19:54
  • 1
    Personally I just create a macro in my IDE so I can create a logging statement like "log.debug("${currentMethodName}: ");" with a few keystrokes - IntelliJ and Eclipse can even be setup to leave the cursor inside the right quote for maximal efficiency – matt b Jul 14 '11 at 19:56
3

If you only need method name and line number, you can do it reasonably fast. In my micro benchmark you can do about 120000 calls per second:

public class A {
  private static final int N = 1000000;

  public static void main(String[] args) {
    A a = new A();
    long l = System.currentTimeMillis();
    for (int i = 0; i < N; i++) {
      a.test(0);
      a.test(1);
      a.test(2);
    }
    double time = (System.currentTimeMillis() - l) / 1000d;
    System.err.println(time + " seconds");
    System.err.println(N / time + " calls/second");
  }

  String test(int i) {
    StackTraceElement ste = Thread.currentThread().getStackTrace()[i];
    return ste.getMethodName() + ":" + ste.getLineNumber();
  }
}

Also see this answer.

Community
  • 1
  • 1
Eugene Kuleshov
  • 31,461
  • 5
  • 66
  • 67
  • `String test(int i) { StackTraceElement ste = Thread.currentThread().getStackTrace()[i]; //String aString = "bleh"; //return aString; return ste.getMethodName(); } } ` I ran testing between doing a hard code and doing StackTrace //With StackTrace // 30.281 seconds //33024.00845414616 calls/second //Second run //17.937 seconds //55750 calls/second //With hard string //0.016 seconds //6.25E7 calls/second --- Basically a substantialy 100 fold increase in cost compared to a hard coded string return – TravMan Jul 14 '11 at 20:06
  • Right. But it all depends on how often this code is called. Say, if you call it only once a second, perhaps you can actually afford it. – Eugene Kuleshov Jul 14 '11 at 20:14
  • What about an annotation or something for simply recording the current method name, so I can cut paste the darn thing without changing the stupid string over and over? – ggb667 Oct 30 '13 at 17:52
2

Why reinvent the wheel, java.util.logging.Logger uses

 /**
* Gets the StackTraceElement of the first class that is not this class.
* That should be the initial caller of a logging method.
* @return caller of the initial logging method or null if unknown.
*/
private StackTraceElement getCallerStackFrame()
{
 Throwable t = new Throwable();
 StackTraceElement[] stackTrace = t.getStackTrace();
 int index = 0;

 // skip to stackentries until this class
 while(index < stackTrace.length
   && !stackTrace[index].getClassName().equals(getClass().getName()))
   index++;

 // skip the stackentries of this class
 while(index < stackTrace.length
   && stackTrace[index].getClassName().equals(getClass().getName()))
   index++;

  return index < stackTrace.length ? stackTrace[index] : null;
}

I doubt you will get it any faster than this.

[Edit] To get the calling methods name use,

StackTraceElement caller = getCallerStackFrame();
String name = caller != null ? caller.getMethodName() : "<unknown>"
Andrew
  • 13,757
  • 13
  • 66
  • 84
  • This uses StackTrace, and requires you to use the Java logger. It's fine if you're doing testing in a small app at home, but as per the test run below StackTrace is 100 times slower. – TravMan Jul 14 '11 at 20:10
  • @TravMan I agree, he just asked for an external method he could call that would return the callers method name, barring hard coding the name(and [wooo bad] reflection apparently), this method would be the fastest. 100 times has no reference frame however and I imagine this is all moot and we are chasing the micro-optimization fairy. – Andrew Jul 14 '11 at 20:16
1

did you consider writing sensible log messages instead? I mean, messages that just tell reader of log the "story" about how code runs? messages that really differ for different methods?

  log4j: some.package.Class1: method1: checkpoint #1
  log4j: some.package.Class1: method1: checkpoint #2
  log4j: some.package.Class2: method2: checkpoint #1
  log4j: some.package.Class2: method2: checkpoint #2

Been banging my head on log like above just a week or two ago (method names were hardcoded). Didn't feel it noticeably more helpful than no logging at all.

gnat
  • 6,213
  • 108
  • 53
  • 73