Uploaded image for project: 'Jira Data Center'
  1. Jira Data Center
  2. JRASERVER-70298

Make DEBUG com.atlassian.cache.event as default logging

      Issue Summary

      Due to the following bugs, a cache flush event can cause cascading performance issue on Data Center.

      As such, we would like to make the cache flush event debug as the default logger in Jira, so that administrator can track the event and correlate with other performance metrics (ie, response time)

      The debug logger consist of one line per event as below.

      awk -F ']' '{if ($0 ~/was flushed/) {print $2}}' atlassian-jira.log | sort | uniq -c | sort -n -k 1,1 | less
         1  Cache UpmPluginLicenseCache was flushed
         1  Cache UpmRoleBasedMetadataCache was flushed
         1  Cache com.atlassian.upm.license.role.jira.GlobalPermissionUserCountCache was flushed
         4  Cache com.atlassian.jira.project.version.CachingVersionStore.cache.versionsByName was flushed
         4  Cache com.atlassian.jira.project.version.CachingVersionStore.cache.versionsByProjectId was flushed
       970  Cache com.atlassian.jira.issue.security.IssueSecuritySchemeManagerImpl.projectSchemeCache was flushed
       970  Cache com.atlassian.jira.issue.security.IssueSecuritySchemeManagerImpl.schemeIdToSecuritiesCache was flushed
       970  Cache com.atlassian.jira.issue.security.IssueSecuritySchemeManagerImplsecurityLevelToPermissionsCache was flushed
      1085  Cache com.atlassian.jira.issue.security.IssueSecurityLevelManagerImpl.projectAndUserToSecurityLevelCache was flushed
      

      Steps to Reproduce

      • Setup 3 nodes data center
      • Create 5000 custom field (to exagerate the prorblem)
      • Change a customfield configuration
      • Notice slow drop on performance across nodes due to cache flush event

      Expected Results

      The debug log should be enabled by default since it is necessary and is not verbose

      Actual Results

      The debug is not enabled hence we don't know if there is cache flush event happened

      Workaround

      Enable DEBUG logging manually (see JRASERVER-66031 for context)

      • navigate to Administration > Logging and Profiling
      • Click Configure debug for new package
      • Add DEBUG on com.atlassian.cache.event

            [JRASERVER-70298] Make DEBUG com.atlassian.cache.event as default logging

            vkharisma,

            could you please confirm what you would like to have logged at DEBUG level? To me it looks like the "was flushed" messages are already logged at INFO.

            This logging comes from the atlassian-cache library. In Jira we use the following atlassian-cache versions:

            ~/src/jira $ for JV in 7.6.15 7.13.9 8.5.1 ; do echo ${JV}; git show ${JV}:pom.xml | grep '<atlassian.cache.version>' ; done
            7.6.15
                    <atlassian.cache.version>3.2.0</atlassian.cache.version>
            7.13.9
                    <atlassian.cache.version>3.2.0</atlassian.cache.version>
            8.5.1
                    <atlassian.cache.version>4.0.0</atlassian.cache.version>

            Both of these versions have logging at INFO:

            ~/src/atlassian-cache $ for CV in 3.2.0 4.0.0 ; do echo ${CV}; git show atlassian-cache-${CV}:atlassian-cache-ehcache/src/main/java/com/atlassian/cache/ehcache/DelegatingCache.java | grep ' was flushed' ; done
            3.2.0
                        eventLogger.info("Cache {} was flushed", delegate.getName());
                            stacktraceLogger.info("Cache {} was flushed. Stacktrace:", delegate.getName(), new Exception());
            4.0.0
                        eventLogger.info("Cache {} was flushed", delegate.getName());
                            stacktraceLogger.info("Cache {} was flushed. Stacktrace:", delegate.getName(), new Exception());

            From what I can see in the jira-components/jira-webapp/src/main/webapp/WEB-INF/classes/log4j.properties file, the logging for all but two caches is turned off:

            #
            # Logging of cache flush events for the most costly caches
            #
            # Dummy parent logger not to write additivity for each cache
            log4j.logger.com.atlassian.cache.event = OFF, filelog
            log4j.additivity.com.atlassian.cache.event = false
            log4j.logger.com.atlassian.cache.stacktrace = OFF, filelog
            log4j.additivity.com.atlassian.cache.stacktrace = false
            
            log4j.logger.com.atlassian.cache.event.com.atlassian.jira.crowd.embedded.ofbiz.EagerOfBizUserCache.userCache = INFO
            log4j.logger.com.atlassian.cache.event.com.atlassian.jira.crowd.embedded.ofbiz.EagerOfBizGroupCache.groupCache = INFO

            Is this ticket about changing these to INFO, or am I missing something?

            Kamil Cichy (Inactive) added a comment - vkharisma , could you please confirm what you would like to have logged at DEBUG  level? To me it looks like the "was flushed" messages are already logged at INFO . This logging comes from the atlassian-cache  library. In Jira we use the following atlassian-cache  versions: ~/src/jira $ for JV in 7.6.15 7.13.9 8.5.1 ; do echo ${JV}; git show ${JV}:pom.xml | grep '<atlassian.cache.version>' ; done 7.6.15 <atlassian.cache.version>3.2.0</atlassian.cache.version> 7.13.9 <atlassian.cache.version>3.2.0</atlassian.cache.version> 8.5.1 <atlassian.cache.version>4.0.0</atlassian.cache.version> Both of these versions have logging at INFO : ~/src/atlassian-cache $ for CV in 3.2.0 4.0.0 ; do echo ${CV}; git show atlassian-cache-${CV}:atlassian-cache-ehcache/src/main/java/com/atlassian/cache/ehcache/DelegatingCache.java | grep ' was flushed' ; done 3.2.0 eventLogger.info("Cache {} was flushed", delegate.getName()); stacktraceLogger.info("Cache {} was flushed. Stacktrace:", delegate.getName(), new Exception()); 4.0.0 eventLogger.info("Cache {} was flushed", delegate.getName()); stacktraceLogger.info("Cache {} was flushed. Stacktrace:", delegate.getName(), new Exception()); From what I can see in the jira-components/jira-webapp/src/main/webapp/WEB-INF/classes/log4j.properties file, the logging for all but two caches is turned off: # # Logging of cache flush events for the most costly caches # # Dummy parent logger not to write additivity for each cache log4j.logger.com.atlassian.cache.event = OFF, filelog log4j.additivity.com.atlassian.cache.event = false log4j.logger.com.atlassian.cache.stacktrace = OFF, filelog log4j.additivity.com.atlassian.cache.stacktrace = false log4j.logger.com.atlassian.cache.event.com.atlassian.jira.crowd.embedded.ofbiz.EagerOfBizUserCache.userCache = INFO log4j.logger.com.atlassian.cache.event.com.atlassian.jira.crowd.embedded.ofbiz.EagerOfBizGroupCache.groupCache = INFO Is this ticket about changing these to INFO , or am I missing something?

              Unassigned Unassigned
              vkharisma vkharisma
              Affected customers:
              1 This affects my team
              Watchers:
              14 Start watching this issue

                Created:
                Updated:
                Resolved: