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

AccessLogFilter概述

• 过滤器作用
• 记录调用日志。
• 使用场景
• 记录服务提供者端调用日志。
• 阻断条件
• 非阻断过滤器。

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

1、核心字段说明

• LOG_MAX_BUFFER：积累最大的日志容量，默认为5000条，如果积压在队列中的待处理日志超过该值，则直接丢弃。
• LOG_OUTPUT_INTERVAL：日志写出的调度频率，默认为5s。
• ConcurrentMap< String, Set< String>> logQueue：日志容器。
• ScheduledExecutorService logScheduled：写出日志调度器，默认为2个线程，线程名称为：Dubbo-Access-Log。

2、invoke方法源码分析

AccessLogFilter#invoke

public Result invoke(Invoker<?> invoker, Invocation inv) throws RpcException { try { String accesslog = invoker.getUrl().getParameter(Constants.ACCESS_LOG_KEY); if (ConfigUtils.isNotEmpty(accesslog)) { // @1 RpcContext context = RpcContext.getContext(); String serviceName = invoker.getInterface().getName(); String version = invoker.getUrl().getParameter(Constants.VERSION_KEY); String group = invoker.getUrl().getParameter(Constants.GROUP_KEY); StringBuilder sn = new StringBuilder(); // @2 start sn.append("[").append(new SimpleDateFormat(MESSAGE_DATE_FORMAT).format(new Date())).append("] ").append(context.getRemoteHost()).append(":").append(context.getRemotePort()) .append(" -> ").append(context.getLocalHost()).append(":").append(context.getLocalPort()) .append(" - "); if (null != group && group.length() > 0) { sn.append(group).append("/"); } sn.append(serviceName); if (null != version && version.length() > 0) { sn.append(":").append(version); } sn.append(" "); sn.append(inv.getMethodName()); sn.append("("); Class<?>[] types = inv.getParameterTypes(); if (types != null && types.length > 0) { boolean first = true; for (Class<?> type : types) { if (first) { first = false; } else { sn.append(","); } sn.append(type.getName()); } } sn.append(") "); Object[] args = inv.getArguments(); if (args != null && args.length > 0) { sn.append(JSON.toJSONString(args)); } String msg = sn.toString(); if (ConfigUtils.isDefault(accesslog)) { // @2 LoggerFactory.getLogger(ACCESS_LOG_KEY + "." + invoker.getInterface().getName()).info(msg); } else { log(accesslog, msg); // @3 } } } catch (Throwable t) { logger.warn("Exception in AcessLogFilter of service(" + invoker + " -> " + inv + ")", t); } return invoker.invoke(inv); // @4 } 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 

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

代码@2：组装服务调用日志，其内容：

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

代码@3：如果accesslog=”true”，则使用info级别的日志输出；如果是配置的是日志路径的话，则异步写入文件。

接下来分析一下log方法，写入日志文件的具体实现：

AccessLogFilter#log

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

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

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

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

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

private class LogTask implements Runnable { @Override public void run() { try { if (logQueue != null && logQueue.size() > 0) { for (Map.Entry<String, Set<String>> entry : logQueue.entrySet()) { try { String accesslog = entry.getKey(); Set<String> logSet = entry.getValue(); File file = new File(accesslog); File dir = file.getParentFile(); if (null != dir && !dir.exists()) { dir.mkdirs(); } // @1 if (logger.isDebugEnabled()) { logger.debug("Append log to " + accesslog); } if (file.exists()) { // @2 String now = new SimpleDateFormat(FILE_DATE_FORMAT).format(new Date()); String last = new SimpleDateFormat(FILE_DATE_FORMAT).format(new Date(file.lastModified())); if (!now.equals(last)) { File archive = new File(file.getAbsolutePath() + "." + last); file.renameTo(archive); } } FileWriter writer = new FileWriter(file, true); try { for (Iterator<String> iterator = logSet.iterator(); iterator.hasNext(); iterator.remove()) { writer.write(iterator.next()); writer.write("\r\n"); } writer.flush(); } finally { writer.close(); } } catch (Exception e) { logger.error(e.getMessage(), e); } } } } catch (Exception e) { logger.error(e.getMessage(), e); } } } 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 

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

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

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

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

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