Uploaded image for project: 'Confluence Data Center'
  1. Confluence Data Center
  2. CONFSERVER-42808

Audit Log i18n usage causes enable/disable of plugins to takes 5+ seconds and generates warnings

    XMLWordPrintable

Details

    Description

      With the freshly-released 5.10.0, programmatic manipulation of plugin states with PluginController (ie. enable/disable plugins, or enable/disable plugin modules) takes 5+ seconds, which causes log warnings and significant issues for other add-ons that manipulate plugin state. For example, if a plugin needs to manipulate the state of four other modules, this takes 20-40 seconds, which in turn can completely prevent that plugin's OSGi bundle from starting up or shutting down within the allotted time.

      This is a regression from 5.9 and the root cause seems to be the new audit log code. One log symptom is the following:

      2016-06-07 11:00:34,468 WARN [http-nio-8510-exec-32] [confluence.util.profiling.DurationThresholdWarningTimingHelperFactory] logMessage Execution time for publishing event com.atlassian.confluence.event.events.plugin.PluginModuleEnableEvent(confluence.sections.admin:dailybackup) took 8609 ms (warning threshold is 5000 ms)

      The plugin enable/disable itself happens immediately, but the dispatch of the corresponding event after the enable/disable is what takes a long time. (The event is synchronous though, so the calling code still does not get control back until after the event dispatch is complete.)

      I took a few stack traces and it seems that the new Audit Log code in 5.10 (which handles the plugin-related events) is doing some I18n translation to create the audit log messages, and the I18n work causes it to continually open and re-open a whole bunch of JARs for reasons that are unknown to me. (Maybe an I18n cache reset after change in plugin state?)

      I created a very simple plugin which reproduces this behavior when doing repeated plugin module enables/disables of a random module. It runs as a servlet filter, and it invokes itself on the first access to Confluence after installation.

      https://bitbucket.org/sdudley/confluence-5.10-plugin-enable-disable-test/src

      Here, you can see that each manipulation takes 5-10 seconds:

      2016-06-07 11:00:03,720 DEBUG [ThreadPoolAsyncTaskExecutor::Thread 28] [com.arsenalesystems.enabledisabletest.TestBean] <init> TestBean constructor
2016-06-07 11:00:03,722 DEBUG [ThreadPoolAsyncTaskExecutor::Thread 28] [com.arsenalesystems.enabledisabletest.TestBean] afterPropertiesSet Tester Thread in afterPropertiesSet
2016-06-07 11:00:04,708 INFO [UpmAsynchronousTaskManager:thread-4] [com.arsenalesystems.enabledisabletest.TestBean] gotEvent Got PluginModuleEnabledEvent for: bustMyCache
2016-06-07 11:00:04,713 INFO [UpmAsynchronousTaskManager:thread-4] [com.arsenalesystems.enabledisabletest.TestBean] gotEvent Got PluginModuleEnabledEvent for: applicationProperties
2016-06-07 11:00:04,716 INFO [UpmAsynchronousTaskManager:thread-4] [com.arsenalesystems.enabledisabletest.TestBean] gotEvent Got PluginModuleEnabledEvent for: lifecyclefilter
2016-06-07 11:00:04,721 INFO [UpmAsynchronousTaskManager:thread-4] [com.arsenalesystems.enabledisabletest.TestBean] gotEvent Got PluginEnabledEvent for: com.arsenalesystems.plugin-enable-disable-test

2016-06-07 11:00:04,773 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Begin calledFromServletFilter
2016-06-07 11:00:04,774 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Begin disabling plugin module
2016-06-07 11:00:04,776 INFO [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] gotEvent Got PluginModuleDisabledEvent for: dailybackup
2016-06-07 11:00:11,769 WARN [UpmAsynchronousTaskManager:thread-4] [confluence.util.profiling.DurationThresholdWarningTimingHelperFactory] logMessage Execution time for publishing event com.atlassian.confluence.event.events.plugin.PluginInstallEvent(com.arsenalesystems.plugin-enable-disable-test) took 7037 ms (warning threshold is 5000 ms)
 -- url: /rest/plugins/1.0/ | referer: http://localhost:8510/plugins/servlet/upm | traceId: 1bb28576fa2ef69d | userName: admin
2016-06-07 11:00:11,772 WARN [http-nio-8510-exec-32] [confluence.util.profiling.DurationThresholdWarningTimingHelperFactory] logMessage Execution time for publishing event com.atlassian.confluence.event.events.plugin.PluginModuleDisableEvent(confluence.sections.admin:dailybackup) took 6993 ms (warning threshold is 5000 ms)
 -- referer: http://localhost:8510/plugins/servlet/upm | url: /rest/plugins/1.0/pending/d2b0adc0-c0a8-40c2-bfaf-56382a78b016 | traceId: e2879392d4b130df | userName: admin
2016-06-07 11:00:11,773 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Done disabling plugin module: elapsed time = 6999
2016-06-07 11:00:11,774 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Begin enabling plugin module
2016-06-07 11:00:11,777 INFO [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] gotEvent Got PluginModuleEnabledEvent for: dailybackup
2016-06-07 11:00:18,654 WARN [http-nio-8510-exec-32] [confluence.util.profiling.DurationThresholdWarningTimingHelperFactory] logMessage Execution time for publishing event com.atlassian.confluence.event.events.plugin.PluginModuleEnableEvent(confluence.sections.admin:dailybackup) took 6872 ms (warning threshold is 5000 ms)
 -- referer: http://localhost:8510/plugins/servlet/upm | url: /rest/plugins/1.0/pending/d2b0adc0-c0a8-40c2-bfaf-56382a78b016 | traceId: e2879392d4b130df | userName: admin
2016-06-07 11:00:18,657 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Done enabling plugin module: elapsed time = 6883
2016-06-07 11:00:18,658 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Begin disabling plugin module
2016-06-07 11:00:18,660 INFO [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] gotEvent Got PluginModuleDisabledEvent for: dailybackup
2016-06-07 11:00:25,848 WARN [http-nio-8510-exec-32] [confluence.util.profiling.DurationThresholdWarningTimingHelperFactory] logMessage Execution time for publishing event com.atlassian.confluence.event.events.plugin.PluginModuleDisableEvent(confluence.sections.admin:dailybackup) took 7186 ms (warning threshold is 5000 ms)
 -- referer: http://localhost:8510/plugins/servlet/upm | url: /rest/plugins/1.0/pending/d2b0adc0-c0a8-40c2-bfaf-56382a78b016 | traceId: e2879392d4b130df | userName: admin
2016-06-07 11:00:25,850 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Done disabling plugin module: elapsed time = 7192
2016-06-07 11:00:25,851 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Begin enabling plugin module
2016-06-07 11:00:25,854 INFO [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] gotEvent Got PluginModuleEnabledEvent for: dailybackup
2016-06-07 11:00:34,468 WARN [http-nio-8510-exec-32] [confluence.util.profiling.DurationThresholdWarningTimingHelperFactory] logMessage Execution time for publishing event com.atlassian.confluence.event.events.plugin.PluginModuleEnableEvent(confluence.sections.admin:dailybackup) took 8609 ms (warning threshold is 5000 ms)
 -- referer: http://localhost:8510/plugins/servlet/upm | url: /rest/plugins/1.0/pending/d2b0adc0-c0a8-40c2-bfaf-56382a78b016 | traceId: e2879392d4b130df | userName: admin
2016-06-07 11:00:34,470 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Done enabling plugin module: elapsed time = 8619
2016-06-07 11:00:34,471 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Begin disabling plugin module
2016-06-07 11:00:34,473 INFO [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] gotEvent Got PluginModuleDisabledEvent for: dailybackup
2016-06-07 11:00:38,462 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Done disabling plugin module: elapsed time = 3991
2016-06-07 11:00:38,462 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Begin enabling plugin module
2016-06-07 11:00:38,464 INFO [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] gotEvent Got PluginModuleEnabledEvent for: dailybackup
2016-06-07 11:00:42,513 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter Done enabling plugin module: elapsed time = 4051
2016-06-07 11:00:42,514 DEBUG [http-nio-8510-exec-32] [com.arsenalesystems.enabledisabletest.TestBean] calledFromServletFilter End calledFromServletFilter

      Attachments

        Activity

          People

            onevalainen Olli Nevalainen
            7c60ab039b09 Scott Dudley [Inactive]
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: