Проблема высокого параллелизма с log4j2

задняя часть JVM Spring Apache

Apache_Log4j_Logo

Оригинальная ссылка:Блог. Отправить две бутылки. Com / Ah-High-Con Color ...

предисловие

Журналы должны быть основными компонентами приложения, среди которых старый log4j должен быть тем, который мы используем больше всего.Позже, с развитием Интернета, все перешли к высокому параллелизму и обнаружили, что производительность log4j не очень хорошая, потому что конкурирующие блокировки приводят к блокировке, и производительность не может поддерживаться. Вверх. Позже, после того, как его основатель установил отдельный журнал журнала портала, новый главный Apache log4j претерпел серьезное обновление и преобразование, которое является сегодняшним log4j2, и его производительность асинхронного журнала также не имеет себе равных,но ям в его использовании все равно много.Если не обращать внимания,сделаешь личную очередь.Перечислим некоторые ямки log4j,на которые наступили другие:

описание проблемы

основная производительность

Служба push-уведомлений APP, после выпуска, при встрече с пакетными push-задачами, пул потоков заполнен, очередь заполнена, а задачи накапливаются (Примечание: поскольку изменения в этом выпуске очень распространены, я не подозревал этот пункт в первую очередь)

Связанные среды

  • spring-boot: 1.5.3
  • log4j: 2.7
  • jdk1.8

Разместить точки изменения

  • Добавлена ​​функция (не относящаяся к данному контенту)
  • добавлен в класс@RefreshScopeаннотация

Технологический поток

  1. Первоначально оно вызвано сторонним интерфейсом. Мониторинг показывает, что дисплей действительно высок, но это не проблема интерфейса с Ping, Curl и мониторингом сети.
  2. Прочтите код и обнаружите, что элемент мониторинга включает в себя не только трудоемкий вызов стороннего интерфейса, но и другие операции, поэтому я считаю, что мониторинг не заслуживает доверия, а проверка не является сторонним интерфейсом или проблема с сетью.
  3. Выяснено, что разница между двумя временными точками в статистическом журнале относительно велика и составляет три секунды.Ключ в том, что между этими двумя временными точками было выбрано только исключение, а затем был записан журнал.
  4. В коде обнаружено, что конфигурация log4j2 использует синхронный Logger и асинхронный AsyncAppender, есть подозрение, что синхронный лог блокируется во время high concurrency, лог меняется на AsyncLogger с дисраптором, но результат бесполезен.
  5. Выполните дамп потока, чтобы обнаружить, что многие потоки заблокированы, отображение стека вызовов действительно связано с log4j и явно указывает на печать стека исключений.
  6. Так как предупреждений в приложении много, и эти логи все выводят стек исключений, так что перестаньте печатать ненужный стек исключений в лог, и тогда проблема решится

анализ проблемы

вопрос о вопросе

  1. Почему журнал не печатается асинхронно?
  2. Почему блокируется печать стека исключений?Где блок?
  3. Почему это вызывает блокировку и как это связано с опубликованной точкой изменения?

Анализ стека потоков

Следующий журнал представляет собой блокирующий стек потока после перехода на асинхронный журнал (AsyncLogger).Можно обнаружить, что журнал не использует безблокировочную библиотеку разрушителя, а преобразуется в синхронный Logger.

"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)
        ... 精简部分日志 ...
        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)

Ниже приведено содержимое стека исключений приложения.

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(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_77]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_77]
        at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:216) ~[spring-core-4.3.15.RELEASE.jar!/:4.3.15.RELEASE]
        at org.springframework.cloud.context.scope.GenericScope$LockedScopedProxyFactoryBean.invoke(GenericScope.java:472) ~[spring-cloud-context-1.3.3.RELEASE.jar!/:1.3.3.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.15.RELEASE.jar!/:4.3.15.RELEASE]
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673) ~[spring-aop-4.3.15.RELEASE.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.common.tool.DeliRunnable.run(DeliRunnable.java:26) ~[delibird-common-1.0-SNAPSHOT.jar!/:?]
        at com.dianwoda.delibird.common.traffic.FastCommander.lambda$runnersEnter$0(FastCommander.java:173) ~[delibird-common-1.0-SNAPSHOT.jar!/:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_77]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_77]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_77]

Вопрос один

Почему журнал не печатается асинхронно?

По умолчанию Log4j2 сначала попытается поместить LogEvent в RingBuffer, если это невозможно (причина, вероятно, в том, что очередь заполнена), решение о следующем действии будет принято через AsyncQueueFullPolicy (настраиваемый) (EventRoute: discard-discard, sync -синхронный, ожидание постановки в очередь — поставить в очередь), в log4j-2.7 по умолчанию запись в лог выполняется синхронно (по умолчанию в 2.9 ожидание постановки в очередь), поэтому, когда объем лога внезапно увеличивается, асинхронный лог становится синхронным журналом!

Вопрос второй

Почему блокируется печать стека исключений?Где блок?

Согласно стеку потоков, проблема в основном потому, чтоorg.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTraceэтот метод, гдеThrowableProxyЭтот класс связан с тем, что LogEvent может передаваться по сети, а стек исключений в LogEvent может быть не распознан другим концом, поэтому стек исключений необходимо переупаковать, а пакет jar исключений и информация о версии в стеке будут удалить. Класс аннотируется следующим образом:

Упаковка метательного объекта и добавление информации о пакете для каждого элемента отслеживания стека.
Используется для указания агента в другом ClassLoader Throwable или JVM при применении десериализации ThrowableProxy, Throwable может не предоставляться, но информация Throwable хранится в других полях агента, таких как сообщение и трассировка стека.

Кроме того, этот метод предназначен для «анализа всех записей стека в этой трассировке стека, которые отличаются от родительского элемента». Короче говоря, он сравнивает стек исключений со стеком текущего потока и анализирует различную информацию о классах в стеке исключений. , включая имя класса, номер строки, имя пакета, версию пакета и другую информацию.В настоящее время вам необходимо получить объект класса в соответствии с именем класса в стеке исключений, и вам необходимо загрузить класс.Проанализируйте загрузку класса процесс согласно стеку потоков, вы можете увидеть заблокированное место ожидания блокировки, именно из-за ожидания блокировки операция печати журнала занимает 3 с.

Ниже приведен стек заблокированного потока:

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)

Ниже приведен фрагмент кода для загрузки класса для получения блокировки:code-1

// java.lang.ClassLoader#loadClass(java.lang.String, boolean)
protected Class<?> loadClass(String name, boolean resolve)
        throws ClassNotFoundException
    {
        synchronized (getClassLoadingLock(name)) { // 源码行号:404
            //(1. 注: 先从jvm检查下类加载过没有,已加载就直接返回该对象,防止类重复加载)
            // First, check if the class has already been loaded
            Class<?> c = findLoadedClass(name);
            if (c == null) {
                long t0 = System.nanoTime();
                try {
                    // 2. 如果该类加载器有父对象,先用父加载器加载,这就是双亲委派机制
                    if (parent != null) {
                        c = parent.loadClass(name, false);
                    } else {
                        // 3. 如果父加载器加载不到,就用引导加载器加载
                        c = 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. 如果前面双亲都没有加载到, 采用当前自定义的findClass加载
                    c = findClass(name); // 源码行号:424

                    // this is the defining class loader; record the stats
                    sun.misc.PerfCounter.getParentDelegationTime().addTime(t1 - t0);
                    sun.misc.PerfCounter.getFindClassTime().addElapsedTimeFrom(t1);
                    sun.misc.PerfCounter.getFindClasses().increment();
                }
            }
            if (resolve) {
                resolveClass(c);
            }
            return c;
        }
    }

Видно, что когда класс загружен, он сначала проверит, был ли он загружен, а затем сразу вернет объект класса в jvm после загрузки.Если он должен получить загруженный класс, он должен быть очень быстрым, потому что это только операция с памятью, полученная блокировка будет снята сразу.В случае тысяч QPS блокировка на 3 секунды невозможна.Так класс в это время был загружен?

Вы можете увидеть, чтобы получить замок0x0000000088104b60Стек нитки:

"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)
        ... 精简部分内容 ...

В соответствии с приведенным выше стеком потоков, после получения блокировки, перейти к строке 424 исходного кода, что означает, что класс не был загружен в jvm, и родительский загрузчик не может быть загружен, поэтому вызовитеfindClassПерейти к загрузке.Это очень странно.Если jvm загрузится один раз, то в следующий раз она будет получена напрямую из jvm.В сочетании с блокировкой, упомянутой выше, она будет разблокирована сразу, и она не будет блокироваться вообще.То есть чтобы сказать, что его действительно нужно перезагружать каждый раз, чтобы узнать, какой класс нужно загружать каждый раз, необходимо отладить, чтобы определить.

Ниже log4j2ThrowableProxyКод процесса загрузки класса:code-2, где вызывается загрузка класса.

   // 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.
     */
    private Class<?> loadClass(final ClassLoader lastLoader, final String className) {
        // XXX: this is overly complicated (注:确实过于复杂,哈哈哈)
        Class<?> clazz;
        if (lastLoader != null) {
            try {
                // 1. 先用ClassLoader加载一下, 加载上就返回
                clazz = lastLoader.loadClass(className); // 源码行号: 539
                if (clazz != null) {
                    return clazz;
                }
            } catch (final Throwable ignore) {
                // Ignore exception.
            }
        }
        try {
            // 2. 上一步没加载上,或者出现异常,用LoaderUtil再次加载(使用Class.forName以及当前线程的ClassLoader)
            clazz = LoaderUtil.loadClass(className);
        } catch (final ClassNotFoundException | NoClassDefFoundError e) {
            // 3. 加载出现异常,再次尝试一种加载方式
            return loadClass(className);
        } catch (final SecurityException e) {
            return null;
        }
        return clazz;
    }
    // 4. 接上面的3, 再次用当前对象类的加载器加载,出现异常返回空
    private Class<?> loadClass(final String className) {
        try {
            return this.getClass().getClassLoader().loadClass(className);
        } catch (final ClassNotFoundException | NoClassDefFoundError | SecurityException e) {
            return null;
        }
    }

процесс отладки

Пусть код выполняется первым и пройдите проблемный процесс несколько раз, чтобы гарантировать, что загруженный класс загружен, а затемcode-1серединаfindLoadedClassточку останова в методе и посмотрите, пусто ли возвращаемое значение.code-2серединаlastLoaderТипLaunchedURLClassLoaderОтношения наследования следующие

LaunchedURLClassLoader

loadClassТакие методы, как:code-3 : org.springframework.boot.loader.LaunchedURLClassLoader#loadClass

@Override
protected Class<?> 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);
    }
}

воплощать в жизньlastLoader.loadClass(className)Прыжокcode-1, весь процесс загрузки следует за механизмом родительской делегирования, как показано ниже

java_classloader_hierarchy

LaunchedURLClassLoader — это настраиваемый загрузчик классов, который напрямую вызывает родительский класс.ClassLoader#loadClassкоторыйcode-1Как показано в , используйте «загрузчик класса приложения», «загрузчик класса расширения», «загрузчик класса загрузки» для загрузки и, наконец, обнаружил, что при появлении имени классаsun.reflect.GeneratedMethodAccessor204После родительских загрузчиков загрузчик начальной загрузки, URLClassLoader#findClass не может быть загружен и, наконец, брошенClassNotFoundExceptionодеялоcode-2Захватите и проигнорируйте шаг 1, затем перейдите к шагу 2, пытаясь загрузить, затем выдается исключение, после попытки захвата снова загрузиться на шаге 3, ненормальный снова возвращается пустым.

такие как журнал исключенияat sun.reflect.GeneratedMethodAccessor119.invoke(Unknown Source) ~[?:?], так как класс не может быть загружен, информация об исходном коде и информация о пакете недоступны.

эпизод:В процессе отладки я перезапустил приложение и обнаружил, что прежняя логика отладки больше не может быть достигнута, вроде бы все нормально, и нет классов, которые нельзя было бы загрузить. Затем по ошибке я использовал скрипт пакетного вызова для его вызова, а затем проблема снова появилась

готовится увидетьsun.reflect.GeneratedMethodAccessor204Почему этот класс не может быть загружен, я обнаружил, что такого класса вообще нет, и я подозреваю, что это класс, сгенерированный отражением, когда я смотрю на имя класса. В дополнение к предыдущему эпизоду, помимо чужих напоминаний и гугления, было установлено, что первопричиной на самом деле была стратегия оптимизации JVM для отражения.

JVM оптимизация отражения

Есть два способа обращения с JVM для отражения:

  1. Используйте нативный метод для операций отражения, скорость которого каждый раз примерно одинакова.
  2. Сгенерировать байт-код для операции отражения, то есть сгенерировать классsun.reflect.GeneratedMethodAccessor<N>, который является классом-оболочкой для метода, вызываемого отражением, проксирующим разные методы, и номер суффикса класса будет увеличиваться. Этот метод медленнее при первом вызове, в 3-4 раза медленнее первого метода, но скорость будет увеличена в 20 раз после многократного вызова

существуетReflectionFactoryЕсть механизм, то есть, когда количество вызовов метода отражением превышает определенный порог (inflationThreshold), для повышения скорости будет использоваться второй метод. Значение этого порога по умолчанию равно 15. Порог можно передать через параметр jvm.-Dsun.reflect.inflationThresholdнастроить.

Так почему же log4j2 не может быть загружен в сгенерированный класс?sun.reflect.GeneratedMethodAccessor<N>Шерстяная ткань?

Чтобы ответить на этот вопрос, нам нужно понять второй способ реализации отражения jvm, jvm будет передавать методsun.reflect.ReflectionFactory#newMethodAccessorСоздайте MethodAccessor, и прокси-сервер вызовет реальный метод через метод вызова объекта. На следующем рисунке показан соответствующий класс реализации интерфейса MethodAccessor.

MethodAccessor接口的相关实现类

ReflectionFactory#newMethodAccessorкод показывает, как показано ниже:code-4

   public MethodAccessor newMethodAccessor(Method method) {
        checkInitted();
        // noInflation(不膨胀)，直接使用字节码增强方式
        if (noInflation && !ReflectUtil.isVMAnonymousClass(method.getDeclaringClass())) {
            return new MethodAccessorGenerator().
                generateMethod(method.getDeclaringClass(),
                               method.getName(),
                               method.getParameterTypes(),
                               method.getReturnType(),
                               method.getExceptionTypes(),
                               method.getModifiers());
        } else {
            // 否则使用Inflation膨胀模式， 先创建NativeMethodAccessorImpl，随后将该实现作为DelegatingMethodAccessorImpl的一个delegate，实际上还是委派给NativeMethodAccessorImpl
            NativeMethodAccessorImpl acc =
                new NativeMethodAccessorImpl(method);
            DelegatingMethodAccessorImpl res =
                new DelegatingMethodAccessorImpl(acc);
            acc.setParent(res);
            return res;
        }
}

sun.reflect.NativeMethodAccessorImpl#invokeкод показывает, как показано ниже: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.(我们不能膨胀属于vm-anonymous的类，因为这种类不能通过名字引用，因此不能从生成的字节码中被发现)
        //
        // 这里可以看到，如果调用次数大于inflationThreshold就会膨胀，使用字节码增强的方式
        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);
        }
        // 没有超过膨胀阈值，就使用JNI方法
        return invoke0(method, obj, args);
}

Продолжайте смотреть на код, вы можете увидетьsun.reflect.MethodAccessorGenerator#generateРеализация заключается в вызове инструмента расширения байт-кода asm для создания класса, что является длительным процессом и здесь не приводится. В конце метода находим, что есть такая операцияsun.reflect.ClassDefiner#defineClass, просмотреть его исходный код

Код defineClass выглядит следующим образом:code-6

/** <P> 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. </P>
      <P> 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. </P>
    */
    static Class<?> defineClass(String name, byte[] bytes, int off, int len,
                                final ClassLoader parentClassLoader)
    {
        // 创建一个DelegatingClassLoader用来加载生成的类
        ClassLoader newLoader = AccessController.doPrivileged(
            new PrivilegedAction<ClassLoader>() {
                public ClassLoader run() {
                        return new DelegatingClassLoader(parentClassLoader);
                    }
                });
        return unsafe.defineClass(name, bytes, off, len, newLoader, null);
}

С помощью приведенного выше кода и комментариев обнаружено, что сгенерированный класс связан вDelegatingClassLoaderНа этом загрузчике могут быть загружены только классы, сгенерированные этим загрузчиком,Однако в log4jThrowableProxy#loadClassметод не пытается использовать загрузчик классов, так что это нормально, что он не может быть загружен.

Вопрос третий

Почему это вызывает блокировку и как это связано с опубликованной точкой изменения?

На этом этапе анализа причина блокировки ясна, потому что jvm оптимизирует отражение, так что динамически сгенерированные классы не всегда могут быть загружены через classLoader, поэтому каждый раз, когда анализируется стек исключений, загрузка классов будет выполнено, и из-за родительского делегирования иThrowableProxy#loadClassОбработка множественных исключений, вызванная временем удержания блокировки, очень длительна, что в конечном итоге приводит к блокировке.

Что касается точки смены релиза, то добавлено@RefreshScopeАннотация, при сравнении лога стека исключений с добавлением и без, разница тоже найдена.

нет добавления@RefreshScopeАннотированная степень исключения:

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_161]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_161]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]

добавлять@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(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_161]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_161]
    at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:216) ~[spring-core-4.3.15.RELEASE.jar:4.3.15.RELEASE]
    at org.springframework.cloud.context.scope.GenericScope$LockedScopedProxyFactoryBean.invoke(GenericScope.java:472) ~[spring-cloud-context-1.3.3.RELEASE.jar:1.3.3.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.15.RELEASE.jar:4.3.15.RELEASE]
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673) ~[spring-aop-4.3.15.RELEASE.jar:4.3.15.RELEASE]
    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_161]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_161]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]

Принцип @RefreshScope

Эта аннотация используется в spring-cloud для обновления bean-компонентов после обновления конфигурации по следующему принципу:

  • Аннотация @Scope встроена в @RefreshScope, который используется для механизма Spring Scope, предназначенного для разделения компонентов на разные типы и управления возвратом компонентов через BeanFactory.
  • пройти черезRefreshScopeМетод родительского классаGenericScope#postProcessBeanFactoryЗарегистрируйтесь в beanFactory и реализуйте интерфейс Scope.GenericScope#getметод, который будет помещен в getStandardScopeCacheВ кеше он фактически объявляетRefreshScopeВсе компоненты лениво загружаются, создаются и кэшируются при первом использовании.
  • при звонкеRefreshScope#refreshметод, удалите предыдущий компонент из кеша перед выполнениемGenericScope.BeanLifecycleWrapper#destroyBean-метод полного завершения жизненного цикла перед публикациейRefreshScopeRefreshedEventсобытие.
  • Когда вызывается метод компонента, поскольку компонент является прокси-сервером, он вызываетorg.springframework.aop.framework.CglibAopProxy.DynamicAdvisedInterceptor#interceptметод, метод вызоветorg.springframework.aop.target.SimpleBeanTargetSource#getTargetРегенерировать bean-компонент вStandardScopeCache, тем самым реализуя обновление bean-компонента

Из приведенного принципа видно, что бин с аннотацией @RefreshScope является прокси.Не сложно понять, почему используется рефлексия, а тут проблема возникает из-за оптимизации рефлексии jvm

Суммировать

На самом деле причин этой проблемы много:

  1. На поверхности кажется, что@RefreshScopeвызвано аннотацией
  2. С его собственной точки зрения, он столкнулся со слишком большим количеством стеков исключений.
  3. Из log4j этоlog4j 2.7Стратегия обработки по умолчанию после заполнения очереди
  4. Кроме того, для log4j, похоже, это действительно место, которое необходимо оптимизировать, для динамически генерируемых классов необходимо выполнить специальную обработку и выбрать правильный загрузчик классов, либо не выполнять загрузку классов.

Ссылаться на

Категории