background

Production environment, operation system discovery is slow, it takes several seconds to open a page,

How do you know it takes seconds? The browser debug mode can be seen, and you can see which request took several seconds.

The cause is that too many logs are printed, which takes too long. What kind of log is it? Check the organization’s data. It’s a million words.

The essential reason is that there is no asynchronous printing, but synchronous printing, and then too many logs, resulting in too long. Asynchronous printing was also configured before, but there was a problem with the configuration.

How to print logs asynchronously?

First step, how do you use it? Obtain the corresponding logger by log name as follows.

private static final Logger logger = LoggerFactory.getLogger("dubbo.accesslog"); Private static final Logger logger_Async = LoggerFactory.getLogger(" dubo.accessLog.asnyc "); // Logs are generated asynchronouslyCopy the code

Where is the logger corresponding to the log name? In the configuration file logback.xml.

<appender name="INFO_FILE" class="xxx.log.logback.appender.ExtRollingFileAppender"> <file>${logback.logpath}/info.log</file> <! -- see https://logback.qos.ch/manual/filters.html --> <filter class="ch.qos.logback.classic.filter.LevelFilter"> <level>INFO</level> <onMatch>ACCEPT</onMatch> <onMismatch>DENY</onMismatch> </filter> <! -- see https://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedFNATP --> <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <fileNamePattern>${logback.logpath}/info.%d{yyyyMMdd}.%i.log </fileNamePattern> <maxFileSize>${logback.maxFileSize}</maxFileSize> </rollingPolicy> <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder"> <! -- see https://logback.qos.ch/manual/layouts.html --> <layout class="xxx.log.logback.layout.ExtLayout"> <pattern>${logback.pattern}</pattern> <charset>${logback.encoding}</charset> </layout> </encoder> </appender> <appender name="ERROR_FILE" class="xxx.log.logback.appender.ExtRollingFileAppender"> <file>${logback.logpath}/error.log</file> <filter class="ch.qos.logback.classic.filter.ThresholdFilter"> <level>WARN</level> </filter> <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <fileNamePattern>${logback.logpath}/error.%d{yyyyMMdd}.%i.log </fileNamePattern> <maxFileSize>${logback.maxFileSize}</maxFileSize> </rollingPolicy> <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder"> <layout class="xxx.log.logback.layout.ExtLayout"> <pattern>${logback.pattern.error}</pattern> <charset>${logback.encoding}</charset> </layout> </encoder> </appender> <! - set up the console log - > < appender name = "stdout" class = "XXX. Log. Logback. Appender. ExtConsoleAppender" > < encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder"> <layout class="xxx.log.logback.layout.ExtLayout"> <pattern>${logback.pattern}</pattern> <charset>${logback.encoding}</charset> </layout> </encoder> </appender> <appender Name = "ASYNC" class = "ch. Qos. Logback. Classic. AsyncAppender" > / / asynchronous print log <! -- Do not lose logs. The system discards cards with 80% of the queue being full. For example, TRACT, DEBUG, and INFO logs are discarded. <discardingThreshold>0</discardingThreshold> Change the default queue depth, which affects performance. The default value is 256 --> <queueSize>512</queueSize> <! > <appender-ref ref="INFO_FILE"/> </appender> <logger name=" dubo.accesslog" Additivity ="false"> // Sync print logs <level value="info"/> <appender-ref ref="INFO_FILE"/> </logger> <! <logger name=" dubo.accesslog.asnyc "additivity="false"> // Debug log <level value="info"/> <appender-ref ref="ASYNC"/> </logger> <root level="${logback.rootLoggerLevel}"> <appender-ref ref="DEBUG_FILE" /> <appender-ref ref="INFO_FILE" /> <appender-ref ref="ERROR_FILE" /> <! <appender-ref ref="stdout" /> </root> </configuration>Copy the code

Source code analysis

conclusion

Conclusion 1. By default, logs are printed synchronously, but asynchronous logs are not printed asynchronously. 2

Class diagram

Then look at the class inheritance diagram

2. If asynchrony is configured and asynchrony is used, asynchrony is used to print logs

The source code

UnsynchronizedAppenderBase

/** * Similar to AppenderBase except that derived appenders need to handle * thread synchronization on their own. * * @author Ceki G&uuml; lc&uuml; * @author Ralph Goers */ abstract public class UnsynchronizedAppenderBase<E> extends ContextAwareBase implements Appender<E> { public void doAppend(E eventObject) { // WARNING: The guard check MUST be the first statement in the // doAppend() method. // prevent re-entry. if (Boolean.TRUE.equals(guard.get())) { return; } try { guard.set(Boolean.TRUE); if (! this.started) { if (statusRepeatCount++ < ALLOWED_REPEATS) { addStatus(new WarnStatus("Attempted to append to non started appender [" + name + "].", this)); } return; } if (getFilterChainDecision(eventObject) == FilterReply.DENY) { return; } // ok, we now invoke derived class' implementation of append this.append(eventObject); } catch (Exception e) {if (exceptionCount++ < ALLOWED_REPEATS) {addError("Appender [" + name + "] failed to append.", e); } } finally { guard.set(Boolean.FALSE); }}Copy the code

AsyncAppenderBase

1. The log producer temporarily stores logs to the collection.

/** * This appender and derived classes, log events asynchronously. In order to avoid loss of logging events, this * appender should be closed. It is the user's responsibility to close appenders, typically at the end of the * application lifecycle. * <p/> * This appender buffers events in a {@link BlockingQueue}. {@link Worker} thread created by this appender takes * events from the head of the queue, and dispatches them to the single appender attached to this appender. * <p/> * <p>Please refer to the <a href="http://logback.qos.ch/manual/appenders.html#AsyncAppender">logback manual</a> for * further information about this  appender.</p> * * @param <E> * @author Ceki G&uuml; lc&uuml; * @ author Torsten Juergeleit * @ since 1.0.4 * / public class AsyncAppenderBase < E > extends UnsynchronizedAppenderBase < E > implements AppenderAttachable<E> { @Override protected void append(E eventObject) { if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) { return; } preprocess(eventObject); put(eventObject); } private void put(E eventObject) {if (neverBlock) {blockingqueue.offer (eventObject); } else {putUninterruptibly(eventObject); }}Copy the code

2. Log consumer and then slowly consume, asynchronous consumption, consumption thread is independent thread.

class Worker extends Thread { public void run() { AsyncAppenderBase<E> parent = AsyncAppenderBase.this; AppenderAttachableImpl<E> aai = parent.aai; // loop while the parent is started while (parent.isStarted()) { try { E e = parent.blockingQueue.take(); / / remove the log to consume aai. AppendLoopOnAppenders (e); } catch (InterruptedException ie) { break; } } addInfo("Worker thread will flush remaining events before exiting. "); for (E e : parent.blockingQueue) { aai.appendLoopOnAppenders(e); parent.blockingQueue.remove(e); } aai.detachAndStopAllAppenders(); }}Copy the code

The call stack

Core flow 1. The application calls the logger to print logs at what log level should logs be printed?

2. Find which logger to use synchronous or asynchronous?

3. Synchronous or asynchronous appender? If asynchronous, print with an asynchronous appender. If it is synchronous, print with a synchronous appender.

A complete method call stack for asynchronously printing logs

Append: 157, AsyncAppenderBase (ch.qos.logback.core) // Print logs asynchronously doAppend:84, UnsynchronizedAppenderBase (ch. Qos. Logback. Core) / / use asynchronous synchronous appender appender or to print log? An asynchronous appender is used to print logs. appendLoopOnAppenders:51, AppenderAttachableImpl (ch.qos.logback.core.spi) //1. If there are four synchronous appenders, none of them are asynchronous. 2. If there are four synchronous appenders, none of them are asynchronous. appendLoopOnAppenders:270, Logger (ch.qos.logback.classic) callAppenders:257, Logger (ch.qos.logback.classic) buildLoggingEventAndAppend:421, Logger (ch.qos.logback.classic) filterAndLog_0_Or3Plus:383, Logger (ch.qos.logback.classic) info:579, Logger (ch.qos.logback.classic) // Which log level is used? Here is the INFO log level. Invoke: 197, AccessLogExtFilter (xxx.xxx.com mon. Filter. Dubbo) / / invoke application layer: 72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:82, CatTransaction (com.xxx.log.rpc.dubbo) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:49, ConsumerContextFilter (com.alibaba.dubbo.rpc.filter) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:56, InvokerWrapper (com.alibaba.dubbo.rpc.protocol) doInvoke:78, FailoverClusterInvoker (com.alibaba.dubbo.rpc.cluster.support) invoke:244, AbstractClusterInvoker (com.alibaba.dubbo.rpc.cluster.support) invoke:75, MockClusterInvoker (com.alibaba.dubbo.rpc.cluster.support.wrapper) invoke:52, InvokerInvocationHandler (com.alibaba.dubbo.rpc.proxy) decryptByType:-1, proxy18 (com.alibaba.dubbo.common.bytecode) decryptByType:193, CipherServiceImpl (xxx.xxx.register.component.cipher) decryptAddress:252, CipherServiceImpl (xxx.xxx.register.component.cipher) decryptMerc:134, xxxMerQueryServer (xxx.xxx.register.remoteserver.impl) getUrmtminf:97, xxxMerQueryServer (xxx.xxx.register.remoteserver.impl) queryMerchantInfo:74, xxxMerQueryServer (xxx.xxx.register.remoteserver.impl) invokeMethod:-1, Wrapper28 (com.alibaba.dubbo.common.bytecode) doInvoke:47, JavassistProxyFactory$1 (com.alibaba.dubbo.rpc.proxy.javassist) invoke:76, AbstractProxyInvoker (com.alibaba.dubbo.rpc.proxy) invoke:52, DelegateProviderMetaDataInvoker (com.alibaba.dubbo.config.invoker) invoke:56, InvokerWrapper (com.alibaba.dubbo.rpc.protocol) invoke:11, AppNameAppendFilter (com.xxx.log.rpc.dubbo) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:62, ExceptionFilter (com.alibaba.dubbo.rpc.filter) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:42, TimeoutFilter (com.alibaba.dubbo.rpc.filter) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:60, ExecuteLimitFilter (com.alibaba.dubbo.rpc.filter) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:75, MonitorFilter (com.alibaba.dubbo.monitor.support) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:78, TraceFilter (com.alibaba.dubbo.rpc.protocol.dubbo.filter) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:85, AccessLogExtFilter (xxx.xxx.common.filter.dubbo) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:82, CatTransaction (com.xxx.log.rpc.dubbo) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:73, ContextFilter (com.alibaba.dubbo.rpc.filter) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:138, GenericFilter (com.alibaba.dubbo.rpc.filter) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:38, ClassLoaderFilter (com.alibaba.dubbo.rpc.filter) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) invoke:38, EchoFilter (com.alibaba.dubbo.rpc.filter) invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol) reply:104, DubboProtocol$1 (com.alibaba.dubbo.rpc.protocol.dubbo) handleRequest:96, HeaderExchangeHandler (com.alibaba.dubbo.remoting.exchange.support.header) received:173, HeaderExchangeHandler (com.alibaba.dubbo.remoting.exchange.support.header) received:51, DecodeHandler (com.alibaba.dubbo.remoting.transport) run:57, ChannelEventRunnable (com.alibaba.dubbo.remoting.transport.dispatcher) runWorker:1145, ThreadPoolExecutor (java.util.concurrent) run:615, ThreadPoolExecutor$Worker (java.util.concurrent) run:745, Thread (java.lang)Copy the code

Look at the method call stack in idea

The log level can be INFO/ERROR for synchronization or Info /error for asynchronous synchronization.

Without asynchronous appenders, logger collections are these

If printed asynchronously, the logger is an asynchronous appender

reference

Juejin. Cn/post / 684490…