背景
生产环境,运营系统发现很慢,打开一个页面要好几秒,
怎么知道耗时好几秒?浏览器的调试模式可以看到,而且可以看到是哪个请求耗时好几秒。
具体原因是打印日志太多,导致耗时太久。是什么日志呢?查组织机构的数据,总共100万字。
本质原因是因为没有异步打印,是同步打印,然后日志太多,导致好久太久。之前也配置了异步打印,但是配置的有点问题。
那怎么实现异步打印日志?
首先第一步,怎么使用?按下面的方式,通过日志名字获取到对应的日志记录器。
private static final Logger logger = LoggerFactory.getLogger("dubbo.accesslog"); //同步打印日志
private static final Logger logger_async = LoggerFactory.getLogger("dubbo.accesslog.asnyc"); //异步打印日志
日志名字对应的日志记录器在哪里?在配置文件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>
<!-- 设置控制台日志 -->
<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"> //异步打印日志
<!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->
<discardingThreshold>0</discardingThreshold>
<!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
<queueSize>512</queueSize>
<!-- 添加附加的appender,最多只能添加一个 -->
<appender-ref ref="INFO_FILE"/>
</appender>
<logger name="dubbo.accesslog" additivity="false"> //同步打印日志
<level value="info"/>
<appender-ref ref="INFO_FILE"/>
</logger>
<!-- 异步日志 -->
<logger name="dubbo.accesslog.asnyc" additivity="false"> //异步打印日志
<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>
源码分析
结论
首先说结论
1.默认是同步打印日志,就不会走异步打印
2.配置了异步打印日志,才会走异步打印
类继承图
然后再看一下类继承图
1.默认是同步,就用同步日志记录器打印日志
2.如果配置了异步,并且使用的时候也是用的异步,那么就用异步日志记录器打印日志
源码
UnsynchronizedAppenderBase
/**
* Similar to AppenderBase except that derived appenders need to handle
* thread synchronization on their own.
*
* @author Ceki Gülcü
* @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);
}
}
AsyncAppenderBase
1.日志生产者
先把日志暂存起来,放到集合里。
/**
* 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ülcü
* @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);
}
}
2.日志消费者
然后再慢慢消费,异步消费,消费线程是独立的线程。
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(); //把日志取出来消费掉
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();
}
}
调用栈
核心流程
1.应用程序调用日志记录器打印日志
用哪个日志级别打印日志?
2.找到用哪个日志记录器
是同步还是异步?
3.用同步appender还是异步appender?
如果是异步,就用异步appender打印;
如果是同步,就用同步appender打印。
异步打印日志的完整方法调用栈
append:157, AsyncAppenderBase (ch.qos.logback.core) //异步打印日志
doAppend:84, UnsynchronizedAppenderBase (ch.qos.logback.core) //用异步appender还是同步appender来打印日志?这里是用异步appender来打印日志。
appendLoopOnAppenders:51, AppenderAttachableImpl (ch.qos.logback.core.spi) //1.如果是4个同步appender,都不走异步 2.如果是异步,才走异步 。
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) //用哪个日志级别?这里是info日志级别。
invoke:197, 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: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)
在idea里看方法调用栈
同步的日志级别可以是info/error,异步的日志级别也可以是info/error。
如果没有异步appender,日志记录器集合就是这几种
如果用异步打印,日志记录器就是异步appender