微信公众号：[中间件兴趣圈]
作者简介：《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 start10 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)) { // @243 LoggerFactory.getLogger(ACCESS_LOG_KEY + "." + invoker.getInterface().getName()).info(msg);44 } else {45 log(accesslog, msg); // @346 }47 }48 } catch (Throwable t) {49 logger.warn("Exception in AcessLogFilter of service(" + invoker + " -> " + inv + ")", t);50 }51 return invoker.invoke(inv); // @452 }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() // @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.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官方微信公众号
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
