源码分析Dubbo服务调用日志(accesslog参数)实现原理
微信公众号：[中间件兴趣圈]
作者简介：《RocketMQ技术内幕》
谈到服务调用日志，大家恐怕第一想到就是如果开启了这个参数，会影响性能。那真实的情况是怎么样了？性能损耗到底有多大呢？在实践中我们如何使用该功能呢？本文将详细分析Dubbo accesslog实现原理。
AccessLogFilter概述
过滤器作用
记录调用日志。使用场景
记录服务提供者端调用日志。阻断条件
非阻断过滤器。接下来源码分析accesslog参数的实现原理。
核心字段说明
LOG_MAX_BUFFER：积累最大的日志容量，默认为5000条，如果积压在队列中的待处理日志超过该值，则直接丢弃。
LOG_OUTPUT_INTERVAL：日志写出的调度频率，默认为5s。
ConcurrentMap< String, Set< String>> logQueue：日志容器。
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 Set<String> logSet = logQueue.get(accesslog); // @2 start
4 if (logSet == null) {
5 logQueue.putIfAbsent(accesslog, new ConcurrentHashSet<String>());
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
3 public void run() {
4 try {
5 if (logQueue != null && logQueue.size() > 0) {
6 for (Map.Entry<String, Set<String>> entry : logQueue.entrySet()) {
7 try {
8 String accesslog = entry.getKey();
9 Set<String> 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 (Iterator<String> iterator = logSet.iterator();
29 iterator.hasNext();
30 iterator.remove()) {
31 writer.write(iterator.next());
32 writer.write("\r\n");
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的配置覆盖机制，该部分的内容详情请参考作者的另一篇推文：源码分析Dubbo override协议 。
广告：作者的新书《RocketMQ技术内幕》已上市
《RocketMQ技术内幕》已出版上市，目前可在主流购物平台（京东、天猫等）购买，本书从源码角度深度分析了RocketMQ NameServer、消息发送、消息存储、消息消费、消息过滤、主从同步HA、事务消息；在实战篇重点介绍了RocketMQ运维管理界面与当前支持的39个运维命令；并在附录部分罗列了RocketMQ几乎所有的配置参数。本书得到了RocketMQ创始人、阿里巴巴Messaging开源技术负责人、Linux OpenMessaging 主席的高度认可并作序推荐。目前是国内第一本成体系剖析RocketMQ的书籍。
新书7折优惠！7折优惠！7折优惠！
更多文章请关注微信公众号：
推荐关注微信公众号：RocketMQ官方微信公众号