When it comes to service invocation logging, the first thing that comes to mind is that if this parameter is turned on, it will affect performance. So what’s the real story? How big is the performance loss? How do we use this feature in practice? This article will analyze the implementation principle of Dubbo AccessLog in detail. AccessLogFilter overview

  • The filter function logs the call.
  • Usage Scenario Recording service provider invocation logs.
  • Block condition Non-block filter.

Next source code analysis of accesslog parameter implementation principle.



1. Description of core fields

  • LOG_MAX_BUFFER: indicates the maximum number of accumulated logs. The default value is 5000. If the number of accumulated logs exceeds this value, the logs are discarded.
  • LOG_OUTPUT_INTERVAL: scheduling frequency of log writing. The default value is 5s.
  • ConcurrentMap< String, Set< String>> logQueue: indicates the log container.
  • ScheduledExecutorService logScheduled: Writes out the Log scheduler. The default value is two threads. The thread name is dubo-access-log.

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}Copy the code

Code @1: First get the AccessLog parameter from the service provider URL, if it is present and not empty, go to the service invocation log, if not configured, go straight to the next filter. Code @2: Assemble the service invocation log with the following contents: [Service invocation time, ] + Consumer IP: Consumer PORT + –> Service provider IP: service provider PORT + service provider group/ (optional) + serviceName(interface name) + :version (optional) + MethodName (+ list of parameter types) + parameter value (string in JSON format). Code @3: If accesslog= “true”, use info-level log output; If the log path is configured, the file is written asynchronously. Next, let’s look at the log method, which writes to a log file: accessLogFile #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); }}Copy the code

@1: Authorize the init method to start the scheduled task. After 5s interval, the first scheduling is performed after 5s delay. The specific task is implemented as 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); }}}}Copy the code

@2: Accesslog from logQueue. If the current processing length is greater than LOG_MAX_BUFFER (fixed number: 5000), it will be discarded. Because the container used to store logs is ConcurrentHashSet, the logs are out of order. The asynchronous log recording task is 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); }}}Copy the code

@1: From here you can see that accesslog is configured to specify the full path of log files, for example, d:/logs/accesslog.log. Code @2: If the file exists, we need to determine whether the last modification time of the file is the same as the current date. If not, we will first rename the file to the previous date, and then create a new AccessLog file, that is, the layout of the AccessLog file is one file per day.

With accessLog invocation logging out of the way, let’s consider the performance impact of enabling this parameter on the service provider. 1. Accesslog = “true”, which is implemented through logging components such as log4j, using the info level to call the log output. This method has a relatively large impact on the service caller and is not recommended. Accesslog = “Log file path”, this method, Dubbo uses asynchronous logging mode, enable additional information, mainly need to organize log content, consume some CPU resources, but the overall performance of the service response will not have a bad impact. By default, it is still not recommended to enable this function, but if there is a BUG in the online server and you need to call the log to catch the error, you can also enable this function without restarting the service provider, using Dubbo’s configuration override mechanism. For details on this section, see another blog post by Author: Source code analysis rules of Dubbo configuration mechanism (override agreements) : blog.csdn.net/prestigedin… .

Welcome to add the author micro signal (DINGwPMZ), add group discussion, the author quality column catalog: 1, source analysis RocketMQ column (40 +) 2, source analysis Sentinel column (12 +) 3, source analysis Dubbo column (28 +) 4, source analysis Mybatis column 5, source analysis Netty column (18 +) 6, source analysis JUC column Source code analysis (MyCat) for Elasticjob