Original link: blog.fliaping.com/a-high-conc…
preface
Logging should be the basic component of an application, and the old log4j should be the one we use most. Later, as the Internet develops, we all work towards high concurrency, and find that log4j performance is not good because of the blocking caused by competing locks. Log4j2 has also been upgraded to provide asynchronous logging performance, but there are still a lot of problems with the use of log4j. Here are some of the pitfalls of log4j:
- Version 1.x of Log4j causes blocked deadlocks
- Log4J, upgrade version in stomp pit
Problem description
The primary performance
After the release of an APP push service, when the batch push task is encountered, the thread pool is full, the queue is full, and the task is piled up. (Note: since the change point of this release is very common, this point was not suspected first.)
Related to the environment
- Spring – the boot: 1.5.3
- Log4j: 2.7
- jdk1.8
Publish change points
- A new feature has been added (unrelated to this article)
- I added it to a class
@RefreshScopeannotations
Processing flow
- I thought it was caused by the increase in the time of the third-party interface. The monitoring shows that the time is quite high, but the ping,curl, and network monitoring show that the interface is not a problem
- Reading the code, I found that the monitoring item not only contained the time spent calling the third-party interface, but also other operations. Therefore, I believed that the monitoring item was not trusted, and verified again that it was not the third-party interface, nor the network problem
- It is found that the two time points in the statistical log are quite different, even three seconds. The point is that an exception was thrown and a log was made between the two points in time
- Found in the code log4j2 configuration using synchronous Logger, asynchronous AsyncAppender, doubt is the high concurrency of synchronous log jam, change the log to cooperate disrupter AsyncLogger, results not what use
- Thread Dump shows that many threads are BLOCKED, and the call stack display is indeed relevant to Log4j, and clearly points to exception stack printing
- Because there are many warnings in the application, and these logs print out the exception stack. Stop printing any unnecessary exception stacks in the log, and the problem is resolved
Problem analysis
Doubt point
- Why are logs not printed asynchronously?
- Why does the print exception stack block? Where is the blockage?
- Why is it blocking, and how is it related to the changes being published?
Thread stack analysis
Disruptor (AsyncLogger) disruptor (AsyncLogger) Disruptor (AsyncLogger) Disruptor (AsyncLogger
"fastExecutor-670" #2178 prio=5 os_prio=0 tid=0x00007f2d483cd800 nid=0x6026 waiting for monitor entry [0x00007f2c158c3000] java.lang.Thread.State: BLOCKED (on object monitor) at java.lang.ClassLoader.loadClass(ClassLoader.java:404) - waiting to lock <0x0000000088104b60> (a java.lang.Object) at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:94) at java.lang.ClassLoader.loadClass(ClassLoader.java:357) at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:539) at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:660) at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:137) at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:94) at java.lang.ClassLoader.loadClass(ClassLoader.java:357) at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:539) at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:660) at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:137) at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:121) at org.apache.logging.log4j.core.impl.Log4jLogEvent.getThrownProxy(Log4jLogEvent.java:555) at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:61 )... Thin down some logs... at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:447) at org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppendersInCurrentThread(AsyncLoggerConfig.java:105) at org.apache.logging.log4j.core.async.EventRoute$2.logMessage(EventRoute.java:65) at org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppenders(AsyncLoggerConfig.java:95) at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:432) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:416) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:402) at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63) at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146) at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2091) at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1988) at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1960) at org.apache.logging.slf4j.Log4jLogger.warn(Log4jLogger.java:259) at com.dianwoda.delibird.common.traffic.FastCommander.lambda$runnersEnter$0(FastCommander.java:175) at com.dianwoda.delibird.common.traffic.FastCommander?Lambda$111/638548222.run(Unknown Source) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)Copy the codeThe following is the content of the application exception stack
com.dianwoda.delibird.common.domain.DeliException: at com.dianwoda.delibird.push.manager.PushManager.send(PushManager.java:104) ~[classes! /:?] at sun.reflect.GeneratedMethodAccessor119.invoke(Unknown Source) ~[?:?] at Sun. Reflect. DelegatingMethodAccessorImpl. Invoke (43) DelegatingMethodAccessorImpl. Java: ~ [? : 1.8.0 comes with _77] the at Java. Lang. Reflect. Method. Invoke (498) Method. The Java: ~ [? : 1.8.0 comes with _77] the at Org. Springframework. Util. ReflectionUtils. InvokeMethod (ReflectionUtils. Java: 216) ~ [spring - core - 4.3.15. The jar! The at / : 4.3.15. RELEASE] org.springframework.cloud.context.scope.GenericScope$LockedScopedProxyFactoryBean.invoke(GenericScope.java:472) ~ [spring - cloud - context - 1.3.3. The jar! The at / : 1.3.3. RELEASE] org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~ [spring aop -- 4.3.15. RELEASE. The jar! The at / : 4.3.15. RELEASE] org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673) ~ [spring aop -- 4.3.15. RELEASE. The jar! / : 4.3.15. RELEASE] at com. Dianwoda. Delibird. Push. Manager. PushManager? EnhancerBySpringCGLIB? 74851038. Send (< generated >) ~[classes! /:?] at com.dianwoda.delibird.push.provider.DeliPushProviderImpl.lambda$send$0(DeliPushProviderImpl.java:84) ~[classes! / :?] at com.dianwoda.delibird.com mon. Tool. DeliRunnable. Run (DeliRunnable. Java: 26) ~ [delibird - common - 1.0 - the SNAPSHOT. The jar! /:?] at com.dianwoda.delibird.common.traffic.FastCommander.lambda$runnersEnter$0(FastCommander.java:173) ~ [delibird - common - 1.0 - the SNAPSHOT. The jar! / :?] at Java. Util. Concurrent. ThreadPoolExecutor. RunWorker (ThreadPoolExecutor. Java: 1142) [? : 1.8.0 comes with _77] the at Java. Util. Concurrent. ThreadPoolExecutor $Worker. The run (ThreadPoolExecutor. Java: 617) [? : 1.8.0 comes with _77] the at Java. Lang. Thread. The run (Thread. Java: 745) [? : 1.8.0 comes with _77]Copy the codeDoubt point a
Why are logs not printed asynchronously?
By default, Log4j2 tries to place logEvents in RingBuffer first, and if not (presumably because the queue is full) then AsyncQueueFullPolicy (customizable) decides the next action (EventRoute: Discard-discard, synchronous – synchronous, waiting for enqueue), in log4J-2.7 the default is synchronous writing (2.9 the default is waiting for enqueue), so when the log volume increases, the asynchronous log becomes synchronous!
Doubt point 2
Why does the print exception stack block? Where is the blockage?
According to the thread stack, the problem is mainly because org. Apache. Logging. Log4j. Core. The impl. ThrowableProxy. ToExtendedStackTrace this method. The reason for ThrowableProxy class is that LogEvent may be transmitted across the network, and the exception stack in LogEvent may not be identified by the other end. Therefore, the exception stack needs to be repackaged to extract the jar package and version of the exception in the stack. The class is commented as follows:
Wrap a Throwable and add package information for each stack trace element. A proxy used to represent Throwable in different Classloaders or JVMS. When an application deserializes a ThrowableProxy, The Throwable may not be set, but the Throwable information is stored in other fields of the agent, such as message and stack Trace
In addition, this method is used to “resolve all stack entries in this stack trace that differ from the parent element “, In simple terms, the exception stack is compared with the current thread stack, the exception stack is not the same Class information resolution, including the Class name, line number, package name, package version and other information, at this time need to obtain the Class object according to the name of the Class in the exception stack, then need to load the Class. According to the analysis of the class loading process based on the thread stack, it can be seen that the blocking place is waiting for a lock. It is because of the lock waiting that the log printing operation takes 3s.
Here is the thread stack for the blocking thread:
at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
- waiting to lock <0x0000000088104b60> (a java.lang.Object)
at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:94)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:539)
at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:660)
Copy the codeHere is the code snippet for class loading to acquire the lock: code-1
// java.lang.ClassLoader#loadClass(java.lang.String, boolean)
protectedClass<? > loadClass(String name,boolean resolve)
throws ClassNotFoundException
{
synchronized (getClassLoadingLock(name)) { // Line number :404
< span style = "max-width: 100%; clear: both; min-width: 1em;
// First, check if the class has already been loadedClass<? > c = findLoadedClass(name);if (c == null) {
long t0 = System.nanoTime();
try {
// 2. If the class loader has a parent object, the parent loader loads it first
if(parent ! =null) {
c = parent.loadClass(name, false);
} else {
// 3. If the parent loader does not load, use the boot loader to loadc = findBootstrapClassOrNull(name); }}catch (ClassNotFoundException e) {
// ClassNotFoundException thrown if class not found
// from the non-null parent class loader
}
if (c == null) {
// If still not found, then invoke findClass in order
// to find the class.
long t1 = System.nanoTime();
// 4. If none of the previous parents are loaded, use the current custom findClass load
c = findClass(name); // Line number :424
// this is the defining class loader; record the statssun.misc.PerfCounter.getParentDelegationTime().addTime(t1 - t0); sun.misc.PerfCounter.getFindClassTime().addElapsedTimeFrom(t1); sun.misc.PerfCounter.getFindClasses().increment(); }}if (resolve) {
resolveClass(c);
}
returnc; }}Copy the codeAs you can see, when a class is loaded, it checks to see if it has been loaded, and then returns the class object directly from the JVM. If the class is loaded, it should be very fast, because it is only a memory operation, the lock will be released immediately, in the case of thousands of QPS there is no such thing as blocking 3s, so at this time the class has been loaded?
Look at the thread stack where lock 0x0000000088104B60 is obtained:
"fastExecutor-671" #1739 prio=5 os_prio=0 tid=0x00007f2d00015000 nid=0x5e64 runnable [0x00007f2c237f9000] java.lang.Thread.State: RUNNABLE at sun.misc.URLClassPath$Loader.getResource(URLClassPath.java:702) at sun.misc.URLClassPath.getResource(URLClassPath.java:212) at java.net.URLClassLoader$1.run(URLClassLoader.java:365) at java.net.URLClassLoader$1.run(URLClassLoader.java:362) at java.security.AccessController.doPrivileged(Native Method) at java.net.URLClassLoader.findClass(URLClassLoader.java:361) at java.lang.ClassLoader.loadClass(ClassLoader.java:424) - locked <0x0000000088104b60> (a java.lang.Object) at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:94) at java.lang.ClassLoader.loadClass(ClassLoader.java:357) at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:539) ... Cut some things down...Copy the codeAccording to the thread stack above, the class was not loaded in the JVM, and the parent loader was not loaded, so findClass was called to load. If the JVM is loaded once, the next time it will be taken directly from the JVM, the lock will be released immediately without blocking at all. That means you actually reload every time. To find out which class needs to be loaded every time, debug is needed.
Here is the code for the ThrowableProxy class loading process in log4j2: code-2, which is where the class loading is called.
// org.apache.logging.log4j.core.impl.ThrowableProxy#loadClass(java.lang.String)
/**
* Loads classes not located via Reflection.getCallerClass.
*
* @param lastLoader The ClassLoader that loaded the Class that called this Class.
* @param className The name of the Class.
* @return The Class object for the Class or null if it could not be located.
*/
privateClass<? > loadClass(final ClassLoader lastLoader, final String className) {
// XXX:This is a bit of overly complicated.Class<? > clazz;if(lastLoader ! =null) {
try {
// 1. Use the ClassLoader to load the file
clazz = lastLoader.loadClass(className); // Line number: 539
if(clazz ! =null) {
returnclazz; }}catch (final Throwable ignore) {
// Ignore exception.}}try {
// The current thread's ClassLoader is used to load the current thread's ClassLoader.
clazz = LoaderUtil.loadClass(className);
} catch (final ClassNotFoundException | NoClassDefFoundError e) {
// 3. The loading is abnormal. Try another loading method
return loadClass(className);
} catch (final SecurityException e) {
return null;
}
return clazz;
}
// 4. Use the current object class loader to load the object
privateClass<? > loadClass(final String className) {
try {
return this.getClass().getClassLoader().loadClass(className);
} catch (final ClassNotFoundException | NoClassDefFoundError | SecurityException e) {
return null; }}Copy the codeDebugging process
Let the code run and go through the process a few times to make sure that the loaded class has been loaded, In code-2, the lastLoader type is LaunchedURLClassLoader, and the inheritance relationship is shown below
LoadClass method such as: code – 3: org. Springframework.. The boot loader. LaunchedURLClassLoader# loadClass
@Override
protectedClass<? > loadClass(String name,boolean resolve)
throws ClassNotFoundException {
Handler.setUseFastConnectionExceptions(true);
try {
try {
definePackageIfNecessary(name);
}
catch (IllegalArgumentException ex) {
// Tolerate race condition due to being parallel capable
if (getPackage(name) == null) {
// This should never happen as the IllegalArgumentException indicates
// that the package has already been defined and, therefore,
// getPackage(name) should not return null.
throw new AssertionError("Package " + name + " has already been "
+ "defined but it could not be found"); }}return super.loadClass(name, resolve);
}
finally {
Handler.setUseFastConnectionExceptions(false); }}Copy the codeExecute lastLoader.loadClass(className) to jump to code-1. The whole loading process follows the parent delegate mechanism, as shown below
LaunchedURLClassLoader is a custom class loader that calls its parent ClassLoader#loadClass as shown in code-1. LaunchedURLClassLoader is a custom class loader that calls its parent ClassLoader#loadClass as shown in code-1. Finally found that the name of the class when in the sun. Reflect. Through GeneratedMethodAccessor204 parent loaders, the bootstrap loader, URLClassLoader# findClass load is less than, Finally, a ClassNotFoundException is thrown, which is caught and ignored in Step 1 of code-2, followed by step 2 to try loading again, and then an exception is thrown. After catching, a second attempt is made to load at Step 3, and the second exception returns null.
Such as abnormal log at sun. Reflect. GeneratedMethodAccessor119. Invoke (Unknown Source) ~ / 😕 Because the class cannot be loaded, the source information, package information is not available.
Episode: During the debugging process, I restart the application and find that I can no longer go to the previous debugging logic. It seems that everything is normal and there are no classes that cannot be loaded. I am completely confused. Then, by mistake, a script that calls in bulk is used to squelch calls, and the problem reappears
In ready to look at the sun. Reflect. GeneratedMethodAccessor204 why this class loading, not found this class, no one see the name of the class is suspected to be a reflection of the generated classes. With the previous episode, other people’s warnings, and Google’s discovery that the root cause was the JVM’s optimization strategy for reflection.
JVM optimizations for reflection
The JVM treats reflection in two ways:
- Use the native method for reflection operations, which are performed at about the same speed each time
- Generate Bytecodes for reflection operations, that is, generate classes
sun.reflect.GeneratedMethodAccessor<N>, it is a wrapper class for the method called by reflection, proxy different methods, class suffix number will increase. This method is slow for the first call, 3-4 times slower than the first call, but up to 20 times faster after multiple calls
There is a mechanism in the ReflectionFactory to use a second method to speed up a method when the number of times a method is called by reflection exceeds a certain inflationThreshold. The threshold of the default value is 15. The threshold can be through the JVM parameter – Dsun. Reflect the inflationThreshold configured.
So why can’t log4j2 be loaded into the generated classsun.reflect.GeneratedMethodAccessor<N>?
To answer this question we must understand the JVM reflection realization way of the second, the JVM will pass way sun. Reflect. ReflectionFactory# newMethodAccessor build MethodAccessor, The proxy invokes the real method through the object’s Invoke method. The following figure shows the relevant implementation classes for the MethodAccessor interface
ReflectionFactory#newMethodAccessor: code-4
public MethodAccessor newMethodAccessor(Method method) {
checkInitted();
// noInflation uses bytecode enhancement directly
if(noInflation && ! ReflectUtil.isVMAnonymousClass(method.getDeclaringClass())) {return new MethodAccessorGenerator().
generateMethod(method.getDeclaringClass(),
method.getName(),
method.getParameterTypes(),
method.getReturnType(),
method.getExceptionTypes(),
method.getModifiers());
} else {
/ / otherwise use plus expansion mode, create NativeMethodAccessorImpl first, then the implementation as a delegate of DelegatingMethodAccessorImpl, Actually delegate to NativeMethodAccessorImpl
NativeMethodAccessorImpl acc =
new NativeMethodAccessorImpl(method);
DelegatingMethodAccessorImpl res =
new DelegatingMethodAccessorImpl(acc);
acc.setParent(res);
returnres; }}Copy the codeSun. Reflect. NativeMethodAccessorImpl# invoke code is as follows: code – 5
public Object invoke(Object obj, Object[] args)
throws IllegalArgumentException, InvocationTargetException
{
// We can't inflate methods belonging to vm-anonymous classes because
// that kind of class can't be referred to by name, hence can't be
// Found from the generated bytecode.
//
// If the number of calls exceeds the inflationThreshold, it will inflate
if(++numInvocations > ReflectionFactory.inflationThreshold() && ! ReflectUtil.isVMAnonymousClass(method.getDeclaringClass())) { MethodAccessorImpl acc = (MethodAccessorImpl)new MethodAccessorGenerator().
generateMethod(method.getDeclaringClass(),
method.getName(),
method.getParameterTypes(),
method.getReturnType(),
method.getExceptionTypes(),
method.getModifiers());
parent.setDelegate(acc);
}
// If the expansion threshold is not exceeded, use JNI method
return invoke0(method, obj, args);
}
Copy the codeContinue to view the code, can see the sun. Reflect. MethodAccessorGenerator# generate implementation is to call the asm bytecode enhancement tools to generate classes, this process is long, not listed here. At the end of the method, we find an operation called sun.reflect.classDefiner #defineClass. Check its source code
The defineClass code is as follows: code-6
/** We define generated code into a new class loader which delegates to the defining loader of the target class. It is necessary for the VM to be able to resolve references to the target class from the generated bytecodes, which could not occur if the generated code was loaded into the bootstrap class loader.
There are two primary reasons for creating a new loader instead of defining these bytecodes directly into the defining loader of the target class: first, it avoids any possible security risk of having these bytecodes in the same loader. Second, it allows the generated bytecodes to be unloaded earlier than would otherwise be possible, decreasing run-time footprint.
*/
staticClass<? > defineClass(String name,byte[] bytes, int off, int len,
final ClassLoader parentClassLoader)
{
// Create a DelegatingClassLoader to load the generated class
ClassLoader newLoader = AccessController.doPrivileged(
new PrivilegedAction<ClassLoader>() {
public ClassLoader run(a) {
return newDelegatingClassLoader(parentClassLoader); }});return unsafe.defineClass(name, bytes, off, len, newLoader, null);
}
Copy the codeThe generated class is bound to the DelegatingClassLoader, which means that the generated class can only be loaded through the DelegatingClassLoader. However, log4j’s ThrowableProxy#loadClass method does not attempt to load the class loader. So it’s normal that it doesn’t load.
Doubt point three
Why is it blocking, and how is it related to the changes being published?
The JVM optimizes reflection so that dynamically generated classes are never loaded by the classLoader, so classes are loaded every time the exception stack is resolved, and because of the parent delegate and the multiple exception handling of ThrowableProxy#loadClass, The lock is held for a long time and eventually blocks.
The difference can be seen by comparing the exception stack logs with and without the update scope annotation.
Exception stack without @refreshScope annotation:
com.dianwoda.delibird.common.domain.DeliException: at com.dianwoda.delibird.push.manager.PushManager.send(PushManager.java:104) ~[classes/:?] at com.dianwoda.delibird.push.provider.DeliPushProviderImpl.lambda$send$0(DeliPushProviderImpl.java:84) ~[classes/:?] at com.dianwoda.delibird.common.tool.DeliRunnable.run(DeliRunnable.java:26) ~[classes/:?] at com.dianwoda.delibird.common.traffic.FastCommander.lambda$runnersEnter$0(FastCommander.java:174) ~[classes/:?] at Java. Util. Concurrent. ThreadPoolExecutor. RunWorker (ThreadPoolExecutor. Java: 1149) [? : 1.8.0 comes with _161] the at Java. Util. Concurrent. ThreadPoolExecutor $Worker. The run (ThreadPoolExecutor. Java: 624) [? : 1.8.0 comes with _161] the at Java. Lang. Thread. The run (Thread. Java: 748) [? : 1.8.0 comes with _161]Copy the codeException stack annotated with @refreshScope:
com.dianwoda.delibird.common.domain.DeliException: at com.dianwoda.delibird.push.manager.PushManager.send(PushManager.java:104) ~[classes/:?] at sun.reflect.GeneratedMethodAccessor204.invoke(Unknown Source) ~[?:?] at Sun. Reflect. DelegatingMethodAccessorImpl. Invoke (43) DelegatingMethodAccessorImpl. Java: ~ [? : 1.8.0 comes with _161] the at Java. Lang. Reflect. Method. Invoke (498) Method. The Java: ~ [? : 1.8.0 comes with _161] the at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:216) ~ [spring - core - 4.3.15. RELEASE. The jar: 4.3.15. RELEASE] the at org.springframework.cloud.context.scope.GenericScope$LockedScopedProxyFactoryBean.invoke(GenericScope.java:472) ~ [spring - cloud - context - 1.3.3. The jar: 1.3.3. RELEASE] the at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~ [spring aop -- 4.3.15. RELEASE. The jar: 4.3.15. RELEASE] the at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673) ~ [spring aop -- 4.3.15. RELEASE. The jar: 4.3.15. RELEASE] the at com.dianwoda.delibird.push.manager.PushManager?EnhancerBySpringCGLIB?14df0707.send(<generated>) ~[classes/:?] at com.dianwoda.delibird.push.provider.DeliPushProviderImpl.lambda$send$0(DeliPushProviderImpl.java:84) ~[classes/:?] at com.dianwoda.delibird.common.tool.DeliRunnable.run(DeliRunnable.java:26) ~[classes/:?] at com.dianwoda.delibird.common.traffic.FastCommander.lambda$runnersEnter$0(FastCommander.java:174) ~[classes/:?] at Java. Util. Concurrent. ThreadPoolExecutor. RunWorker (ThreadPoolExecutor. Java: 1149) [? : 1.8.0 comes with _161] the at Java. Util. Concurrent. ThreadPoolExecutor $Worker. The run (ThreadPoolExecutor. Java: 624) [? : 1.8.0 comes with _161] the at Java. Lang. Thread. The run (Thread. Java: 748) [? : 1.8.0 comes with _161]Copy the codeThe principle of the @ RefreshScope
This annotation is used in Spring-Cloud to refresh beans after configuration updates. It works as follows:
- RefreshScope is embedded with the @Scope annotation for the Spring Scope mechanism, which divides beans into different types and controls how beans are returned via the BeanFactory.
- through
RefreshScopeThe parent class method ofGenericScope#postProcessBeanFactoryRegister yourself in the beanFactory, and implement the Scope interfaceGenericScope#getMethod, which is put at getStandardScopeCacheIn the cache, it’s actually declaredRefreshScopeBeans are lazily loaded, created and cached for first use. - When calling
RefreshScope#refreshMethod to remove the previous Bean from the cache before executingGenericScope.BeanLifecycleWrapper#destroyMethod completely ends the previous Bean life cycle and then publishes anotherRefreshScopeRefreshedEventEvents. - Raised when a Bean’s method is called because the Bean is proxied
org.springframework.aop.framework.CglibAopProxy.DynamicAdvisedInterceptor#interceptMethod, called in the methodorg.springframework.aop.target.SimpleBeanTargetSource#getTargetGenerate a new bean to put inStandardScopeCache, thus achieving the bean update
Given that the @refreshScope annotated bean is a proxy, it is not difficult to understand why reflection is used and then caused by the JVM’s optimization of reflection
conclusion
There are many reasons for this problem:
- By the looks of it, there’s a
@RefreshScopeannotated - From its own point of view is hit too many exception stack
- From log4j, yes
Log4j 2.7The default processing policy problem after the queue is full - In addition, log4J seems to be an area that needs to be optimized. Dynamically generated classes should be treated specially, choosing the correct class loader, or not loading classes
reference
- Implementation analysis of @RefreshScope and Environment Changes in Spring Cloud
- How does Spring Cloud implement hot updates
- Use asynchronous logging to improve service performance
- Delve into Java class loaders
- how to suppress the generation of DelegatingClassLoader
- Potential memory usage issues with reflection proxy class loaders