我们使用log4j将不同的东西写入不同的日志文件.我继承了这段代码,所以无论好坏,一般结构都会暂时停留.
记录器将创建两个日志文件:main.log和stats.log.通过单独的调用将两个记录器记录到某个统计信息(您将在下面看到),并将大量其他内容记录到主日志中.
因此,通过我们的代码,您将看到诸如Log.logMain(someMessageToLog);之类的内容.在我们的代码中的一个地方(由多个线程执行)有以下内容:
- String statsMessage = createStatsMessage();
- Log.logMain(statsMessage);
- Log.logStats(statsMessage);
主记录器的名称为main,统计记录器的名称为stats.问题是,有时在负载很重的情况下,我们会在main.log中看到其中包含字符串统计信息INFO的行. main.log中的所有内容都应该只包含主要的INFO,因为这是唯一记录到该文件的记录器,而且我们在某些行中看到混合输出.这似乎是线程安全问题,但log4j文档说log4j是线程安全的.这是我的意思的一个例子:
- 2012-03-21 16:01:34,7742012-03-21 16:01:34,774| | stats main INFO [INFO http-8080-18]: [message redacted].
- 2012-03-21 16:01:36,380| main 2012-03-21 16:01:36,380| INFO [stats INFO http-8080-15]: [message redacted].
- 2012-03-21 16:01:37,465| main INFO 2012-03-21 16:01:37,465 [| stats http-8080-1]: [message redacted].
这是Log类(被剥离以仅显示有问题的记录器 – 其中实际上有一堆其他记录器,所有记录器都与这些类似):
- import org.apache.log4j.*;
- import java.io.IOException;
- final public class Log
- {
- private static final String LOG_IDENTIFIER_MAINLOG = "main";
- private static final String LOG_IDENTIFIER_STATSLOG = "stats";
- private static final String MAIN_FILENAME = "/var/log/app_main.log";
- private static final String STATS_FILENAME = "/var/log/app_stats.log";
- private static final int BACKUP_INDEX = 40;
- private static final String BACKUP_SIZE = "10MB";
- private static final PatternLayout COMMON_LAYOUT =
- new PatternLayout("%d| %c %-6p [%t]: %m.%n");
- private static Logger mainLogger;
- private static Logger statsLogger;
- public static void init() {
- init(MAIN_FILENAME,STATS_FILENAME);
- }
- public static void init(String mainLogFilename,String statsLogFilename) {
- mainLogger = initializeMainLogger(mainLogFilename);
- statsLogger = initializeStatsLogger(statsLogFilename);
- }
- public static void logMain(String message) {
- if (mainLogger != null) {
- mainLogger.info(message);
- }
- }
- public static void logStats(String message) {
- if (statsLogger != null) {
- statsLogger.info(message);
- }
- }
- private static Logger getLogger(String loggerIdentifier) {
- Logger logger = Logger.getLogger(loggerIdentifier);
- logger.setAdditivity(false);
- return logger;
- }
- private static boolean addFileAppender(Logger logger,String logFilename,int maxBackupIndex,String maxSize) {
- try {
- RollingFileAppender appender =
- new RollingFileAppender(COMMON_LAYOUT,logFilename);
- appender.setMaxBackupIndex(maxBackupIndex);
- appender.setMaxFileSize(maxSize);
- logger.addAppender(appender);
- }
- catch (IOException ex) {
- ex.printStackTrace();
- return false;
- }
- return true;
- }
- private static Logger initializeMainLogger(String filename) {
- Logger logger = getLogger(LOG_IDENTIFIER_MAINLOG);
- addFileAppender(logger,filename,BACKUP_INDEX,BACKUP_SIZE);
- logger.setLevel(Level.INFO);
- return logger;
- }
- private static Logger initializeStatsLogger(String filename) {
- Logger logger = getLogger(LOG_IDENTIFIER_STATSLOG);
- addFileAppender(logger,BACKUP_SIZE);
- logger.setLevel(Level.INFO);
- return logger;
- }
- }
更新:
这是一个小程序(至少对我而言)将使用上面的Log类重现问题:
- final public class Stress
- {
- public static void main(String[] args) throws Exception {
- if (args.length != 2) {
- Log.init();
- }
- else {
- Log.init(args[0],args[1]);
- }
- for (;;) {
- // I know Executors are preferred,but this
- // is a quick & dirty test program
- Thread t = new Thread(new TestLogging());
- t.start();
- }
- }
- private static final class TestLogging implements Runnable
- {
- private static int counter = 0;
- @Override
- public void run() {
- String msg = new StringBuilder("Count is: ")
- .append(counter++).toString();
- Log.logMain(msg);
- Log.logStats(msg);
- try {
- Thread.sleep(1);
- }
- catch (InterruptedException e) {
- Log.logMain(e.getMessage());
- }
- }
- }
- }
以及日志中的一些示例输出:
- $grep stats main.log
- 2012-03-23 15:30:35,919| stats 2012-03-23 15:30:35,919| main INFO INFO [ [Thread-313037]: Thread-313036]: Count is: 312987.
- 2012-03-23 15:30:35,929| stats INFO [Thread-313100]: Count is: 313050.
- 2012-03-23 15:30:35,937| stats INFO [Thread-313168]: Count is: 313112.
- 2012-03-23 15:30:35,945| stats INFO [Thread-313240]: Count is: 313190.
- 2012-03-23 15:30:35,946| stats INFO [Thread-313251]: Count is: 313201.
- 2012-03-23 15:30:35,949| stats INFO [2012-03-23 15:30:35,949| main INFO Thread-313281]: Count is: 313231.
- 2012-03-23 15:30:35,954| stats INFO [Thread-313331]: Count is: 313281.
- 2012-03-23 15:30:35,956| 2012-03-23 15:30:35,956stats | main INFOINFO [ [Thread-313356]: Count is: 313306.
- 2012-03-23 15:30:35,9562012-03-23 15:30:35,956| main | INFO stats [INFOThread-313359]: Count is: 313309.
- 2012-03-23 15:30:35,962| stats INFO 2012-03-23 15:30:35,962| main INFO [Thread-313388]: [Count is: 313338.
和
- $grep main stats.log
- 2012-03-23 15:30:35,913| 2012-03-23 15:30:35,913| main INFO [Thread-312998]: Count is: 312948.
- 2012-03-23 15:30:35,915| main INFO [Thread-313014]: Count is: 312964.
- 2012-03-23 15:30:35,931| main INFO [Thread-313116]: Count is: 313066.
- 2012-03-23 15:30:35,947| main INFO [2012-03-23 15:30:35,947Thread-313264]: | Count is: 313214.
- 2012-03-23 15:30:35,962| main INFO [Thread-313388]: [Count is: 313338.
对于它的价值,在一个145516行的main.log文件中,“stats”出现了2452次.所以它并不罕见,但它不是一直都在发生(当然这个测试非常极端).
解决方法
你在两个appender之间共享PatternLayout,根据上面的API链接:
已知此代码具有同步和org.apache.log4j.EnhancedPatternLayout中不存在的其他问题.应优先使用EnhancedPatternLayout而不是PatternLayout. EnhancedPatternLayout分布在log4j extras伴侣中.
因此,为每个appender创建一个新的PatternLayout