Log4j是输出日志时是如何获知当前方法、行号的

记得最早在项目中用Log4j的时候,也是觉得在每一个要记载日志的类中或者某个上层类中要声明一个Logger属性挺麻烦的

或者

于是就写了一个自己的Logger类UnmiLogger,也就是把Log4j的Logger包装一下,直接调用Logger的日志输出方法,info、debug、warn等,只不过在UnmiLogger中把日志输出方法都改为静态的,让在别的代码中方便使用。

使用起来就只要在需要打印日志的地方用 UnmiLogger.debug("Hello UnmiLogger")就行,但是这样用的话实际输出的日志就会有很多问题的。例如,log4j.properties中配置的输出格式为:

那么输出来的日志信息就总是

[main] [UnmiLogger.debug:45] Hello UnmiLogger

期望输出的类名和方法名及行号总是指向了UnmiLogger类,而且也不能依包来过滤控制输出,因为Category也总是UnmiLogger。

后来就思考如何输出期望的日志信息,如类Test中用代码UnmiLogger.debug("Hello")输出日志时,要让显示的信息为Test类和Test类的哪个方法、哪行代码。于是头脑中也浮现过这样一个问题:

执行时,在某一个类的方法中如何能知道是谁(哪个类、哪个方法)调用了它?

这个问题很容易让我想到介助于动态代码、或者运行时修改字节码、或者AOP、方法拦截。这里列出来的四个说法基本也是围绕着一个目的。

用上面的方法感觉着眼点太大,一下也比较难以吃透,所以没有深究。

初写Java代码的人,在处理异常的时候,常常会Catch到某个异常e,然后就只是不负责任的用 e.printStackTrace(),打印一大堆,不作更实际的处理,但是我们也能够从打印的调用栈信息获得启发,异常堆栈信息从里至外显示出每一层是什么类、哪个方法、哪行代码的信息,这不就正能为我的UnmiLogger所用吗!

只要在UnmiLogger的日志输出方法,如debug中new一个异常Throwable然后获取取异常栈信息,取上一层就是使用它的类了,从中获取到出异常的类名、方法名、代码行。

确定类名、方法名、代码行的工作算是完成了,可也总会想:每打印一条日志都要产生一个异常,然后抠出它的异常栈信息,这样做的成本是不是太高了啊。从此继续反回,在Log4j的代码中它又是如何获取到行号信息呢?

至于上面的解决办法如何做到日志按包过滤输出,还留待后叙……

不能光想不做,近段时间也闲着也不安,那就奋不顾身的钻到Log4j的源码中去探个究竟吧!

在类com.unmi.Test的main方法中写了这样两行代码去追踪

执行过程中发现在输出代码行数的时候,方法调用栈如下图如示:

Log4j是通过LocationInfo类来获知调试代码位置信息的,看到上图上加亮的那行代码就能领悟到,原来,原来Log4j想的跟咱也是一样,它也是�ü齨ew一个异常Throwable来得到那些信息的。说明我在软件行里混达的还算是块料。

再继续看LocationInfo的构造部分代码片断,

这时候可以看到this.fullInfo的值是"com.unmi.Test.main(Test.java:14)",这就是要输出的信息了,格式化输出时再取子字符串就行了。

亲爱的朋友,如果你读到前面这几话的时候,不妨让我们再回到前面写的那个日志工具类UnmiLogger,在debug方法中,为了得到行号等信息,new 过一次Throwable异常了,临到实际调用Logger的debug方法时,又要new一次Throwable了,所以这样看来,自己写的那个日志工具类执行代价还真不小啦。

因此,如果以后要写象UnmiLogger那样的日志工具类的话,可以考虑更为大胆的举措:真接修改类LocationInfo的行为。当然还不能忘记要解决前面的一个问题--日志分包过滤输出,必要时还得在Log4j源码中动些手术,遵照它的开源协议,公开这部分代码也无所谓,更何况真的没必要这么认真的。

类别: Uncategorized. 阅读(2,812). 订阅评论. TrackBack.

Leave a Reply

Be the First to Comment!

avatar
wpDiscuz