Log4j最佳实践

本文是结合项目中使用Log4j总结的最佳实践，非转载。网上可以找到的是这一篇《Log4j最佳实践》。本来Log4j使用是非常简单的，无需多介绍其用法，这只是在小型项目中；但在大型的项目中使用log4j不太一样。大型项目非常依赖日志，因为解决线上问题必须依靠log，依靠大量的日志！线上出现问题往往不能重现，而且无法调试，log是必须中的必须，解决线上问题全靠它。本文内容：

• 大型项目中Log4j的使用注意点
• Log4j为性能考虑的注意点
• a). 避免输出'%C', '%F', '%L' '%M' 等位置信息
• b). 使用异步（异步写文件，异步写数据库）
• 把ERROR信息输出到单独的文件
• 在基类写log4j日志要注意的问题
• Log4j基础知识
• Log4j的AsyncAppender存在的严重问题

大型项目中Log4j的使用注意点

在大型项目中使用Log4j要注意下面几点：

• 不能因为写log使得系统性能变慢（最好使用异步）
• log能易于定位问题，log要能体现何时（精确到毫秒级）、在哪（包、机器、类、函数、行、文件等）、发生了什么问题、以及严重性
• log要易于自动、手工、半自动分析（如记录文件太大则不能打开分析，写数据库等）
• 能根据模块/包来动态单独配置log级别（FATAL – ERROR – WARNING – INFO – DEBUG - TRACE） 和单独配置输出文件等
• 可以用grep分析出独立的行，尽量不要分行
• 有时调试线上问题还需要非常丰富的信息，例如：进入模块和函数的入口参数信息、完成某项操作耗费的时间、SessionID、机器IP地址和端口号、版本号、try{}catch{}里面的StackTrace信息。
• 大型系统的日志文件应该定期用gzip压缩并移动到一个专门的档案日志服务器。应该每天晚上，或者每小时这样做一次。
• 不要随便从网上复制一个Log4j的配置文件，你必须深入理解里面的每一个配置项代表的含义！
• 如果你拼装的动作比较耗资源，请用if ( log.isDebugEnabled() )
• 千万不要try{}catch{}了异常却没有记录日志
• 不要仅记录到数据库，记录文件更加可靠，因为记录到数据库可能发生网络和数据库异常，没有记录本地磁盘可靠。

例如下面这个启动日志包含了版本号、耗费时间、userID等等丰富的信息：

 

Log4j为性能考虑的注意点

为系统性能考虑，使用Log4j注意下列几点：

• 避免输出'%C', '%F', '%L' '%M' 等位置信息
• 尽量使用异步
• 为每个模块设置单独的输出文件
• 每次调用前检查if(logger.isDebugEnabled()){ logger.debug(……) }

a). 避免输出'%C', '%F', '%L' '%M' 等位置信息

当配置文件中的配置项包含Location信息时候会非常昂贵，因此，需要避免'C', 'F', 'L' 'M' 等位置信息的记录（参数配置项详细说明）。

• %C - 输出类名
• %F - 输出文件名
• %L - 输出行号
• %M - 输出函数名

（注意：当配置为异步输出的时候，以上位置信息可能会显示为问号？，因为是在另外一个线程记录的调用信息。此时，我们可以使用下面的方法来获取类名和函数名：

1 2	StackTraceElement se = Thread.currentThread().getStackTrace()[ 2 ]; String msg = se.getClassName() + "-["  + se.getMethodName() + "] "  + errorMessage;

）

b). 使用异步（异步写文件，异步写数据库）

Log4j异步写可以使用默认的appender：org.apache.log4j.AsyncAppender，配置文件log4j.xml样例：

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 54

<?xml version= "1.0"  encoding= "UTF-8"  ?>  <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd" >      <log4j:configuration xmlns:log4j= 'http://jakarta.apache.org/log4j/'  debug= "false" >          <appender name= "DAILY_FILE"  class = "org.apache.log4j.DailyRollingFileAppender" >       <layout class = "org.apache.log4j.PatternLayout" >         <param name= "ConversionPattern"  value= "%d{yyyy-MM-dd HH:mm:ss,SSS} %5p %c %x - %m%n" />       </layout>       <param name= "File"  value= "log/log4j.log" />       <param name= "DatePattern"  value= "'.'yyyy-MM-dd" />    </appender>         <appender name= "ASYNC_FILE"  class = "org.apache.log4j.AsyncAppender" >       <param name= "BufferSize"  value= "10000" />       <param name= "Blocking"  value= "false" />       <appender-ref ref= "DAILY_FILE" />     </appender>        <appender name= "DB_OUT"  class = "org.apache.log4j.jdbc.JDBCAppender" >        <param name= "URL"  value= "jdbc:postgresql://192.168.1.34:5432/myDB"  />        <param name= "Driver"  value= "org.postgresql.Driver" />        <param name= "User"  value= "aaa" />        <param name= "Password"  value= "bbb" />        <param name= "Sql"  value= "INSERT INTO tracelog (ModuleName ,LoginID,UserName,Class, Method,createTime,LogLevel,MSG) values ('%c', '','','','','%d{yyyy-MM-dd HH:mm:ss,SSS}','%p','%m')" />       </appender>        <appender name= "ASYNC_DB"  class = "org.apache.log4j.AsyncAppender" >       <param name= "BufferSize"  value= "10000" />       <param name= "Blocking"  value= "false" />       <appender-ref ref= "DB_OUT" />     </appender>           <root>       <level value= "info" />       <appender-ref ref= "ASYNC_DB"  />       <appender-ref ref= "ASYNC_FILE"  />    </root>         <logger name= "PACKAGE_1"  additivity= "false" >       <level value= "info" />        <appender-ref ref= "ASYNC_DB"  />       <appender-ref ref= "ASYNC_FILE"  />    </logger>       <logger name= "PACKAGE_2"  additivity= "false" >       <level value= "info" />        <appender-ref ref= "ASYNC_DB"  />       <appender-ref ref= "ASYNC_FILE"  />    </logger>          </log4j:configuration>

上面的配置文件包含异步写文件和异步写入postgreSQL数据库的配置，默认是root，也有各个Package的配置。用的时候可以写一个logUtil的类来初始化这个log4j.xml:

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 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118

package  com.ibm;   import  org.apache.log4j.Logger; import  org.apache.log4j.xml.DOMConfigurator;   public  class  LogUtil implements  ILogUtil {        public  static  LogUtil getInstance() {          if  (instance == null )              instance = new  LogUtil();          return  instance;      }        @Override      public  void  init()  {          //PropertyConfigurator.configure("conf/log4j.properties");          DOMConfigurator.configure( "conf/log4j.xml" );      }        @Override      public  void  close() {      }        @Override      public  void  logError(String errorMessage) {          logger.error(errorMessage.replace( "'" , "''" ));      }        @Override      public  void  logWarn(String warnMessage) {          logger.warn(warnMessage.replace( "'" , "''" ));      }        @Override      public  void  logInfo(String infoMessage) {          logger.info(infoMessage.replace( "'" , "''" ));      }        @Override      public  void  logDebug(String debugMessage) {          logger.debug(debugMessage.replace( "'" , "''" ));      }        @Override      public  void  logFatal(String fatalMessage) {          logger.fatal(fatalMessage.replace( "'" , "''" ));      }        private  LogUtil() {      }        private  static  Logger getPackageLogger(String packageName){          if (packageName.equals(PackageName.PACKAGE_1.toString()))              return  Logger.getLogger(PackageName.PACKAGE_1.toString());          else  if (packageName.equals(PackageName.PACKAGE_2.toString()))              return  Logger.getLogger(PackageName.PACKAGE_2.toString());          else              return  Logger.getRootLogger();      }        @Override      public  void  logError(String packageName, String errorMessage) {          getPackageLogger(packageName).error(errorMessage.replace( "'" , "''" ));      }        @Override      public  void  logError(String packageName, String errorMessage,              Throwable exception) {          getPackageLogger(packageName).error(errorMessage.replace( "'" , "''" ), exception);      }        @Override      public  void  logWarn(String packageName, String warnMessage) {          getPackageLogger(packageName).warn(warnMessage.replace( "'" , "''" ));      }        @Override      public  void  logWarn(String packageName, String warnMessage,              Throwable exception) {          getPackageLogger(packageName).warn(warnMessage.replace( "'" , "''" ), exception);      }        @Override      public  void  logInfo(String packageName, String infoMessage) {          getPackageLogger(packageName).info(infoMessage.replace( "'" , "''" ));      }        @Override      public  void  logInfo(String packageName, String infoMessage,              Throwable exception) {          getPackageLogger(packageName).info(infoMessage.replace( "'" , "''" ), exception);      }        @Override      public  void  logDebug(String packageName, String debugMessage) {          getPackageLogger(packageName).debug(debugMessage.replace( "'" , "''" ));      }        @Override      public  void  logDebug(String packageName, String debugMessage,              Throwable exception) {          getPackageLogger(packageName).debug(debugMessage.replace( "'" , "''" ), exception);      }        @Override      public  void  logFatal(String packageName, String fatalMessage) {          getPackageLogger(packageName).fatal(fatalMessage.replace( "'" , "''" ));      }        @Override      public  void  logFatal(String packageName, String fatalMessage,              Throwable exception) {          getPackageLogger(packageName).fatal(fatalMessage.replace( "'" , "''" ), exception);      }        private  static  Logger logger = Logger.getRootLogger();      private  static  LogUtil instance; }

具体各个Package可以调用：

1	LogUtil.getInstance().logError( "PACKAGE_1" , "error message...." , e);

（注意：写数据库的时候配置文件log4j.xml里面有一菊SQL，这个SQL在写的message包含单引号或双引号的时候会爆异常，所以需要把单引号或双引号转义为两个单引号；我们自己的log可以控制，如果是例如Tomcat/jBoss写的log的message包含单引号或双引号的时候会写数据库异常，具体做法可以自定义JDBCAppender，参考这一片文章。自定义字段可以使用MDC和%X，参考这一片文章。）

上面的配置文件已经根据各个Package配置单独的log输出，可以配置为写某个文件，或单独写数据库，或是组合，都可以灵活根据自己的需要配置。

(AsyncAppender中BufferSize/默认128的含义：the number of messages allowed in the event buffer before the calling thread is blocked (if blocking is true) or until messages are summarized and discarded.)

JDBCAppender存在没有数据库连接池的问题，可以扩展一下JDBCAppender，引入第三方连接池例如C3P0:

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 54 55 56 57 58 59 60 61 62 63 64 65 66 67

package  com.ibm.log4j.jdbcplus;   import  org.apache.log4j.jdbc.JDBCAppender; import  org.apache.log4j.spi.LoggingEvent; import  java.sql.Connection;  import  java.sql.SQLException;  import  org.apache.log4j.spi.ErrorCode;  import  com.codestudio.sql.PoolMan;    public  class  DBAppender extends  JDBCAppender {            /**通过 PoolMan 获取数据库连接对象的 jndiName 属性*/       protected  String jndiName;       /**数据库连接对象*/       protected  Connection connection = null ;            public  DBAppender() {           super ();       }             @Override       protected  void  closeConnection(Connection con) {           try  {               if  (connection != null  && !connection.isClosed())                   connection.close();           } catch  (SQLException e) {               errorHandler.error( "Error closing connection" , e, ErrorCode.GENERIC_FAILURE);           }       }             @Override       protected  Connection getConnection() throws  SQLException {                     try  {               //通过 PoolMan 获取数据库连接对象(http://nchc.dl.sourceforge.net/project/poolman/PoolMan/poolman-2.1-b1/poolman-2.1-b1.zip)               Class.forName( "com.codestudio.sql.PoolMan" );               connection= PoolMan.connect( "jdbc:poolman://"  + getJndiName());           } catch  (Exception e) {               System.out.println(e.getMessage());           }           return  connection;       }       /**       * @return the jndiName       */       public  String getJndiName() {           return  jndiName;       }       /**       * @param jndiName the jndiName to set       */       public  void  setJndiName(String jndiName) {           this .jndiName = jndiName;       }         @Override      public  void  append(LoggingEvent event) {          if  (event.getMessage() != null )              event.getMessage().toString().replace( "'" , "''" ); //      if (event.getThrowableInformation() != null) //          event.getThrowableInformation().toString().replace("'", "''");          buffer.add(event);                    if  (buffer.size() >= bufferSize)              flushBuffer();      } }

把ERROR信息输出到单独的文件

如果你的日志级别是INFO，想把ERROR log输出到单独的文件，可以这样配置：

1 2 3 4 5 6 7 8 9 10 11 12 13

<appender name= "ERROR_FILE" >     <param name= "Threshold"  value= "ERROR" /> </appender>   <appender name= "GENERAL" >     <param name= "Threshold"  value= "INFO" /> </appender>   <logger name= "com.acme" >    <level value= "INFO" />    <appender-ref ref= "ERROR_FILE" />    <appender-ref ref= "GENERAL" /> </logger>

在基类写log4j日志要注意的问题

最后要注意的是，如果你把写日志这部分封装到一个独立的jar包模块里面（在基类或者静态类里面写日志），就会导致输出的类名、函数名都是基类的类名和函数名，这将是重大的错误。因为下面的这行：

1	private  static  Logger log = Logger.getLogger( MyClass. class  );

如果你获得的是基类的logger那就永远是基类的logger。这一点需要注意.

Log4j基础知识

如果你对Log4j基础不熟悉，建议你学习一下什么是log4j里面的logger, root logger, appender, configuration、Additivity和layout.

SocketAppender / JMSAppender

除了AsyncAppender,你还可以使用SocketAppender, JMSAppender...和其它各种log4j的appender。当然，除了log4j，你也可以转到slf4j, logBack.

Log4j的AsyncAppender存在的严重问题

Log4j的异步appender也就是AsyncAppender存在性能问题（现在Log4j 2.0 RC提供了一种新的异步写log的机制(基于disruptor)来试图解决问题），问题是什么呢？异步写log有一个buffer的设置，也就是当队列中多少个日志的时候就flush到文件或数据库，当配置为blocking=true的时候，当你的应用写日志很快，log4j的缓冲队列将很快充满，当它批量flush到磁盘文件的时候，你的磁盘写入速度很慢，会发生什么情况？是的，队列阻塞，写不进去了，整个log4j阻塞了，始终等待队列写入磁盘/DB，整个异步线程死了变成同步的了？而当配置为blocking=false的时候，不会阻塞但会扔出异常并丢弃消息。你是希望log4j死掉，还是希望后续消息被丢弃？都是问题。

当然，一个办法是把缓冲bufferSize设大一点。最好的解决办法：1、自己实现消息队列和自定义的AsyncAppender； 2. 等log4j 2.0 成熟发布。

（注：log4j 2 由于采用了LMAX Disruptor，性能超过原来AsyncAppender几个数量级，支持每秒并发写入1800万条日志）