微信公众号:[中间件兴趣圈]
作者简介:《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官方微信公众号