源码分析Dubbo服务调用日志(accesslog参数)实现原理

微信公众号：**[中间件兴趣圈]** 作者简介：《RocketMQ技术内幕》

谈到服务调用日志，大家恐怕第一想到就是如果开启了这个参数，会影响性能。那真实的情况是怎么样了？性能损耗到底有多大呢？在实践中我们如何使用该功能呢？本文将详细分析Dubbo accesslog实现原理。

AccessLogFilter概述

过滤器作用 记录调用日志。

使用场景 记录服务提供者端调用日志。

阻断条件 非阻断过滤器。

接下来源码分析accesslog参数的实现原理。

使用场景
记录服务提供者端调用日志。

接下来源码分析accesslog参数的实现原理。

核心字段说明

LOG_MAX_BUFFER：积累最大的日志容量，默认为5000条，如果积压在队列中的待处理日志超过该值，则直接丢弃。

LOG_OUTPUT_INTERVAL：日志写出的调度频率，默认为5s。

ConcurrentMap String, Set String logQueue：日志容器。

ScheduledExecutorService logScheduled：写出日志调度器，默认为2个线程，线程名称为：Dubbo-Access-Log。

LOG_OUTPUT_INTERVAL：日志写出的调度频率，默认为5s。

ScheduledExecutorService logScheduled：写出日志调度器，默认为2个线程，线程名称为：Dubbo-Access-Log。

invoke方法源码分析

AccessLogFilter#invoke

 1public Result invoke(Invoker? invoker, Invocation inv) throws RpcException {
 2        try {
 3            String accesslog = invoker.getUrl().getParameter(Constants.ACCESS_LOG_KEY);    
 4            if (ConfigUtils.isNotEmpty(accesslog)) {    // @1                                                       
 5                RpcContext context = RpcContext.getContext();
 6                String serviceName = invoker.getInterface().getName();
 7                String version = invoker.getUrl().getParameter(Constants.VERSION_KEY);
 8                String group = invoker.getUrl().getParameter(Constants.GROUP_KEY);
 9                StringBuilder sn = new StringBuilder();         // @2 start
10                sn.append("[").append(new SimpleDateFormat(MESSAGE_DATE_FORMAT).format(new Date())).append("] 
11                       ").append(context.getRemoteHost()).append(":").append(context.getRemotePort())
12                        .append(" - ").append(context.getLocalHost()).append(":").append(context.getLocalPort())
13                        .append(" - ");
14                if (null != group && group.length()  0) {
15                    sn.append(group).append("/");
16                }
17                sn.append(serviceName);
18                if (null != version && version.length()  0) {
19                    sn.append(":").append(version);
20                }
21                sn.append(" ");
22                sn.append(inv.getMethodName());
23                sn.append("(");
24                Class?[] types = inv.getParameterTypes();
25                if (types != null && types.length  0) {
26                    boolean first = true;
27                    for (Class? type : types) {
28                        if (first) {
29                            first = false;
30                        } else {
31                            sn.append(",");
32                        }
33                        sn.append(type.getName());
34                    }
35                }
36                sn.append(") ");
37                Object[] args = inv.getArguments();
38                if (args != null && args.length  0) {
39                    sn.append(JSON.toJSONString(args));
40                }
41                String msg = sn.toString();
42                if (ConfigUtils.isDefault(accesslog)) {         // @2
43                    LoggerFactory.getLogger(ACCESS_LOG_KEY + "." + invoker.getInterface().getName()).info(msg);
44                } else {
45                    log(accesslog, msg);                              // @3
46                }
47            }
48        } catch (Throwable t) {
49            logger.warn("Exception in AcessLogFilter of service(" + invoker + " - " + inv + ")", t);
50        }
51        return invoker.invoke(inv);                                 // @4
52    }
53

代码@1：首先从服务提供者URL中获取accesslog参数，如果存在该参数并且不为空，则进入服务调用日志，如果未配置，则直接进入下一个过滤器。

代码@2：组装服务调用日志，其内容：
[服务调用时间，精确到时分秒] + 消费者IP:消费者PORT +  – 服务提供者IP:服务提供者端口 +  “服务提供者group/“(可选) + serviceName(interface name) + “:version”(可选) + methodName( + 参数类型列表）+  参数值(json格式的字符串) 。

代码@3：如果accesslog=”true”，则使用info级别的日志输出；如果是配置的是日志路径的话，则异步写入文件。
接下来分析一下log方法，写入日志文件的具体实现：

AccessLogFilter#log

 1private void log(String accesslog, String logmessage) {
 2        init();                                                             // @1
 3        SetString logSet = logQueue.get(accesslog);                                            // @2 start
 4        if (logSet == null) {
 5            logQueue.putIfAbsent(accesslog, new ConcurrentHashSetString());
 6            logSet = logQueue.get(accesslog);
 7        }
 8        if (logSet.size()  LOG_MAX_BUFFER) {                                                   // @2 end
 9            logSet.add(logmessage);
10        }
11    }

代码@1：授权通过init方法启动定时任务，已间隔5s,延迟5s后执行第一次调度，具体的任务实现为LogTask。

 1private void init() {
 2        if (logFuture == null) {
 3            synchronized (logScheduled) {
 4                if (logFuture == null) {
 5                    logFuture = logScheduled.scheduleWithFixedDelay(new LogTask(), LOG_OUTPUT_INTERVAL, LOG_OUTPUT_INTERVAL, 
 6                           TimeUnit.MILLISECONDS);
 7                }
 8            }
 9        }
10    }

代码@2：以文件路径名accesslog为键，从logQueue中获取，如果当前处理的长度大于LOG_MAX_BUFFER固定为5000条，则丢弃。由于存储日志的容器为ConcurrentHashSet，则日志记录是乱序的。

具体异步记录日志的任务实现为AccessLogFilter$LogTask。

 1private class LogTask implements Runnable {
 2        @Override
 3        public void run() {
 4            try {
 5                if (logQueue != null && logQueue.size()  0) {
 6                    for (Map.EntryString, SetString entry : logQueue.entrySet()) {
 7                        try {
 8                            String accesslog = entry.getKey();
 9                            SetString logSet = entry.getValue();
10                            File file = new File(accesslog);              
11                            File dir = file.getParentFile();  
12                            if (null != dir && !dir.exists()) {
13                                dir.mkdirs();
14                            }     // @1
15                            if (logger.isDebugEnabled()) {
16                                logger.debug("Append log to " + accesslog);
17                            }
18                            if (file.exists()) {    // @2
19                                String now = new SimpleDateFormat(FILE_DATE_FORMAT).format(new Date());
20                                String last = new SimpleDateFormat(FILE_DATE_FORMAT).format(new Date(file.lastModified()));
21                                if (!now.equals(last)) {
22                                    File archive = new File(file.getAbsolutePath() + "." + last);
23                                    file.renameTo(archive);
24                                }
25                            }
26                            FileWriter writer = new FileWriter(file, true);
27                            try {
28                                for (IteratorString iterator = logSet.iterator();
29                                     iterator.hasNext();
30                                     iterator.remove()) {
31                                    writer.write(iterator.next());
32                                    writer.write("rn");
33                                }
34                                writer.flush();
35                            } finally {
36                                writer.close();
37                            }
38                        } catch (Exception e) {
39                            logger.error(e.getMessage(), e);
40                        }
41                    }
42                }
43            } catch (Exception e) {
44                logger.error(e.getMessage(), e);
45            }
46        }
47    }

代码@1：从这里可以看出accesslog配置的是具体的日志文件全路径，例如d:/logs/accesslog.log。

代码@2：如果文件存在，则需要判断该文件的最后修改时间与当前日期是否相同，如果不同，则首先将文件重新命名为前一天的日期，然后再创建一个新的accesslog文件，也就是accesslog文件的布局是一天一个文件。

accesslog调用日志记录就分析到这里，我们思考一下开启该参数对服务提供者的性能影响。

accesslog="true",其实现为通过log4j等日志组件，使用info级别将调用日志输出，该方法对服务调用者的影响还是比较大，不建议这样使用。

accesslog="日志文件路径"，该方式，dubbo使用的是异步记录日志的方式，开启额外的信息，主要是需要组织日志内容，耗费一定的CPU资源，但对服务的响应整体性能损耗还是不会起到恶劣的影响。默认情况下，还是不建议开启，但是如果线上服务器有BUG，需要通过调用日志来拍错的话，也可以在不重启服务提供者的情况下开启，开启方法利用Dubbo的配置覆盖机制，该部分的内容详情请参考作者的另一篇推文： 。

广告：作者的新书《RocketMQ技术内幕》已上市

《RocketMQ技术内幕》已出版上市，目前可在主流购物平台（京东、天猫等）购买，本书从源码角度深度分析了RocketMQ NameServer、消息发送、消息存储、消息消费、消息过滤、主从同步HA、事务消息；在实战篇重点介绍了RocketMQ运维管理界面与当前支持的39个运维命令；并在附录部分罗列了RocketMQ几乎所有的配置参数。本书得到了RocketMQ创始人、阿里巴巴Messaging开源技术负责人、Linux OpenMessaging 主席的高度认可并作序推荐。目前是国内第一本成体系剖析RocketMQ的书籍。
新书7折优惠！7折优惠！7折优惠！

更多文章请关注微信公众号：

推荐关注微信公众号：RocketMQ官方微信公众号

原文始发于微信公众号（中间件兴趣圈）：