我们在使用Java的日志库进行日志打印时，有个微小的功能，打印当前代码行所在的类名，方法名以及行号等信息，这个功能是如何实现的呢？说起来这还是一个推动JDK发展的事情，从最初的没提供相关的能力，到JDK1.5之后提供Thread.currentThread().getStackTrace()方法能够方便的获取StackTraceElement数组，进而方便的拿到类名与行号等信息，也是非常好的一个进化例子。但是我们这里关注的是调用这个方法，给应用带来的消耗是怎么样的？这是个快速简洁的方式么？
上测试验证的代码如下：
/**
* Thread.currentThread().getStackTrace() 获取代码类名与行号的消耗
*/
public class CodeLine {
public static final boolean DEBUG = false;
public static void main(String[] args) {
CodeLine CL = new CodeLine();
CL.mainTestFunction(20,1000,1);
CL.mainTestFunction(20,1000,1);
CL.mainTestFunction(20,1000,1);
CL.mainTestFunction(20,1000,0);
CL.mainTestFunction(20,1000,0);
CL.mainTestFunction(20,1000,0);
CL.mainTestFunction(40,1000,1);
CL.mainTestFunction(40,1000,1);
CL.mainTestFunction(40,1000,1);
CL.mainTestFunction(40,1000,0);
CL.mainTestFunction(40,1000,0);
CL.mainTestFunction(40,1000,0);
CL.mainTestFunction(80,1000,1);
CL.mainTestFunction(80,1000,1);
CL.mainTestFunction(80,1000,1);
CL.mainTestFunction(80,1000,0);
CL.mainTestFunction(80,1000,0);
CL.mainTestFunction(80,1000,0);
CL.mainTestFunction(20,10,1);
CL.mainTestFunction(20,10,1);
CL.mainTestFunction(20,10,1);
CL.mainTestFunction(20,10,0);
CL.mainTestFunction(20,10,0);
CL.mainTestFunction(20,10,0);
}
/**
*
* @param deep 堆栈深度
* @param count 循环次数
* @param method 获取方式:0-关闭；1-Thread.currentThread().getStackTrace()
*/
public void mainTestFunction(int deep,int count,int method)
{
long stt = System.nanoTime();
testStackTrace(deep,count,method);
long end = System.nanoTime();
System.out.println(String.format("类型:[%2d],深度:[%10d],次数:[%10d],耗时:[%10d]纳秒",method,deep,count,(end-stt)));
}
/**
*
* @param deep 堆栈深度
* @param count 循环次数
* @param method 获取方式:0-关闭；1-Thread.currentThread().getStackTrace()
*/
public void testStackTrace(int deep,int count,int method)
{
if(deep!=0)
{
testStackTrace(deep-1,count,method);
}
else
{
for(int i=0;i<count;i++)
{
testStackTraceDirect(i,method);
}
}
}
public void testStackTraceDirect(int currentCount,int method)
{
String className = "";
int lineNumber = 0 ;
switch (method){
case 1:
StackTraceElement[] result = Thread.currentThread().getStackTrace();
className = result[1].getClassName();
lineNumber = result[1].getLineNumber();
}
if(DEBUG&¤tCount==0)
{
System.out.println("className:"+ className + ",line:" + lineNumber);
}
}
}
一次本地运行效果如下：
类型:[ 1],深度:[ 20],次数:[ 1000],耗时:[ 21663284]纳秒
类型:[ 1],深度:[ 20],次数:[ 1000],耗时:[ 15444246]纳秒
类型:[ 1],深度:[ 20],次数:[ 1000],耗时:[ 20645272]纳秒
类型:[ 0],深度:[ 20],次数:[ 1000],耗时:[ 43295]纳秒
类型:[ 0],深度:[ 20],次数:[ 1000],耗时:[ 47645]纳秒
类型:[ 0],深度:[ 20],次数:[ 1000],耗时:[ 19836]纳秒
类型:[ 1],深度:[ 40],次数:[ 1000],耗时:[ 30264831]纳秒
类型:[ 1],深度:[ 40],次数:[ 1000],耗时:[ 28124662]纳秒
类型:[ 1],深度:[ 40],次数:[ 1000],耗时:[ 25975522]纳秒
类型:[ 0],深度:[ 40],次数:[ 1000],耗时:[ 6565]纳秒
类型:[ 0],深度:[ 40],次数:[ 1000],耗时:[ 4495]纳秒
类型:[ 0],深度:[ 40],次数:[ 1000],耗时:[ 5969]纳秒
类型:[ 1],深度:[ 80],次数:[ 1000],耗时:[ 50870539]纳秒
类型:[ 1],深度:[ 80],次数:[ 1000],耗时:[ 51951023]纳秒
类型:[ 1],深度:[ 80],次数:[ 1000],耗时:[ 48961432]纳秒
类型:[ 0],深度:[ 80],次数:[ 1000],耗时:[ 5279]纳秒
类型:[ 0],深度:[ 80],次数:[ 1000],耗时:[ 4634]纳秒
类型:[ 0],深度:[ 80],次数:[ 1000],耗时:[ 4502]纳秒
类型:[ 1],深度:[ 20],次数:[ 10],耗时:[ 151152]纳秒
类型:[ 1],深度:[ 20],次数:[ 10],耗时:[ 254739]纳秒
类型:[ 1],深度:[ 20],次数:[ 10],耗时:[ 323122]纳秒
类型:[ 0],深度:[ 20],次数:[ 10],耗时:[ 747]纳秒
类型:[ 0],深度:[ 20],次数:[ 10],耗时:[ 481]纳秒
类型:[ 0],深度:[ 20],次数:[ 10],耗时:[ 397]纳秒
其中类型1，是执行类名与代码行号获取，类型0是执行路径完全相同，但是不进行类名与行号获取。对比发现，其消耗差别是非常大的。堆栈深度20，调用10次日志打印，可能是一个应用系统中，很常见的一次交易处理在某个应用中的场景，在打印行号的情况下，仅仅是日志语句的打印行号的消耗，就消耗了0.2~0.3毫秒。这还不是一个日志库的全部执行时间。
在正式运行的系统中，正常日志打印，格式字符串中，无需进行代码类与行号的相关配置。在出现异常时，异常堆栈自带相关信息。在日常调试时，可以修改格式字符串，打印相关的信息，但正式运行，请关掉。