一些日志优化相关的东东.

1. 关掉没用的appender

现在我们所有的系统都会把日志输出到指定的文件,为了本地开发测试方便,我们也会把日志输出到控制台。在生产环境输出到控制台是完全没有必要的,既浪费了存储空间,又浪费了性能,请在生产环境去掉ConsoleAppender

  • logback去掉
    1
    ch.qos.logback.core.ConsoleAppender
    
  • log4j去掉
    1
    org.apache.log4j.ConsoleAppender
    

使用logback的同学也可以如下操作:

1.添加依赖

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
<dependency>
		<groupId>org.codehaus.janino</groupId>
		<artifactId>janino</artifactId>
		<version>2.5.16</version>
</dependency> 2.修改logback.xml中原ConsoleAppender配置如下:

<if condition='property("os.name").toUpperCase().contains("WINDOWS")'>
	<then>
		<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
			<encoder>
				<pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36}:%L-%msg%n%n</pattern>
			</encoder>
		</appender>
		<root>
			<appender-ref ref="STDOUT" />
		</root>
	</then>
</if>

上面的配置表示在windows中运行时日志输出到控制台,在其他系统中日志不输出到控制台

2. 禁用日志收集栈信息

在写日志时,打印行号能方便我们快速定位出问题的代码。此功能通过生成栈信息,然后定位到合适的栈帧来实现。禁用此功能会提高日志性能。

异步日志实现默认关闭了收集栈信息,见

1
ch.qos.logback.classic.AsyncAppender#includeCallerData

对于同步日志,只需要把

1
pattern
中的
1
%L
去掉就可以禁用栈信息。

3. 使用异步日志

3.1 logback

logback只需要用异步appender包裹原来的appender就可以了

1
2
3
<appender name="ASYNC_ROLLING-cs" class="com.yjf.common.log.LogbackAsyncAppender">
	<appender-ref ref="ROLLING-cs" />
</appender>

目前我们使用了用于输出日志到文件的

1
ch.qos.logback.core.rolling.RollingFileAppender
和输出日志到rabbitmq的
1
com.yjf.monitor.client.integration.log.appender.jms.LogbackMsgRollingAppenderAdapter
,请都用上面的
1
LogbackAsyncAppender
包裹住。

此配置下,对象先放入一个队列,然后由另外一个线程来处理具体的日志输出,实现异步化,实现流程如下:

  • queue大小为1024,如果queue剩余空间小于100时,会做丢弃判断
  • 如果queue剩余空间小于100时,会丢弃TRACE、DEBUG日志,也会丢弃LoggerName不以com.yjf开始的INFO日志
  • 如果queue没有剩余空间为0时,会阻塞业务线程,直到queue有剩余空间
  • 输出日志到文件的appender,由于会用锁来控制多线程的写入,这种用单线程来写文件的方式很完美。
  • 输出日志到rabbitmq的appender,
    1
    LogbackMsgRollingAppenderAdapter
    
    在并发下会有性能问题,因为
    1
    LogbackMsgRollingAppenderAdapter
    
    内部只用到一个channel,如果遇到高并发场景,请给
    1
    CachingConnectionFactory
    
    设置合理的channelCacheSize值

3.2 log4j

  • 写日志到文件的appender,用
    1
    org.apache.log4j.AsyncAppender
    
    代替
    1
    org.apache.log4j.DailyRollingFileAppender
    
  • 写日志到rabbitmq的appender,建议用
    1
    com.yjf.common.log.Log4jAsynAmqpAppender
    
    ,内部也用queue来实现异步化

4. logger api增强

下面是常用的使用方式:

1
2
3
logger.info("金额无效,手续费大于或者等于提现总金额.charge:{},amount:{}", new Object[] { 1, 2, 3 });
logger.info("金额无效,手续费大于或者等于提现总金额.charge:{},amount:{},test:{}", 1, 2, 3); 
LoggerFormat.info(String.format("金额无效,手续费大于或者等于提现总金额.charge:%s,amount:%s,test:%s", 1, 2,3), logger);

第一种是slf4j提供的原生api,第二种是yjf-common-utils提供的支持可变的参数的logger,第三种是yjf-common-util提供的日志工具类。这三种使用方式在日志级别为error的情况下,跑一百万次测试出的性能数据如下:

1
2
3
4
5
6
7
8
LoggerFactoryTest.testLogOri: [measured 1000000 out of 1020000 rounds, threads: 4 (all cores)]
 round: 0.00 [+- 0.00], round.gc: 0.00 [+- 0.00], GC.calls: 2, GC.time: 0.62, time.total: 2.67, time.warmup: 0.04, time.bench: 2.63

LoggerFactoryTest.testYjfLogger: [measured 1000000 out of 1020000 rounds, threads: 4 (all cores)]
 round: 0.00 [+- 0.00], round.gc: 0.00 [+- 0.00], GC.calls: 1, GC.time: 0.72, time.total: 3.43, time.warmup: 0.06, time.bench: 3.37

LoggerFactoryTest.testLogUtils: [measured 1000000 out of 1020000 rounds, threads: 4 (all cores)]
 round: 0.00 [+- 0.00], round.gc: 0.00 [+- 0.00], GC.calls: 14, GC.time: 1.78, time.total: 11.62, time.warmup: 0.22, time.bench: 11.40

从这些数据可以看出,第三种使用方式由于在方法调用时就有字符串拼接的开销,在error级别下,性能肯定不是很好。

在日志级别为info情况下,这种差距不是很大,但是如果我们使用异步日志,字符串的拼接在独立的线程中完成,不会在调用线程中完成,业务整体执行时间会减少。

第三种方式还有一个问题,行号永远显示的是LoggerFormat.info方法的行号,不便于我们定位问题。“懒”的同学就用第二种方式吧,支持变长参数,例子如下:

1
2
3
4
5
6
7
8
import com.yjf.common.log.Logger;
import com.yjf.common.log.LoggerFactory;
...		
Logger logger = LoggerFactory.getLogger(LoggerFactoryTest.class
	.getName());
...
logger.info("xx:{} xx:{} xx:{}","a","b","c");
logger.info("xx:{} xx:{} xx:[]", "a","b","c", new RuntimeException("挂了"));

请不要再使用

1
com.yjf.common.log.LoggerFormat
1
com.yjf.common.lang.util.PrintLogTool

5. tomcat日志优化

tomcat embed默认日志使用的是

1
org.apache.juli.logging.DirectJDKLog
,此日志使用了
1
java.util.logging.Logger
,此logger使用了jre下面的配置文件
1
$JAVA_HOME\jre\lib\logging.properties
,此配置文件配置了一个处理器
1
java.util.logging.ConsoleHandler
,它只做了一个事情,使用
1
System.err
来作为默认的日志输出,也就是说tomcat embed遇到不能处理的异常后,用System.err来打印日志。(见:
1
org.apache.catalina.core.StandardWrapperValve#invoke
方法)

我们使用的的tomcat和tomcat embed有点差别,tomcat 中使用了

1
org.apache.juli.FileHandler
,此输出位置为
1
$CATALINA_HOME/logs/localhost.yyyy-MM-dd.log
,也就是说tomcat在遇到他搞不定的异常时,把日志输出到了此位置。 tomcat把输出和错误输出都打印到catalina.out文件了,见catalina.sh

1
2
org.apache.catalina.startup.Bootstrap "$@" start \
  >> "$CATALINA_OUT" 2>&1 "&"

这也解释了上次易交易产品遇到的那个问题,spring mvc action递归调用自己,catalina.out文件中没有异常日志。但是我在本地使用tomcat embed测试,会在控制台输出

1
StackOverflowError

tomcat日志优化点:

  • 1
    org.apache.juli.AsyncFileHandler
    
    代替
    1
    org.apache.juli.FileHandler
    
  • 现在我们应用的日志目录都改为
    1
    /var/log/webapps/{project_name}/
    
    。为了便于管理,tomcat 所有日志文件也会输出到
    1
    /var/log/webapps/{project_name}/
    
    路径

以上优化已提交到定制化tomcat模板。

6.优化J.U.C

J.U.L代表java内置的日志机制,上面部分提到tomcat在遇到他搞不定的异常时,会把日志输出到

1
localhost.yyyy-MM-dd.log
。这样很不爽,很多同学在检查应用异常时,下意识的不会去看此日志文件,为了避免此问题,请使用下面的解决方案:

  1. 使用

    1
    com.yjf.common.log.LogbackConfigListener
    
    ,使用方法见doc

    请使用yjf-common-util版本大于等于1.6.9.20130708的包

  2. logback增加配置

    1
    2
    3
     <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
     		<resetJUL>true</resetJUL>
      		</contextListener>
    

从此以后,所有的异常日志都会在应用日志文件中找到。

7. 性能测试

测试四种情况,普通日志输出,普通日志禁用线程栈信息,异步日志,异步日志禁用线程栈信息,测试结果如下:

1
2
3
4
5
6
7
8
9
10
11
LoggerPerfTest.testCommonLogger: [measured 100000 out of 101000 rounds, threads: 16 (physical processors: 4)]
 	round: 0.00 [+- 0.00], round.block: 0.00 [+- 0.00], round.gc: 0.00 [+- 0.00], GC.calls: 2, GC.time: 0.12, time.total: 10.73, time.warmup: 0.11, time.bench: 10.62
 	
LoggerPerfTest.testCommonLoggerWithoutStackInfo: [measured 100000 out of 101000 rounds, threads: 16 (physical processors: 4)]
 	round: 0.00 [+- 0.00], round.block: 0.00 [+- 0.00], round.gc: 0.00 [+- 0.00], GC.calls: 2, GC.time: 0.04, time.total: 3.93, time.warmup: 0.14, time.bench: 3.79
 	
LoggerPerfTest.testAsyncLogger: [measured 100000 out of 101000 rounds, threads: 16 (physical processors: 4)]
 	round: 0.00 [+- 0.00], round.block: 0.00 [+- 0.00], round.gc: 0.00 [+- 0.00], GC.calls: 3, GC.time: 0.15, time.total: 2.77, time.warmup: 0.06, time.bench: 2.71
 	
LoggerPerfTest.testAsyncLoggerWithoutStackInfo: [measured 100000 out of 101000 rounds, threads: 16 (physical processors: 4)]
 	round: 0.00 [+- 0.00], round.block: 0.00 [+- 0.00], round.gc: 0.00 [+- 0.00], GC.calls: 0, GC.time: 0.00, time.total: 1.86, time.warmup: 0.00, time.bench: 1.85

可见异步日志性能会提升不少,不收集栈信息性能也会提升不少。

很多时候,我们需要连到远程应用服务器上去观察java进程的运行情况。由于邪恶的防火墙限制我们很难直接连到应用服务器。所以,也有了本文… 常见的网络拓扑结构如下:

如上图所示,办公电脑通过互联网连接跳板机,在跳板机上,我们可以访问应用服务器,查看应用服务器日志或做其他操作。现在我们需要在办公电脑上监控应用服务器1上的java进程。

ssh tunneling

由于防火墙的限制,我们不能直接访问应用服务器。我们可以通过ssh tunneling来实现从办公电脑访问到应用服务器服务端口。

  • 跳板机:内网ip:192.168.0.1 外网ip:14.17.32.211 ssh端口:22

  • 应用服务器1:内网ip:192.168.0.2 应用端口:11113

通过ssh tunneling,我们利用ssh client建立ssh tunneling映射如下:

1
127.0.0.1:11113->14.17.32.211:22->192.168.0.2:11113

本地应用客户端通过访问本地11113端口,ssh client会把请求转发到应用服务器192.168.0.2:11113

JMX

一个典型的jmx url:

service:jmx:rmi://localhost:5000/jndi/rmi://localhost:6000/jmxrmi

这个JMX URL可以分为如下几个部分:

  • service:jmx: 这个是JMX URL的标准前缀,所有的JMX URL都必须以该字符串开头。

  • rmi: 这个是connector server的传输协议,在这个url中是使用rmi来进行传输的。JSR 160规定了所有connector server都必须至少实现rmi传输,是否还支持其他的传输协议依赖于具体的实现。比如MX4J就支持soap、soap+ssl、hessian、burlap等等传输协议。

  • localhost:5000: 这个是connector server的IP和端口,该部分是一个可选项,可以被省略掉。因为我们可以通过后面的服务注册端口,拿到jmx服务运行的端口信息。

  • /jndi/rmi://localhost:6000/jmxrmi: 这个是connector server的路径,具体含义取决于前面的传输协议。比如该URL中这串字符串就代表着该connector server的stub是使用jndi api绑定在rmi://localhost:6000/jmxrmi这个地址。可以理解为,localhost:6000提供了服务的注册查询端口,具体的jmx服务实现在localhost:5000

java进程一般通过如下的配置启动jmx:

-Dcom.sun.management.jmxremote -Djava.rmi.server.hostname=192.168.0.2 -Dcom.sun.management.jmxremote.port=11113 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false

通过上面的配置可以看出,只配置了服务注册查询端口11113,而实际的jmx服务运行端口是在运行时通过11113获取到的。

如何实现

上面提到了用ssh tunneling来实现端口转发,跳过防火墙的限制,也讲到了jmx的服务暴露方式。同时引出了我们遇到的问题,我们为了监控远程服务器上的java进程,我们能通过本地的11113端口访问到远程服务器上的JMX服务注册查询端口11113,但是JMX服务运行端口,我们不知道(因为是在运行时随机指定的),这样貌似走进了死胡同。

幸运的是我们自己来初始化JMXConnectorServer时,我们可以指定具体的jmx服务端口,并且还可以指定JMX服务端口和JMX注册查询端口为同一个端口。比如我们可以设置JMX url为:

1
service:jmx:rmi://localhost:11113/jndi/rmi://localhost:11113/jmxrmi

解决方案如下:

  1. 通过Java Agent实现在java业务代码运行之前,启动jmx server,并且设置jxm服务注册查询端口和服务端口为同一端口,JMX URL为:

    1
     service:jmx:rmi://127.0.0.1:11113/jndi/rmi://127.0.0.1:11113/jmxrmi
    
  2. 通过ssh tunneling实现端口转发,我们的JMX client只需要访问本地的端口就能跳过防火墙的限制

注意:这里ip地址写为127.0.0.1是有原因的,看看我们的请求流程:

  • JMX client访问本地的127.0.0.1:11113
  • 注册查询请求被ssh tunneling转发到应用服务192.168.0.2:11113
  • 应用服务器上的java进程JMX注册查询服务会告诉JMX client,JMX服务在127.0.0.1:11113
  • 然后JMX client再访问127.0.0.1:11113
  • 服务请求又被ssh tunneling转发到应用服务192.168.0.2:11113,这次建立了JMX服务请求连接

操作步骤

  1. 下载jmx agent后执行
    1
    mvn package
    
    ,在target目录会生成jmxagent-0.0.1.jar,上传此jar包到服务器
  2. 配置java服务进程启动参数

    1
     -javaagent:/root/jmxagent-0.0.1.jar -Djmx.rmi.agent.hostname=127.0.0.1 -Djmx.rmi.agent.port=11113
    

    上面设置jmx服务ip为127.0.0.1,服务端口为11113,使用javaagent jar包路径为/root/jmxagent-0.0.1.jar

  3. 启动java服务

    在控制台中,可以看到

    1
    Start the RMI connector server
    
    的字样,说明服务正常启动了。

  4. 建立ssh tunneling

    在xshell中配置ssh tunneling很简单,只需要两个步骤:

    配置连接,我们这里需要连接到跳板机的ssh服务,如下图:

    配置tunneling,配置稳定端口11113,应用服务器192.168.0.2:11113

  5. 使用jmx client监控远程服务

    在jvisualvm中添加JMX连接,如下图:

  6. enjoy!

PS:附带一个maven启用此解决方案的脚本

1
2
export MAVEN_OPTS="-server -Xms8192m -Xmx8192m -XX:PermSize=128m -XX:MaxPermSize=256m -XX:+PrintGCTimeStamps -XX:+PrintGCDetails  -XX:SurvivorRatio=4 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:MaxTenuringThreshold=5 -XX:+CMSClassUnloadingEnabled -verbosegc  -Xloggc:/var/log/xxx/gc.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/log/xxx/oom.hprof  -Djava.awt.headless=true  -javaagent:/root/jmxagent-0.0.1.jar -Djmx.rmi.agent.hostname=127.0.0.1 -Djmx.rmi.agent.port=11113"
mvn exec:java -Dexec.mainClass="com.xxx.Bootstrap" &

JDK7在Throwable对象中增加了一个新的构造器

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
protected Throwable(String message, Throwable cause,
                    boolean enableSuppression,
                    boolean writableStackTrace) 第三个参数表示是否启用suppressedExceptions(try代码快中抛出异常,在finally中又抛出异常,导致try中的异常丢失) 。第四个参数表示是否填充异常栈,如果为false,异常在初始化的时候不会调用本地方法fillInStackTrace。 <!--more--> 在业务开发中,我们会使用很多异常来表示不同的业务限制,比如用户余额不足、用户权限不够、参数不合法,这样的异常是不需要填充栈信息的,所以我们可以使用如下的代码来提高异常生成性能:

package com.yjf.common.exception;	
public class AppExcetpion extends RuntimeException {
	private static final long serialVersionUID = 1L;		
	public AppExcetpion() {
		this(null, null);
	}
	public AppExcetpion(String message, Throwable cause) {
		super(message, cause, true, false);
	}
	
	public AppExcetpion(String message) {
		this(message, null);
	}
	
	public AppExcetpion(Throwable cause) {
		this(null, cause);
	}

}

使用此异常会比以前我们使用的异常性能提高10多倍。

1
2
2013-05-09 14:58:39 [main] ERROR com.yjf.common.exception.JAVA7ExceptionTest.testJava7:23 - 运行:2000000/2010000 耗时:457ms
2013-05-09 14:58:45 [main] ERROR com.yjf.common.exception.JAVA7ExceptionTest.testOri:40 - 运行:2000000/2010000 耗时:6442ms

ps:没用使用jdk7或者某些场景下不能使用新特性的,可以考虑重写

1
fillInStackTrace
方法:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
public class OrderCheckException extends IllegalArgumentException {

	private static final long serialVersionUID = 1L;

	private Map<String, String> errorMap = new HashMap<>();

	private String msg;

	public OrderCheckException() {
		super();
	}

	public OrderCheckException(Throwable cause) {
		super(cause);
	}

	public Map<String, String> getErrorMap() {
		return errorMap;
	}

	/**
	 * 增加参数错误信息
	 * 
	 * @param parameter 校验失败参数
	 * @param msg 参数信息
	 */
	public void addError(String parameter, String msg) {
		this.errorMap.put(parameter, msg);
		this.msg = null;
	}

	@Override
	public String getMessage() {
		if (msg == null) {
			if (errorMap.isEmpty()) {
				msg = "";
			} else {
				StringBuilder sb = new StringBuilder();
				for (Map.Entry entry : errorMap.entrySet()) {
					sb.append(entry.getKey()).append(SplitConstants.SEPARATOR_CHAR_COLON)
					.append(entry.getValue()).append(SplitConstants.SEPARATOR_CHAR_COMMA);
				}
				msg = sb.toString();
			}
		}
		return msg;
	}

	@Override
	public synchronized Throwable fillInStackTrace() {
		return this;
	}
  	}

上面这个

1
OrderCheckException
,它继承了
1
IllegalArgumentException
,但是此异常没有重写
1
java.lang.RuntimeException#RuntimeException(java.lang.String, java.lang.Throwable, boolean, boolean)
,只有通过重写
1
fillInStackTrace
来达到效果.