java 怎么合理的打印日志

青旅半醒 2021-10-19 09:58 313阅读 0赞

# 1.日志的主要作用 #

1）日志是系统运行的“照妖镜”，通过它能够实时反映系统的运行状态；

如上图所示，系统A中producer不断产生数据放入到data queue中，sender不断从data queue中取数据发送给下游系统B的receiver，那么对于系统A来说，data queue中的待发送数据量便是一个非常关键的指标，它能够从侧面真实反应当前系统的运行状况，如果data queue中的element个数超过容量的90%了，那么标志着此时系统可能运行不正常了，会有队列堵塞的风险；如果data queue中的element个数不到容量的10%，那么标志着此时系统运行比较正常，出现队列堵塞的风险较低。

如果这个指标没有输出到日志中，开发和运维人员是无法确切知道当前系统A的运行状态的(当然也有其他的方式来获取这个指标，比如通过http接口暴露出来也是一种方式之一)。

2）良好的日志便于后期运维和开发人员迅速定位线上问题，加快止损速度，减少系统故障带来的损失；

3）日志还有另外一个作用便是能够无缝与监控系统结合，通过监控系统进行日志采集，拿到系统运行的相关性能指标，有利于分析系统的性能瓶颈、提前规避风险；

举例说明：

假如有一个商城系统，在初期，数据库通过2台服务器提供服务(1台master，1台slave)，此时大部分接口能在秒级内响应用户请求。随着时间的推移，商城系统的用户量逐渐增多，并发查询和写入量都出现了一定的增长，数据库中的数据量也慢慢增多，导致部分sql语句查询越来越慢，突然有一天，数据库的slave机器由于过多的慢查询导致被拖垮，彻底宕机了，导致商城服务不可用。

如果商城系统在日志中记录了每个http请求的耗时情况，通过监控系统配置日志采集，同时配置相应的报警，那么便能提前发现由于业务增长带来的系统性能瓶颈，提前进行系统优化(如机器扩容、sql语句优化、分库分表等)，规避风险。

4）便于统计与业务相关的指标数据，进行相关业务分析和功能优化。

举例说明：

比如一个搜索系统，想统计过去一周不同地域(如南北地域)的搜索使用占比，如果日志中本身打印了每个搜索query请求的ip，则很容易统计，否则需要重新上线加日志才能统计。

因此，大家在日常编写代码过程中要注重日志书写的规范性，让它发挥出它应有的价值，在辅助保障我们服务稳定运行的同时，能够有效提升后期系统维护效率。

# 2.如何规范地打印程序日志？ #

接下来，我们从以下几个方面来谈谈如何规范地打印日志。

1.  日志文件命名
2.  日志滚动
3.  日志级别
4.  日志打印时机的选择

## 2.1 日志文件命名 ##

通常来说日志文件的命名可包括以下几个关键信息：

1.  类型标识(logTypeName)
2.  日志级别(logLevel)
3.  日志生成时间(logCreateTime)
4.  日志备份编号(logBackupNum)

类型标识：指此日志文件的功能或者用途，比如一个web服务，记录http请求的日志通常命名为request.log或者access.log，request、access就是类型标识，而java的gc日志通常命名为gc.log，这样看一目了然；而通常用来记录服务的整体运行的日志一般用服务名称(serviceName、appKey)或者机器名(hostName)来命名，如 nginx.log；

日志级别：打印日志的时候直接通过文件来区分级别是一种比较推荐的方式，如果把所有级别的日志打到同一个日志文件中，在定位问题时，还需要去文件中进行查找操作，相对繁琐。日志级别一般包括DEBUG、INFO、WARN、ERROR、FATAL这五个级别，在实际编写代码中，可以采取严格匹配模式或者非严格匹配模式，严格匹配模式即INFO日志文件中只打印INFO日志，ERROR日志文件只打印ERROR日志；非严格匹配模式即INFO日志文件可以打印INFO日志、WARN日志、ERROR日志、FATAL日志，WARN日志文件可以打印WARN日志、ERROR日志、FATAL日志，以此类推。

日志生成时间：即在日志文件名称中附带上日志文件创建的时间，方便在查找日志文件时进行排序；

日志备份编号：当进行日志切割时，如果是以文件大小进行滚动，此时可以在日志文件名称末尾加上编号；

## 2.2 日志滚动 ##

虽然日志中能够保存系统运行时的关键信息，但是由于磁盘空间有限，所以我们不能无限制地保留日志，因此必须有日志滚动策略。日志滚动通常有以下几种模式：

1.  第一种：按照时间滚动
2.  第二种：按照单个日志文件大小滚动
3.  第三种：同时按照时间和单个日志文件大小滚动。

按照时间滚动，即每隔一定的时间建立一个新的日志文件，通常可以按照小时级别滚动或者天级别滚动，具体采取哪种方式取决于系统日志的打印量。如果系统日志比较少，可以采取天级别滚动；而如果系统日常量比较大，则建议采取小时级别滚动。  
按照单个日志文件大小滚动，即每当日志文件达到一定大小则建立一个新的日志文件，通常建议单个日志文件大小不要超过500M，日志文件过大的话，对于日志监控或者问题定位排查都可能会造成一定影响。

按照时间和单个日志文件大小滚动，这种模式通常适用于希望保留一定时间的日志，但是又不希望单个日志文件过大的场景。

对于日志滚动策略来说，有2个比较关键的参数：最大保留日志数量和最大磁盘占用空间。这2个参数切记一定要设置，如果没有设置，则很有可能会出现把线上机器磁盘打满的情况。

## 2.3 日志级别 ##

日志的级别通常有以下几种：

debug/trace、info、warning、error、fatal

这几种日志级别的严重程序依次递增：

*  debug/trace：debug和trace级别的日志由于打印内容较多，所以通常情况下不适用于线上生产环境使用，一般使用于前期线下环境调试。即使线上环境要使用，也需要通过开关来控制，只在定位追踪线上问题时才开启；
 *  info：info日志一般用来记录系统运行的关键状态、关键业务逻辑或者关键执行节点。但切记一点，info日志绝不可滥用，如果info日志滥用，则和debug/trace日志没有太大区别了。
 *  warning：warning日志一般用来记录系统运行时的一些非预期情况，顾名思义，是作为一种警示，提醒开发和运维人员需要关注，但是不用人为介入立刻去处理的。
 *  error：error日志一般用来记录系统运行时的一些普通错误，这些错误一旦出现，则表示已经影响了用户的正常访问或者使用，通常意味着需要人为介入处理。但很多时候在生产环境中，也不一定是出现error日志就需要人工立即介入处理的，通常会结合error日志的数量以及持续时间来进行综合判断。
 *  fatal：属于系统致命错误，一般出现意味着系统基本等于挂掉了，需要人工立即介入处理。

下面举个简单的例子来说明，假如我们有这样一个场景，我们有一个工资计算系统，每隔月1号需要从员工考勤系统获取公司所有员工的考勤数据，然后根据考勤数据来计算上月应发工资，那么需要有一个函数从考勤系统获取员工考勤数据：

public Map<Long, Double> getEmployeeWorkDaysFromAttendance(int year, int month, Set<Long> employeeList) throws BusiessException { 
            // 入口关键日志，需要打印关键的参数，因为employeeList可能数量较大，所以次数没有直接打印employeeList列表内容，只打印了size
            logger.info("get employee work days, year:{}, month:{}, employeeList.size:{}", year, month, employeeList.size());
     
            // 如果需要临时检验员工列表，可以把debug日志开关打开
            if (debugOpen()) { 
                logger.debug("employ list content:{}", JSON.toJsonString(employeeList));
            }
             
            int retry = 1;
            while (retry <= MAX_RETRY_TIMES) { 
                try { 
                    Map<Long, Double> employeeWorkDays = employeeAttendanceRPC.getEmployeeWorkDays(year, month, employeeList);
                    logger.info("get employee work days success, year:{}, month:{}, employeeList.size:{}, employeeWorkDays.size:{}", year, month, employeeList.size(), employeeWorkDays.size());
                    return employeeWorkDays;
                } catch (Exception ex) { 
                    logger.warning("rpc invoke failed(employeeAttendanceRPC.getEmployeeWorkDays), retry times:{}, year：{}, month:{}, employeeList.size:{}", retry, year, month, employeeList.size(), ex);
                     
                    // 连续重试失败之后，向上跑出异常
                    // 对于没有异常机制的语言，此处应该打印error日志
                    if (retry == MAX_RETRY_TIMES) { 
                        throw new BusiessException(ex, "rpc invoke failed(employeeAttendanceRPC.getEmployeeWorkDays)");
                    }
                }
                retry++;
            }
        }

## 2.4 日志打印时机的选择 ##

由于日志是为了方便我们了解系统当前的运行状况以及定位线上问题，所以日志打印的时机非常重要，如果滥用日志，则会导致日志内容过多，影响问题定位的效率；如果日志打印过少，则容易导致缺少关键日志，导致在线上定位问题时找不到问题根音。因此把握日志打印的时机至关重要，以下是常见的适合打印日志的时机：

### 1）http调用或者rpc接口调用 ###

在程序调用其他服务或者系统的时候，需要打印接口调用参数和调用结果(成功/失败)。

### 2）程序异常 ###

在程序出现exception的时候，要么选择向上抛出异常，要么必须在catch块中打印异常堆栈信息。不过需要注意的是，最好不要重复打印异常日志，比如在catch块里既向上抛出了异常，又去打印错误日志(对外rpc接口函数入口处除外)。

### 3）特殊的条件分支 ###

程序进入到一些特殊的条件分支时，比如特殊的else或者switch分支。比如我们根据工龄计算薪资：

public double calSalaryByWorkingAge(int age) { 
           if (age < 0) { 
               logger.error("wrong age value, age:{}", age);
               return 0;
           }
           // ..
       }

理论上工龄不可能小于0，所以需要打印出这种非预期情况，当然通过抛出异常的方式也是可行的。

### 4）关键执行路径及中间状态 ###

在一些关键的执行路径以及中间状态也需要记录下关键日志信息，比如一个算法可能分为很多步骤，每隔步骤的中间输出结果是什么，需要记录下来，以方便后续定位跟踪算法执行状态。

### 5）请求入口和出口 ###

在函数或者对外接口的入口/出口处需要打印入口/出口日志，一来方便后续进行日志统计，同时也更加方便进行系统运行状态的监控。

## 2.5 日志内容与格式 ##

日志打印时机决定了能够根据日志去进行问题定位，而日志的内容决定了是否能够根据日志快速找出问题原因，因此日志内容也是至关重要的。通常来说，一行日志应该至少包括以下几个组成部分：

logTag、param、exceptionStacktrace

*  logTag为日志标识，用来标识此日志输出的场景或者原因，
 *  param为函数调用参数，
 *  exceptionStacktrace为异常堆栈。

举例说明：

good case

public class HttpClient { 
            private static final Logger LOG = LoggerFactory.getLogger(HttpClient.class);
     
            private static int CONNECT_TIMEOUT = 5000;   // unit ms
            private static int READ_TIMEOUT = 10000;     // unit ms
     
            public static String sendPost(String url, String param) { 
                OutputStream out = null;
                BufferedReader in = null;
                String result = "";
                try { 
                    URL realUrl = new URL(url);
                    URLConnection conn = realUrl.openConnection();
                    conn.setDoInput(true);
                    conn.setDoOutput(true);
                    conn.setConnectTimeout(CONNECT_TIMEOUT);
                    conn.setReadTimeout(READ_TIMEOUT);
                    conn.setRequestProperty("charset", "UTF-8");
                    out = new PrintWriter(conn.getOutputStream());
                    out.print(parm);
                    out.flush();
                    in = new BufferedReader(new InputStreamReader(conn.getInputStream()));
                    String line;
                    while ((line = in.readLine()) != null) { 
                        result += line;
                    }
                } catch (Exception ex) { 
                    // 有关键logTag，有参数信息，有错误堆栈
                    LOG.error("post request error!!!, url:[[}], param:[{}]", url, param, ex);
                } finally { 
                    try { 
                        if (out != null) { 
                            out.close();
                        }
                        if (in != null) { 
                            in.close();
                        }
                    } catch (IOException ex) { 
                        LOG.error("close stream error!!!, url:[[}], param:[{}]", url, param, ex);
                    }
                    return result;
                }
            }
        }

bad case

public class HttpClient { 
        private static final Logger LOG = LoggerFactory.getLogger(HttpClient.class);
     
        private static int CONNECT_TIMEOUT = 5000;   // unit ms
        private static int READ_TIMEOUT = 10000;     // unit ms
         
        public static String sendPost(String url, String param) { 
            OutputStream out = null;
            BufferedReader in = null;
            String result = "";
            try { 
                URL realUrl = new URL(url);
                URLConnection conn = realUrl.openConnection();
                conn.setDoInput(true);
                conn.setDoOutput(true);
                conn.setConnectTimeout(CONNECT_TIMEOUT);
                conn.setReadTimeout(READ_TIMEOUT);
                conn.setRequestProperty("charset", "UTF-8");
                out = new PrintWriter(conn.getOutputStream());
                out.print(parm);
                out.flush();
                in = new BufferedReader(new InputStreamReader(conn.getInputStream()));
                String line;
                while ((line = in.readLine()) != null) { 
                    result += line;
                }
            } catch (Exception ex) { 
                // 没有任何错误信息
                LOG.error("post request error!!!");
            } finally { 
                try { 
                    if (out != null) { 
                        out.close();
                    }
                    if (in != null) { 
                        in.close();
                    }
                } catch (IOException ex) { 
                    LOG.error("close stream error!!!");
                }
                return result;
            }
        }
    }

另外，对于对外http接口或者rpc接口，最好对于每个请求都有requestId，以便跟踪每个请求后续所有的执行路径。

## 项目中该如何正确的打日志？ ##

### 1. 正确的定义日志 ###

### 2. 使用参数化形式\{\}占位，\[\] 进行参数隔离 ###

LOG.debug("Save order with order no：[{}], and order amount：[{}]");

### 3. 输出不同级别的日志 ###

项目中最常用有日志级别是ERROR、WARN、INFO、DEBUG四种了，这四个都有怎样的应用场景呢。

## 几个错误的打日志方式 ##

### 1.不要使用 `System.out.print..` ###

输出日志的时候只能通过日志框架来输出日志，而不能使用 System.out.print… 来打印日志，这个只会打印到 tomcat 控制台，而不会记录到日志文件中，不方便管理日志，如果通过服务形式启动把日志丢弃了那更是找不到日志了。

### 2. 不要使用 `e.printStackTrace()` ###

它其实也是利用 System.err 输出到了 tomcat 控制台。

### 3. 不要抛出异常后又输出日志 ###

如捕获异常后又抛出了自定义业务异常，此时无需记录错误日志，由最终捕获方进行异常处理。不能又抛出异常，又打印错误日志，不然会造成重复输出日志。

try { 
        // ...
    } catch (Exception e) { 
        // 错误
        LOG.error("xxx", e);
        throw new RuntimeException();
    }

### 4. 没有输出全部错误信息 ###

看以下代码，这样不会记录详细的堆栈异常信息，只会记录错误基本描述信息，不利于排查问题。

try { 
        // ...
    } catch (Exception e) { 
        // 错误
        LOG.error('XX 发生异常', e.getMessage());
     
        // 正确
        LOG.error('XX 发生异常', e);
    }

### 5. 不要使用错误的日志级别 ###

曾经在线上定位一个问题，同事自信地和我说：明明输出了日志啊，为什么找不到…，后来我去看了下他的代码，是这样的：

try { 
        // ...
    } catch (Exception e) { 
        // 错误
        LOG.info("XX 发生异常...", e);
    }

用 info 记录 error 日志，日志输出到了 info 日志文件中了，同事拼命地在 error 错误日志文件里面找怎么能找到呢？

### 6. 不要在千层循环中打印日志 ###

这个是什么意思，如果你的框架使用了性能不高的 Log4j 框架，那就不要在上千个 for循环中打印日志，这样可能会拖垮你的应用程序，如果你的程序响应时间变慢，那要考虑是不是日志打印的过多了。

for(int i=0; i<2000; i++){ 
        LOG.info("XX");
    }

### 7. 禁止在线上环境开启 debug ###