Java学习-046-日志抓取合并后排序问题解决方案之 --- log4j 二次定制，实现日志输出添加延时10ms
2016-04-10 23:57
489 查看
自3月25至今，已经好久没有写学习日志了，今天在写日志抓取合并的小方法，发现抓取后的日志并米有依据系统执行的日志顺序排序。日志抓取排列逻辑如下：
通过日志标识，从各个日志文件（例如 use.log，error.log 等）中获取所需日志列表
合并日志列表
升序排序
输出日志报告
结果最后获取日志信息后，发现实际产出结果与预期结果不相符，如下所示：
通过日志可以发现，排序时起决定作用的日志时间影响较大，系统运算速度越快，产生相同时间开头的日志就越多，因而影响了最终的排序结果。
如何才能解决呢？我想出了如下的解决方案：
将所有的日志信息统一输出到一个文件中，只需要依次获取日志输出即可
创建自己的日志模块取代 log4j
日志排序打标，即：在每个日志字符串前添加一个唯一 ID，通过此 ID 进行排序
二次编译 log4j 的源码在 debug、info、warn、error、fatal 方法中添加延时
再三思索下，决定采用第四种解决方案。原因如下：
所有日志信息输出到同一文件，日志文件较大，且不符合日志分类习惯
耗时较长（主要是有很多开源的日志构件，自己再开发，觉得浪费时间，哈哈哈）
日志打标需要在每个日志输出的地方添加标识，因方法或语句块会被多次执行，此方案直接KO
省时省力，只是需要牺牲点时间（个人觉得此方案比其他方案会更优）
经过查询 log4j 的api 发现，上述日志方法在 org\apache\log4j\Category.java 文件中，具体延时时间依据实际需要自行酌情设置即可，添加或修改如下所示代码（info、warn、error、fatal 方法参考修改即可）：
下载 log4j-1.2.17.jar ，对其进行反编译（不会的请参阅我之前写的文章：Java学习-039-源码 jar 包的二次开发扩展实例（源码修改）），然后打包上传到私服，在 pom 文件中添加引用即可。
重新执行测试用例，得到的日志数据如下所示（此时获取的日志结果为期望结果，同时从日志中也可看出我们的日志延时输出已经生效）：
至此， Java学习-046-测试日志抓取合并、排序问题解决方案之 --- [b]log4j 二次定制，实现日志输出添加延时10ms [/b]顺利完结，希望此文能够给初学 Java 的您一份参考。
最后，非常感谢亲的驻足，希望此文能对亲有所帮助。热烈欢迎亲一起探讨，共同进步。非常感谢！ ^_^
通过日志标识，从各个日志文件（例如 use.log，error.log 等）中获取所需日志列表
合并日志列表
升序排序
输出日志报告
结果最后获取日志信息后，发现实际产出结果与预期结果不相符，如下所示：
2016-04-10 22:54:23,042 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:151] - [1460300059732] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】概要报告 ... 2016-04-10 22:54:23,042 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:167] - [1460300059732] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】概要报告 ... 2016-04-10 22:54:23,042 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:187] - [1460300059732] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】断言报告 ... 2016-04-10 22:54:23,042 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:211] - [1460300059732] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】断言报告 ... 2016-04-10 22:54:23,042 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:286] - [1460300059732] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求响应报告 ... 2016-04-10 22:54:23,042 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:358] - [1460300059732] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求报告 ... 2016-04-10 22:54:23,042 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:392] - [1460300059732] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求报告 ... 2016-04-10 22:54:23,042 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:409] - [1460300059732] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求参数报告 ... 2016-04-10 22:54:23,042 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:426] - [1460300059732] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求参数报告 ... 2016-04-10 22:54:23,042 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:441] - [1460300059732] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求主体报告 ... 2016-04-10 22:54:23,042 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:446] - [1460300059732] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求主体报告 ... 2016-04-10 22:54:24,102 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:261] - [1460300059732] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】日志报告 ... 2016-04-10 22:54:24,102 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:338] - [1460300059732] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求响应报告 ... 2016-04-10 22:54:24,102 - INFO - [main] [cn.ffp.autotest.api.util.IpUtils:108] - [1460300059732] 成功获取主机IP地址... 2016-04-10 22:54:24,102 - INFO - [main] [cn.ffp.autotest.api.util.IpUtils:108] - [1460300059732] 成功获取主机IP地址... 2016-04-10 22:54:24,102 - INFO - [main] [cn.ffp.autotest.api.util.IpUtils:192] - [1460300059732] 开始通过主机域名【mb.ffp.com】获取对应的地址对象 ... 2016-04-10 22:54:24,102 - INFO - [main] [cn.ffp.autotest.api.util.IpUtils:197] - [1460300059732] 成功通过主机域名【mb.ffp.com】获取对应的地址对象 ... 2016-04-10 22:54:24,102 - INFO - [main] [cn.ffp.autotest.api.util.IpUtils:98] - [1460300059732] 开始获取主机IP地址... 2016-04-10 22:54:24,102 - INFO - [main] [cn.ffp.autotest.api.util.IpUtils:98] - [1460300059732] 开始获取主机IP地址...
通过日志可以发现，排序时起决定作用的日志时间影响较大，系统运算速度越快，产生相同时间开头的日志就越多，因而影响了最终的排序结果。
如何才能解决呢？我想出了如下的解决方案：
将所有的日志信息统一输出到一个文件中，只需要依次获取日志输出即可
创建自己的日志模块取代 log4j
日志排序打标，即：在每个日志字符串前添加一个唯一 ID，通过此 ID 进行排序
二次编译 log4j 的源码在 debug、info、warn、error、fatal 方法中添加延时
再三思索下，决定采用第四种解决方案。原因如下：
所有日志信息输出到同一文件，日志文件较大，且不符合日志分类习惯
耗时较长（主要是有很多开源的日志构件，自己再开发，觉得浪费时间，哈哈哈）
日志打标需要在每个日志输出的地方添加标识，因方法或语句块会被多次执行，此方案直接KO
省时省力，只是需要牺牲点时间（个人觉得此方案比其他方案会更优）
经过查询 log4j 的api 发现，上述日志方法在 org\apache\log4j\Category.java 文件中，具体延时时间依据实际需要自行酌情设置即可，添加或修改如下所示代码（info、warn、error、fatal 方法参考修改即可）：
package org.apache.log4j;
import org.apache.log4j.spi.AppenderAttachable;
import org.apache.log4j.spi.LoggingEvent;
import org.apache.log4j.spi.LoggerRepository;
import org.apache.log4j.spi.HierarchyEventListener;
import org.apache.log4j.helpers.NullEnumeration;
import org.apache.log4j.helpers.AppenderAttachableImpl;
import java.util.Enumeration;
import java.util.MissingResourceException;
import java.util.ResourceBundle;
import java.util.Vector;
public class Category implements AppenderAttachable {
/**
* Aaron.ffp 2016-04-10 add log delay time 10ms
* reference：debug、info、warn、error、fatal
*/
protected long delay = 10;
public void debug(Object message) {
try {
Thread.sleep(delay);
} catch (InterruptedException e) {
}
if (repository.isDisabled(Level.DEBUG_INT))
return;
if (Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel())) {
forcedLog(FQCN, Level.DEBUG, message, null);
}
}
public void debug(Object message, Throwable t) {
try {
Thread.sleep(delay);
} catch (InterruptedException e) {
}
if (repository.isDisabled(Level.DEBUG_INT))
return;
if (Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel()))
forcedLog(FQCN, Level.DEBUG, message, t);
}
}下载 log4j-1.2.17.jar ，对其进行反编译（不会的请参阅我之前写的文章：Java学习-039-源码 jar 包的二次开发扩展实例（源码修改）），然后打包上传到私服，在 pom 文件中添加引用即可。
重新执行测试用例，得到的日志数据如下所示（此时获取的日志结果为期望结果，同时从日志中也可看出我们的日志延时输出已经生效）：
2016-04-10 23:08:01,005 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:151] - [1460300877526] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】概要报告 ... 2016-04-10 23:08:01,015 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:167] - [1460300877526] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】概要报告 ... 2016-04-10 23:08:01,025 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:187] - [1460300877526] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】断言报告 ... 2016-04-10 23:08:01,035 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:211] - [1460300877526] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】断言报告 ... 2016-04-10 23:08:01,045 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:358] - [1460300877526] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求报告 ... 2016-04-10 23:08:01,055 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:409] - [1460300877526] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求参数报告 ... 2016-04-10 23:08:01,065 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:426] - [1460300877526] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求参数报告 ... 2016-04-10 23:08:01,075 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:441] - [1460300877526] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求主体报告 ... 2016-04-10 23:08:01,085 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:446] - [1460300877526] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求主体报告 ... 2016-04-10 23:08:01,095 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:392] - [1460300877526] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求报告 ... 2016-04-10 23:08:01,105 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:286] - [1460300877526] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求响应报告 ... 2016-04-10 23:08:01,205 - INFO - [main] [cn.ffp.autotest.api.util.IpUtils:98] - [1460300877526] 开始获取主机IP地址... 2016-04-10 23:08:01,215 - INFO - [main] [cn.ffp.autotest.api.util.IpUtils:108] - [1460300877526] 成功获取主机IP地址... 2016-04-10 23:08:01,225 - INFO - [main] [cn.ffp.autotest.api.util.IpUtils:192] - [1460300877526] 开始通过主机域名【mb.ffp.com】获取对应的地址对象 ... 2016-04-10 23:08:01,235 - INFO - [main] [cn.ffp.autotest.api.util.IpUtils:197] - [1460300877526] 成功通过主机域名【mb.ffp.com】获取对应的地址对象 ... 2016-04-10 23:08:01,245 - INFO - [main] [cn.ffp.autotest.api.util.IpUtils:98] - [1460300877526] 开始获取主机IP地址... 2016-04-10 23:08:01,255 - INFO - [main] [cn.ffp.autotest.api.util.IpUtils:108] - [1460300877526] 成功获取主机IP地址... 2016-04-10 23:08:01,265 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:338] - [1460300877526] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】请求响应报告 ... 2016-04-10 23:08:01,275 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:261] - [1460300877526] 开始生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】日志报告 ... 2016-04-10 23:08:01,305 - INFO - [main] [cn.ffp.autotest.api.report.ReportHelper:266] - [1460300877526] 成功生成【Test_001_001 | 首页接口-导航栏配置 | 范丰平 | 2016-03-29 00:03:34 | 是】日志报告 ...
至此， Java学习-046-测试日志抓取合并、排序问题解决方案之 --- [b]log4j 二次定制，实现日志输出添加延时10ms [/b]顺利完结，希望此文能够给初学 Java 的您一份参考。
最后，非常感谢亲的驻足，希望此文能对亲有所帮助。热烈欢迎亲一起探讨，共同进步。非常感谢！ ^_^
内容来自用户分享和网络整理，不保证内容的准确性，如有侵权内容，可联系管理员处理 
相关文章推荐
- struts2校验框架的一个坑
- struts2的jar包下载流程
- Mybatis 系列（1）—— JSP + Spring + Mybatis+Mysql 框架搭建
- eclipse如何终止对Android项目的调试
- java程序实现一个有趣的买啤酒问题
- 20145129 《Java程序设计》第6周学习总结
- Java第一次实验 20145104张家明
- 20145201 《Java程序设计》第六周学习总结
- 20145201《Java程序设计》第1次实验报告
- 20145310第一周JAVA实验报告
- java线程池newFixedThreadPool详解
- 20145314郑凯杰 《Java程序设计》实验一 Java开发环境的熟悉(Windows + Eclipse)实验报告
- 为eclipse项目添加 working set
- 20145216 史婧瑶《Java程序设计》第6周学习总结
- 20145216史婧瑶《Java程序设计》第一次实验报告
- 【java】final的要点和static final的区别
- java对象的序列化与反序列化（测试说明）
- Struts2项目搭建—实现参数传递
- 20145211 《Java程序设计》第6周学习总结——三笑徒然当一痴
- jdk 配置以及配置出错could not open `C:\Program Files\Java\jre7\lib\amd64\jvm.cfg' 解决方案