注册 登录  
 加关注

网易博客网站关停、迁移的公告:

将从2018年11月30日00:00起正式停止网易博客运营
查看详情
   显示下一条  |  关闭
温馨提示!由于新浪微博认证机制调整,您的新浪微博帐号绑定已过期,请重新绑定!立即重新绑定新浪微博》  |  关闭

为着理想勇敢前进

 
 
 

日志

 
 

打一句log时间不到一纳秒!完爆log4j、logback、slf4j……  

2011-11-23 04:14:42|  分类: 默认分类 |  标签: |举报 |字号 订阅

  下载LOFTER 我的照片书  |

用Java打log时,最不爽的一点就是即使你把log禁用了,只要打log的那行代码还在,每次执行到那一行还是有开销!尼玛Java没有宏啊,不能像C++那样做个编译选项不输出log时就直接跳过嘛。况且就算Java有宏,搞Java那帮道貌暗忍的人渣们也不会用的,他们只用XML和Annotation 来配置,感受不到编译选项带来的爱。Scala就有个-Xelide-below的编译选项可以排除掉不需要的函数调用,直接被搞Lift的混蛋们无视了,照样用着天杀的slf4j.

那么用slf4j打log到底有多大开销呢?这取决于slf4j的后端,不管用什么后端,真正输出log是需要IO的,一般都要几十上百微妙,也就是几万或者几十万纳秒,这部分开销是省不了的。我刚才抱怨的是那些被过滤掉的log,这些log的开销根据参数的复杂程度,要消耗从几个纳秒到上百个纳秒不等。

纳秒什么的最讨厌了,上百个纳秒,听起来好多!我一个纳秒都不想浪费!于是我就写了个pico-logger,pico-logger对org.slf4j.Logger包装了一下,但用pico-logger比直接用org.slf4j.Logger快得多。

如果一条log没被过滤掉,需要实际IO输出,用pico-logger和用slf4j一样快。但是slf4j打一条复杂log时,即使被过滤掉了,也需要消耗上百纳秒,而pico-logger过滤掉log时一纳秒都不浪费。无论多复杂的log,pico-logger在JVM优化后执行时间都不超过2个时钟周期,在我2.1GHz的CPU上只要952皮秒,一纳秒都不到。如果传给pico-logger的参数是没有额外变量的字符串字面量,执行时间为零。零执行时间的意思是你在任何深层循环输出log,只要一禁用掉,都对性能完全没有影响。

以下是在Scala中PicoLogger的用法:

object Foo extends PicoLogger(org.slf4j.LoggerFactory.getLogger(classOf[Foo]))
{
def foo() {
// 用PicoLogger,当trace级别被禁用时,零执行时间
trace("string literal")

// 用org.slf4j.Logger,当trace级别被禁用时,消耗4纳秒左右。不同后端性能稍有差异。
logger.trace("string literal")
}

def bar(p1: Int, p2: Double, p3: Long, p4: Byte, p5: Boolean) {
// 用PicoLogger,当trace级别被禁用时,2个时钟周期,在2GHz以上的CPU时不到1纳秒
trace("p1=" + p1 + ", p2=" + p2 + ", p3=" + p3 + ", p4=" + p4 + ", p5=" + p5)

// 用org.slf4j.Logger,当trace级别被禁用时,消耗约100纳秒
logger.trace("p1={},p2={},p3={},p4={},p5={}", Array(p1, p2, p3, p4, p5))
}
}

顺便做了个benchmark,对比了一下slf4j和pico-logger的性能。在下列表格中,每一项的单位是时钟周期,即以java -server方式运行,并经过充分优化后执行需要消耗的CPU时钟周期。在我2.1GHz的CPU上,每个时钟周期是0.476纳秒,即476皮秒。与slf4j中用格式化字符串的代码对应的pico-logger用例是拼接字符串。

字符串字面量字符串格式+2个字符串参数字符串格式+2个整数参数字符串格式+5个各种参数
slf4j+log4j151641+186+
slf4j+logback9939+191+
slf4j+java.util.logging6734+187+
pico-logger02

slf4j整数参数会变慢,是因为slf4j需要为非引用的参数装箱。每次装箱就要消耗大约20个时钟周期,因为装箱涉及内存分配,所以每次装箱消耗的时钟周期数不等。上述表格中的数字都是取最好的结果,实际上平均成绩还会比这个最好成绩消耗更多的CPU时间。字符串字面量下面的“0”表示如果输出的这条log会被过滤掉,那么哪怕连写10遍,JVM优化后都是直接跳过这些代码的压根不作任何判断。

代码我放Google Code上了:http://pico-logger.googlecode.com/,一共只有一个类,性能评测的代码也在里面。
  评论这张
 
阅读(3630)| 评论(4)
推荐 转载

历史上的今天

在LOFTER的更多文章

评论

<#--最新日志,群博日志--> <#--推荐日志--> <#--引用记录--> <#--博主推荐--> <#--随机阅读--> <#--首页推荐--> <#--历史上的今天--> <#--被推荐日志--> <#--上一篇,下一篇--> <#-- 热度 --> <#-- 网易新闻广告 --> <#--右边模块结构--> <#--评论模块结构--> <#--引用模块结构--> <#--博主发起的投票-->
 
 
 
 
 
 
 
 
 
 
 
 
 
 

页脚

网易公司版权所有 ©1997-2018