Loading...

Type: Bug
Resolution: Timed out
Priority: Low
Fix Version/s: None
Affects Version/s: 7.2.2
Component/s: Issue - View Issue
Labels:
- affects-server
- pse-request

Introduced in Version:
7.02
Support reference count:
3
Symptom Severity:
Severity 2 - Major
UIS:
1
Bug Fix Policy:
View Atlassian Server bug fix policy

Summary

StackTraceInfo Class are initialised multiple times on stack trace logging

Steps to Reproduce

Produce a lot of logging in the same thread

Expected Results

No additional overhead and class loading done only once.

Actual Results

Thread produces many log messages with stacktrace and each time it tries to load some class from com.atlassian.logging.log4j.FilteredPatternLayout.getThrowableStrRep. This causing slow execution and high CPU usage.
Progress over time:

grep -A 50 http-nio-8080-exec-243 jira_threads.20161025-133* | grep -e 'com.atlassian.logging.log4j.FilteredPatternLayout.getThrowableStrRep' -e 'org.apache.log4j.WriterAppender.subAppend' -e 'java.lang.Thread.State' -e 'org.apache.log4j.Category.callAppenders' -e 'org.apache.logging.log4j.core.util.Loader.initializeClass'

jira_threads.20161025-133119.txt-   java.lang.Thread.State: RUNNABLE
jira_threads.20161025-133119.txt-	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
jira_threads.20161025-133119.txt-	at org.apache.log4j.Category.callAppenders(Category.java:206)

jira_threads.20161025-133131.txt-   java.lang.Thread.State: RUNNABLE
jira_threads.20161025-133131.txt-	at org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:66)
jira_threads.20161025-133131.txt-	at com.atlassian.logging.log4j.FilteredPatternLayout.getThrowableStrRep(FilteredPatternLayout.java:359)
jira_threads.20161025-133131.txt-	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
jira_threads.20161025-133131.txt-	at org.apache.log4j.Category.callAppenders(Category.java:206)

jira_threads.20161025-133142.txt-   java.lang.Thread.State: RUNNABLE
jira_threads.20161025-133142.txt-	at org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:66)
jira_threads.20161025-133142.txt-	at com.atlassian.logging.log4j.FilteredPatternLayout.getThrowableStrRep(FilteredPatternLayout.java:359)
jira_threads.20161025-133142.txt-	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
jira_threads.20161025-133142.txt-	at org.apache.log4j.Category.callAppenders(Category.java:206)

jira_threads.20161025-133153.txt-   java.lang.Thread.State: BLOCKED (on object monitor)
jira_threads.20161025-133153.txt-	at org.apache.log4j.Category.callAppenders(Category.java:204)

jira_threads.20161025-133204.txt-   java.lang.Thread.State: RUNNABLE
jira_threads.20161025-133204.txt-	at com.atlassian.logging.log4j.FilteredPatternLayout.getThrowableStrRep(FilteredPatternLayout.java:359)
jira_threads.20161025-133204.txt-	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
jira_threads.20161025-133204.txt-	at org.apache.log4j.Category.callAppenders(Category.java:206)

jira_threads.20161025-133215.txt-   java.lang.Thread.State: BLOCKED (on object monitor)
jira_threads.20161025-133215.txt-	at org.apache.log4j.Category.callAppenders(Category.java:204)

Full stacktrace:

"http-nio-8080-exec-243 uri:/secure/admin/views/issuefields/screens/viewfieldscreens.jsp username:" #25366 daemon prio=5 tid=0x00007f41b8055800 nid=0x293d runnable [0x00007f3ec4d7c000]
  java.lang.Thread.State: RUNNABLE
      at java.util.zip.ZipFile.getEntry(Native Method)
      at java.util.zip.ZipFile.getEntry(ZipFile.java:310)
      - locked <0x00000007b5902e30> (a java.util.jar.JarFile)
      at java.util.jar.JarFile.getEntry(JarFile.java:240)
      at java.util.jar.JarFile.getJarEntry(JarFile.java:223)
      at org.apache.catalina.webresources.JarResourceSet.getArchiveEntry(JarResourceSet.java:120)
      at org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(AbstractArchiveResourceSet.java:260)
      at org.apache.catalina.webresources.StandardRoot.getResourceInternal(StandardRoot.java:281)
      at org.apache.catalina.webresources.Cache.getResource(Cache.java:63)
      at org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:216)
      at org.apache.catalina.webresources.StandardRoot.getClassLoaderResource(StandardRoot.java:225)
      at org.apache.catalina.loader.WebappClassLoaderBase.findResourceInternal(WebappClassLoaderBase.java:2569)
      at org.apache.catalina.loader.WebappClassLoaderBase.findClassInternal(WebappClassLoaderBase.java:2406)
      at org.apache.catalina.loader.WebappClassLoaderBase.findClass(WebappClassLoaderBase.java:831)
      at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1274)
      - locked <0x0000000401a8d810> (a org.apache.catalina.loader.WebappClassLoader)
      at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1139)
      at java.lang.Class.forName0(Native Method)
      at java.lang.Class.forName(Class.java:348)
      at org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:66)
      at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:501)
      at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:629)
      at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:111)
      at com.atlassian.logging.log4j.StackTraceInfo.buildPackagingRepresentation(StackTraceInfo.java:145)
      at com.atlassian.logging.log4j.StackTraceInfo.buildThrowableStrRep(StackTraceInfo.java:106)
      at com.atlassian.logging.log4j.StackTraceInfo.<init>(StackTraceInfo.java:43)
      at com.atlassian.logging.log4j.FilteredPatternLayout.getThrowableStrRep(FilteredPatternLayout.java:359)
      at com.atlassian.logging.log4j.FilteredPatternLayout.formatStackTrace(FilteredPatternLayout.java:336)
      at com.atlassian.logging.log4j.FilteredPatternLayout.format(FilteredPatternLayout.java:330)
      at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
      at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:276)
      at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
      at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
      - locked <0x0000000401138288> (a org.apache.log4j.RollingFileAppender)
      at com.atlassian.jira.logging.JiraHomeAppender.doAppend(JiraHomeAppender.java:206)
      at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
      at org.apache.log4j.Category.callAppenders(Category.java:206)
      - locked <0x000000040113de30> (a org.apache.log4j.Logger)
      at org.apache.log4j.Category.forcedLog(Category.java:391)
      at org.apache.log4j.Category.log(Category.java:856)
      at org.slf4j.impl.Log4jLoggerAdapter.log(Log4jLoggerAdapter.java:601)
      at org.apache.commons.logging.impl.SLF4JLocationAwareLog.error(SLF4JLocationAwareLog.java:225)
      at webwork.util.ValueStack.findValue(ValueStack.java:532)
      at webwork.util.SimpleTest.test(SimpleTest.java:408)
      at webwork.util.ValueStack.test(ValueStack.java:157)
      at webwork.view.taglib.IfTag.doStartTag(IfTag.java:40)
      at jsp.secure.admin.views.issuefields.screens.viewfieldscreens_jsp._jspx_meth_ww_005fif_005f6(viewfieldscreens_jsp.java:2355)
      at jsp.secure.admin.views.issuefields.screens.viewfieldscreens_jsp._jspService(viewfieldscreens_jsp.java:281)
      at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
...

Notes

None

Workaround

None

is related to

JRASERVER-62958 Enabling access logging might cause JIRA to stall

Gathering Impact

Details

Description

Summary

Steps to Reproduce

Expected Results

Actual Results

Notes

Workaround

Attachments

Issue Links

Forms

Activity

People

Dates