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

谈到服务调用日志，大家恐怕第一想到就是如果开启了这个参数，会影响性能。那真实的情况是怎么样了？性能损耗到底有多大呢？在实践中我们如何使用该功能呢？本文将详细分析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("
");
 }
 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的配置覆盖机制，