[JRASERVER-67614] JMX Monitoring may take a long time to load during Jira Startup

Type: Bug
Resolution: Unresolved
Priority: Low (View bug fix roadmap)
Fix Version/s: None
Affects Version/s: 7.6.0, 7.6.6, 7.11.0
Component/s: System Administration - Others
Labels:
- pse-request

Introduced in Version:
7.06
Support reference count:
5
Symptom Severity:
Severity 3 - Minor
UIS:
0
Bug Fix Policy:
View Atlassian Server bug fix policy

Problem

JMX Monitoring is slow due to license count and delays startup.

Related: ~~JRASERVER-64384~~ - license count slow
Can Cause: ~~JRASERVER-67613~~ - lock check failures

Diagnosis

In a large instance with many users and groups, JMX startup may be slow.

Application Logs

Logs may have noticeable delays like:

2018-07-13 17:55:09,844 localhost-startStop-1 INFO [c.a.j.instrumentation.external.DatabaseExternalGauges] Installing DBCP monitoring instruments: DatabaseExternalGauges.JiraDbcpInstruments[instruments=[DBCP_MAX, DBCP_ACTIVE, DBCP_IDLE],objectName=com.atlassian.jira:name=BasicDataSource]

2018-07-13 17:55:38,300 localhost-startStop-1 WARN      [c.a.jira.health.HealthChecks] Your database is using an unsupported collation

Note this 20s delay, generally this is expected to occur within a few seconds.

Thread Dumps

When taking frequent thread dumps, in this case with 2s intervals, we see this long-running thread:

"localhost-startStop-1" #29 daemon prio=5 os_prio=0 tid=0x00007f36a0001800 nid=0x4227 runnable [0x00007f3701afe000]
   java.lang.Thread.State: RUNNABLE
	at org.ofbiz.core.entity.model.ModelFieldTypeReader.getModelFieldType(ModelFieldTypeReader.java:195)
	at org.ofbiz.core.entity.jdbc.SqlJdbcUtil.getValue(SqlJdbcUtil.java:596)
	at org.ofbiz.core.entity.EntityListIterator.currentGenericValue(EntityListIterator.java:181)
	at org.ofbiz.core.entity.EntityListIterator.next(EntityListIterator.java:267)
	at com.atlassian.jira.ofbiz.DefaultOfBizListIterator.next(DefaultOfBizListIterator.java:100)
	at com.atlassian.jira.ofbiz.WrappingOfBizListIterator.next(WrappingOfBizListIterator.java:68)
	at com.atlassian.jira.crowd.embedded.ofbiz.OfBizUserDao.processUsers(OfBizUserDao.java:960)
	at com.atlassian.jira.crowd.embedded.ofbiz.DelegatingUserDao.processUsers(DelegatingUserDao.java:53)
	at com.atlassian.jira.crowd.embedded.ofbiz.IndexedUserDao.processUsers(IndexedUserDao.java:63)
	at com.atlassian.jira.crowd.embedded.ofbiz.DelegatingUserDao.processUsers(DelegatingUserDao.java:53)
	at com.atlassian.jira.crowd.embedded.ofbiz.SwitchingUserDao.processUsers(SwitchingUserDao.java:30)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.lambda$readUsersInGroupsExcluding$23(DefaultApplicationRoleManager.java:1077)
	at com.atlassian.jira.application.DefaultApplicationRoleManager$$Lambda$800/1668537103.accept(Unknown Source)
	at com.atlassian.jira.crowd.embedded.ofbiz.db.DefaultOfBizTransaction.lambda$withTransaction$0(DefaultOfBizTransaction.java:44)
	at com.atlassian.jira.crowd.embedded.ofbiz.db.DefaultOfBizTransaction$$Lambda$801/1417043076.apply(Unknown Source)
	at com.atlassian.jira.crowd.embedded.ofbiz.db.DefaultOfBizTransaction.withTransaction(DefaultOfBizTransaction.java:28)
	at com.atlassian.jira.crowd.embedded.ofbiz.db.DefaultOfBizTransaction.withTransaction(DefaultOfBizTransaction.java:42)
	at com.atlassian.jira.crowd.embedded.ofbiz.db.DefaultOfBizTransactionManager.withTransaction(DefaultOfBizTransactionManager.java:9)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.readUsersInGroupsExcluding(DefaultApplicationRoleManager.java:1076)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.readUsersInGroups(DefaultApplicationRoleManager.java:1048)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.countUsersInGroups(DefaultApplicationRoleManager.java:1100)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.countApplicationRoleUsers(DefaultApplicationRoleManager.java:955)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.countApplicationUsers(DefaultApplicationRoleManager.java:938)
	at com.atlassian.jira.application.DefaultApplicationRoleManager$$Lambda$796/449395834.apply(Unknown Source)
	at com.atlassian.fugue.Option.map(Option.java:272)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.lambda$new$1(DefaultApplicationRoleManager.java:197)
	at com.atlassian.jira.application.DefaultApplicationRoleManager$$Lambda$189/365645537.load(Unknown Source)
	at com.atlassian.cache.ehcache.LoadingCache.getFromLoader(LoadingCache.java:145)
	at com.atlassian.cache.ehcache.LoadingCache.loadValueAndReleaseLock(LoadingCache.java:100)
	at com.atlassian.cache.ehcache.LoadingCache.get(LoadingCache.java:76)
	at com.atlassian.cache.ehcache.DelegatingCache.get(DelegatingCache.java:99)
	at com.atlassian.jira.cache.DeferredReplicationCache.get(DeferredReplicationCache.java:48)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.lambda$getUserCountCurrentValue$16(DefaultApplicationRoleManager.java:583)
	at com.atlassian.jira.application.DefaultApplicationRoleManager$$Lambda$795/1812474572.apply(Unknown Source)
	at com.atlassian.fugue.Option$Some.fold(Option.java:421)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.getUserCountCurrentValue(DefaultApplicationRoleManager.java:581)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.getUserCount(DefaultApplicationRoleManager.java:574)
	at com.atlassian.jira.instrumentation.external.InternalStatisticsExternalGauges$1.lambda$new$1(InternalStatisticsExternalGauges.java:96)
	at com.atlassian.jira.instrumentation.external.InternalStatisticsExternalGauges$1$$Lambda$769/1512596918.get(Unknown Source)
	at com.atlassian.jira.monitoring.jmx.InstrumentationMetricsCollector.lambda$null$1(InstrumentationMetricsCollector.java:87)
	at com.atlassian.jira.monitoring.jmx.InstrumentationMetricsCollector$$Lambda$784/1964062498.get(Unknown Source)
	at com.atlassian.jira.monitoring.jmx.bean.DynamicJmxValue.lambda$getMBeanInfo$0(DynamicJmxValue.java:60)
	at com.atlassian.jira.monitoring.jmx.bean.DynamicJmxValue$$Lambda$785/55309983.apply(Unknown Source)
	...
	at com.atlassian.jira.monitoring.jmx.bean.DynamicJmxValue.getMBeanInfo(DynamicJmxValue.java:66)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getNewMBeanClassName(DefaultMBeanServerInterceptor.java:333)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:319)
	at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
	at com.atlassian.jira.monitoring.jmx.JmxMetricsExposerImpl.register(JmxMetricsExposerImpl.java:56)
	at com.atlassian.jira.monitoring.jmx.JmxMetricsExposerImpl.startExposing(JmxMetricsExposerImpl.java:83)
	- locked <0x00000001cb97e198> (a java.lang.Object)
	at com.atlassian.jira.monitoring.jmx.JmxMetricsExposerImpl.refreshState(JmxMetricsExposerImpl.java:123)
	at com.atlassian.jira.monitoring.jmx.JmxMetricsExposerImpl.init(JmxMetricsExposerImpl.java:113)
	at com.atlassian.jira.instrumentation.Instrumentation.start(Instrumentation.java:168)
	at com.atlassian.jira.ComponentManager.runStartable(ComponentManager.java:312)
	at com.atlassian.jira.ComponentManager.quickStart(ComponentManager.java:225)
	at com.atlassian.jira.ComponentManager.start(ComponentManager.java:165)
	- locked <0x00000001c039d2d8> (a com.atlassian.jira.ComponentManager)
	at com.atlassian.jira.upgrade.PluginSystemLauncher.start(PluginSystemLauncher.java:47)
	at com.atlassian.jira.startup.DefaultJiraLauncher.lambda$postDbLaunch$2(DefaultJiraLauncher.java:154)
	at com.atlassian.jira.startup.DefaultJiraLauncher$$Lambda$80/1981519697.run(Unknown Source)
	at com.atlassian.jira.config.database.DatabaseConfigurationManagerImpl.doNowOrEnqueue(DatabaseConfigurationManagerImpl.java:304)
	at com.atlassian.jira.config.database.DatabaseConfigurationManagerImpl.doNowOrWhenDatabaseActivated(DatabaseConfigurationManagerImpl.java:199)
	at com.atlassian.jira.startup.DefaultJiraLauncher.postDbLaunch(DefaultJiraLauncher.java:146)
	at com.atlassian.jira.startup.DefaultJiraLauncher.lambda$start$0(DefaultJiraLauncher.java:105)
	at com.atlassian.jira.startup.DefaultJiraLauncher$$Lambda$28/2068762689.run(Unknown Source)
	at com.atlassian.jira.util.devspeed.JiraDevSpeedTimer.run(JiraDevSpeedTimer.java:31)
	at com.atlassian.jira.startup.DefaultJiraLauncher.start(DefaultJiraLauncher.java:103)
	at com.atlassian.jira.startup.LauncherContextListener.initSlowStuff(LauncherContextListener.java:157)
	at com.atlassian.jira.startup.LauncherContextListener.initSlowStuffInBackground(LauncherContextListener.java:142)
	at com.atlassian.jira.startup.LauncherContextListener.contextInitialized(LauncherContextListener.java:104)
	at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4727)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5189)

Notice that during startup, the JMX monitoring is loaded, which then spends time getting users for license count.

	at com.atlassian.jira.application.DefaultApplicationRoleManager.readUsersInGroups(DefaultApplicationRoleManager.java:1048)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.countUsersInGroups(DefaultApplicationRoleManager.java:1100)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.countApplicationRoleUsers(DefaultApplicationRoleManager.java:955)
	at com.atlassian.jira.application.DefaultApplicationRoleManager.countApplicationUsers(DefaultApplicationRoleManager.java:938)

Workaround

Disable JMX Monitoring before restarting Jira.

causes

JRASERVER-67613 Race Condition with Jira Startup Consistency Checker Can Result in File Lock Errors

Closed

is related to

JRASERVER-67466 Expose Jira and performance metrics through JMX (part1)

Closed

relates to

JRASERVER-64384 ActiveUsersCountForLicense cache is populated inefficiently leading to performance degradation across the application

Closed

mentioned in: Page Failed to load

Form Name

Rinish made changes - 30/Sep/2022 8:43 AM

Remote Link

New: This issue links to "Page (Confluence)" [ 689486 ]

SET Analytics Bot made changes - 09/Apr/2022 4:05 AM

Support reference count

Original: 4

New: 5

SET Analytics Bot made changes - 12/Feb/2021 1:30 AM

UIS

Original: 1

New: 0

Bugfix Automation Bot made changes - 01/Nov/2019 10:00 AM

Support reference count

Original: 3

New: 4

Mateusz Walas (Inactive) made changes - 29/Jul/2019 11:38 AM

Status

Original: Needs Triage [ 10030 ]

New: Gathering Impact [ 12072 ]

Mateusz Walas (Inactive) made changes - 29/Jul/2019 11:38 AM

Occurrence Factor

New: 10% [ 12830 ]

Bugfix Automation Bot made changes - 06/Jun/2019 10:01 PM

Support reference count

Original: 2

New: 3

Bugfix Automation Bot made changes - 28/Mar/2019 12:25 AM

Minimum Version

New: 7.06

Bugfix Automation Bot made changes - 28/Feb/2019 9:31 AM

Support reference count

Original: 3

New: 2

Bugfix Automation Bot made changes - 27/Feb/2019 10:01 PM

Support reference count

Original: 2

New: 3

Assignee:: Unassigned

Reporter:: David Chan

Affected customers:: 3 This affects my team

Watchers:: 6 Start watching this issue

Created:: 18/Jul/2018 1:05 PM

Updated:: 30/Sep/2022 8:43 AM

Details

Description

Problem

Diagnosis

Application Logs

Thread Dumps

Workaround

Attachments

Issue Links

Forms

Activity

People

Dates