记一次JAVA FULL GC问题处理【3】
1： 上次的定位原因找到了后，再回过头来看我们的代码问题。实现如下的日志打印格式
其实通过log4j2 的PatternLayout 配置基本都能实现， 但有一个关键点，我们是WEB应用，希望一次请求通过一个比较唯一的会话号来跟踪。方便作ES根踪。
2： 代码大约如下，提供了多个静太的info，warn 代码。
3: 以上代码，确认达到了输出日志号（会话号）的目的，但考虑到日志输出的频繁性，觉得这样做不好。
不好的点主要在于会有多余的内存创建和销毁开销。列举Log4j原始 API 参数，详细问题列举如下：
1）接口上问题 info(String msg) 参数为String ，这要求把其它的参数全部转换成String， 如Int ->转String。 特别对于StringBuilder转String 里面的char[] 是会重新生成的。带来极大的内存开销。
StringBuilder sb=new StringBuilder("").append("123");
Log.info(sb.toString);
2）另外就是关于StringBuilder的拼接，这里将 5个String 对象拼接，生成一个StringBuilder。 但这个StringBuilder 的使用，已经很大程度上让Log4j的内存复用优化打大折扣。
4： 改进策略：
<PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss,SSS}] %-5p %m%n" /> 修改前的配置
<PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss,SSS}] %-5p %l[%y]: %m%n" /> 修改后的配置
@Plugin(name = "LogIdPatternConverter", category = PatternConverter.CATEGORY)
@ConverterKeys({ "y", "logId" })
public class LogIdPatternConverter extends LogEventPatternConverter {
private static final LogIdPatternConverter INSTANCE =
new LogIdPatternConverter();
public static LogIdPatternConverter newInstance(
final String[] options) {
return INSTANCE;
}
private LogIdPatternConverter(){
super("LogId", "logId");
}
@Override
public void format(LogEvent event, StringBuilder toAppendTo) {
toAppendTo.append(LogUtil.getThreadLogId());
// toAppendTo.append(LogUtil.name.get()).append("[").append(LogUtil.getThreadLogId()).append("]:");
}
}
5： 写测试代码
@Test
public void testLogBefore() {
long begin = System.currentTimeMillis();
for(int i=0; i<5000; i++){
Log.info("I will print you");
}
long over = System.currentTimeMillis();
System.out.println("操作testLogBefore类型使用的时间为："+(over-begin)+"毫秒");
}
@Test
public void testLogAfter () {
LogUtil.initThreadLogId();
long begin = System.currentTimeMillis();
for(int i=0; i<5000; i++){
LogUtil.info("I will print you");
}
long over = System.currentTimeMillis();
System.out.println("操作testLogAfter类型使用的时间为："+(over-begin)+"毫秒");
}
操作testLogBefore类型使用的时间为：615毫秒
操作testLogAfter类型使用的时间为：339毫秒
这里有所提升，但对于%l 操作的性能耗损很大。
5： 原因分析： 可这个代码位置的代码，这个代码为了获取堆栈信息 是通过new Exception 方式获得， 有clone等操作。导致信息量过大。从而性能比较差。
http://logging.apache.org/log4j/2.x/performance.html#asyncLoggingWithLocation
大概也就是说日志格式使用这些参数的使用会导致性能的急剧下降
C or $class, %F or %file, %l or %location, %L or %line, %M or %method
大概下降30-100倍左右，这才找到真正的原因，原来同步和异步的性能影响是一部分，本身日志格式的配置也是存在问题的。
较为影响性能的日志输出参数
%C - 调用者的类名(速度慢,不推荐使用);
%F - 调用者的文件名(速度极慢,不推荐使用)
%l - 调用者的函数名、文件名、行号(速度极其极其慢,不推荐使用)
%L - 调用者的行号(速度极慢,不推荐使用)
%M - 调用者的函数名(速度极慢,不推荐使用)
6: 进一步修改
<PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss,SSS}] %-5p [%y] %m%n" />
public class LogUtil {
private static Logger log = ((LoggerContext) LogManager.getContext(false)).getLogger(com.chinamobile.iot.component.log.Log.class.getName());
private static Map<String, Level> logLevels = new HashMap(8);
static ThreadLocal<String> threadLocal = new ThreadLocal();
static ThreadLocal<String> name = new ThreadLocal();
private static Random random;
private LogUtil() {
}
public static void debug(String msg) {
if (log.isDebugEnabled()) {
log.debug(msg);
}
}
public static void debug(String msg, String logId) {
if (log.isDebugEnabled()) {
log.debug(msg);
}
}
public static void info(String msg) {
if (log.isInfoEnabled()) {
name.set(getLogTrace());
log.info(msg);
}
}
。。。。。。。
}
@Test
public void testLogBefore() {
long begin = System.currentTimeMillis();
for(int i=0; i<5000; i++){
Log.info("I will print you");
}
long over = System.currentTimeMillis();
System.out.println("操作testLogBefore类型使用的时间为："+(over-begin)+"毫秒");
}
@Test
public void testLogAfter () {
LogUtil.initThreadLogId();
long begin = System.currentTimeMillis();
for(int i=0; i<5000; i++){
LogUtil.info("I will print you");
}
long over = System.currentTimeMillis();
System.out.println("操作testLogAfter类型使用的时间为："+(over-begin)+"毫秒");
}
操作testLogBefore类型使用的时间为：627毫秒
操作testLogAfter类型使用的时间为：156毫秒
对于logId, 方法名，内存复用方案，在当前情况下测试的比较好的结果。
