在高并发的情况下小小的日志打印会严重影响到性能。
来源:互联网 发布:中世纪2原版优化9血统 编辑:程序博客网 时间:2024/04/30 00:53
以前编程不喜欢对每个功能、重要的方法进行日志的格式化输出,即使要输出,也没按照规范进行输出。前段时间,随着我们平
台用户量不断增加,出现些问题。当用户遇到问题,就给我们客服打电话。然后客服毫无疑问就来找我们。当我们接收到这样问题的时候,
我们首先要定位是什么原因造成的。当时就是因为自己方法中输出的日志很少,而且不规范,所以根本找不到具体原因,虽然最后问题解
决了,但是花费很多不必要的时间。
那么我们怎样使用好日志这一利器呢?
1.写好日志:
我们先来看一下糟糕的日志打印:
@ResponseBody@RequestMapping(value = "unbind.do", method = RequestMethod.POST)public Object unbind(String bankId, String memberId) {if (StringUtils.isBlank(bankId) || StringUtils.isBlank(memberId)) {return new Result(false, "解绑参数不合法!");}try {authPayTwoService.unbind(bankId, memberId);} catch (AppException e) {LOG.info("认证支付2.0(unbind)失败:{}",e);return new Result(false, e.getMessage());} catch (Exception e) {LOG.info("认证支付2.0(unbind)]失败:{}", e);return new Result(false, "解绑银行卡失败,请重试");}return new Result(true, "解绑银行卡成功!");}
上面代码是严格不符合规范的,每个公司都有自己的打印要求。首先日志的打印必须是以logger.error、logger.warn或logger.info
的方式打印出来。日志打印格式应包含[系统来源] 错误描述 [关键信息],日志信息要能打印出能看懂的信息,有前因和后果。方法的入参和
出参也要考虑打印出来。
好的日志格式打印:
@ResponseBody@RequestMapping(value = "unbind.do", method = RequestMethod.POST)public Object unbind(String bankId, String memberId) {LOG.info("[解绑银行卡--认证支付2.0][params:bankId=" + bankId + ",memberId="+ memberId + "]");if (StringUtils.isBlank(bankId) || StringUtils.isBlank(memberId)) {return new Result(false, "解绑参数不合法!");}try {authPayTwoService.unbind(bankId, memberId);} catch (AppException e) {LOG.error("[解绑银行卡--认证支付2.0(unbind)-mas][error:{}",e);return new Result(false, e.getMessage());} catch (Exception e) {LOG.error("[解绑银行卡--认证支付2.0(unbind)][error:{}",e);return new Result(false, "解绑银行卡失败,请重试");}return new Result(true, "解绑银行卡成功!");}
从上面的代码可以很轻松的定位方法、传入的参数及异常是调用接口抛出的异常还是系统级的异常。
出格式也有很大的关系,希望看到此文的朋友们多多优化自己的日志和输出格式。2.良好的日志输出格式
最近测试同事采用两百并发对项目进行测试。
格式优化前:
经过测试查看每秒的并发量平均只有110多如下图:
通过查看jvm 虚拟机发现很多日志线程出现BLOCKED,如下:
"http-saoma%2F192.168.6.162-8097-132" daemon prio=10 tid=0x00002aaab88e4800 nid=0x2c8e runnable [0x0000000045274000] java.lang.Thread.State: BLOCKEDat java.lang.Throwable.getStackTraceElement(Native Method)at java.lang.Throwable.getOurStackTrace(Throwable.java:591)- locked <0x00000007691390d0> (a java.lang.Throwable)at java.lang.Throwable.getStackTrace(Throwable.java:582)at sun.reflect.GeneratedMethodAccessor29.invoke(Unknown Source)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)at java.lang.reflect.Method.invoke(Method.java:597)at org.apache.log4j.spi.LocationInfo.<init>(LocationInfo.java:139)at org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:253)at org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:500)at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:65)at org.apache.log4j.PatternLayout.format(PatternLayout.java:506)at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)at org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:369)at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)- locked <0x0000000780fb1e00> (a org.apache.log4j.DailyRollingFileAppender)at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)at org.apache.log4j.Category.callAppenders(Category.java:206)- locked <0x00000007800020a0> (a org.apache.log4j.spi.RootLogger)at org.apache.log4j.Category.forcedLog(Category.java:391)at org.apache.log4j.Category.log(Category.java:856)at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:497)
我们定位org.apache.log4j.spi.LocationInfo类的代码如下:String s; // Protect against multiple access to sw. synchronized(sw) {t.printStackTrace(pw);s = sw.toString();sw.getBuffer().setLength(0); } //System.out.println("s is ["+s+"]."); int ibegin, iend; // Given the current structure of the package, the line // containing "org.apache.log4j.Category." should be printed just // before the caller. // This method of searching may not be fastest but it's safer // than counting the stack depth which is not guaranteed to be // constant across JVM implementations. ibegin = s.lastIndexOf(fqnOfCallingClass);从上面可以看出在该方法中用了synchronized锁,然后又通过打印堆栈来获取行号。那么肯定会影响到性能的,我们通过看
此时log4j.properties日志文件配置的输出格式为:
%d %-5p %c:%L [%t] - %m%n
很明显就是%l输出行号的问题,那么我们把%l去掉结果会不会好很多呢?
把log4j.properties文件中输出格式改为:
%d %-5p %c [%t] - %m%n
输出格式优化后:
再看每秒的并发量如下图:
从图中我们可以看出并发量提高了40多,同时jvm线程日志中java.lang.Thread.State: BLOCKED也没有了。看来程序的性能和日志的输
- 在高并发的情况下小小的日志打印会严重影响到性能。
- 使用Google的开源TCMalloc库,提高MySQL在高并发情况下的性能
- 使用Google的开源TCMalloc库,提高MySQL在高并发情况下的性能
- 使用Google的开源TCMalloc库,提高MySQL在高并发情况下的性能
- 使用Google的开源TCMalloc库,提高MySQL在高并发情况下的性能
- 静态方法在高并发情况下对性能的影响
- 提高MySQL在高并发情况下的负载
- 高并发高负载情况下常见的3种性能问题
- 高并发高负载情况下常见的3种性能问题
- 高并发高负载情况下常见的3种性能问题
- 高并发高负载情况下常见的3种性能问题
- 索引的建立方式,直接会影响到查询性能。
- SpringMVC是单例的,高并发情况下,如何保证性能的?
- SpringMVC是单例的,高并发情况下,如何保证性能的?
- SpringMVC是单例的,高并发情况下,如何保证性能的?
- SpringMVC默认单例的,高并发情况下,如何保证性能的?
- SpringMVC是单例的,高并发情况下,如何保证性能的?
- 测试Nginx 和 Tomcat 高并发情况下处理静态页面的性能
- JNI的基本语法
- 无法获得VMCI驱动程序的版本
- 深入探究文件I/O
- Android判断设备网络连接状态,并判断连接方式
- linux学习之计算机基础(一)
- 在高并发的情况下小小的日志打印会严重影响到性能。
- akka actor监控(monitoring)
- 工作
- Button和ImageButton的背景选择
- 51NOD 1537 分解
- 37. Sudoku Solver
- 如何解决tomcat8080端口占用问题
- appium 原理
- 使用Cygwin编译Windows版本的Rsync