[JRASERVER-62959] StackTraceInfo Class are initialised multiple times on stack trace logging

Type: Bug
Resolution: Timed out
Priority: Low (View bug fix roadmap)
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

Closed

Ewelina Fiedorowicz added a comment - 22/Jul/2021 10:31 AM

Atlassian Update – 22.07.2021

Hi Everyone,

We have recently reviewed this issue and the overall interest in the problem. As the issue hasn't collect votes, watchers, comments, or support cases from many customers during its lifetime, it's very low on our priority list, and will not be fixed in the foreseeable future. That's why we've decided to resolve it as Time Out.

Although we're aware the issue is still important to those of you who were involved in the conversations around it, we want to be clear in managing your expectations. The Jira team is focusing on issues that have broad impact and high value, reflected by the number of comments, votes, support cases, and customers interested. Please consult the Atlassian Bugfix Policy for more details.

We understand how disappointing this decision may be, but we hope you'll appreciate our transparent approach and communication.
Atlassian will continue to watch this issue for further updates, so please feel free to share your thoughts in the comments.

Thank you,
Ewelina Fiedorowicz

Ewelina Fiedorowicz added a comment - 22/Jul/2021 10:31 AM Atlassian Update – 22.07.2021 Hi Everyone, We have recently reviewed this issue and the overall interest in the problem. As the issue hasn't collect votes, watchers, comments, or support cases from many customers during its lifetime, it's very low on our priority list, and will not be fixed in the foreseeable future. That's why we've decided to resolve it as Time Out . Although we're aware the issue is still important to those of you who were involved in the conversations around it, we want to be clear in managing your expectations. The Jira team is focusing on issues that have broad impact and high value, reflected by the number of comments, votes, support cases, and customers interested. Please consult the Atlassian Bugfix Policy for more details. We understand how disappointing this decision may be, but we hope you'll appreciate our transparent approach and communication. Atlassian will continue to watch this issue for further updates, so please feel free to share your thoughts in the comments. Thank you, Ewelina Fiedorowicz

Details

Description

Summary

Steps to Reproduce

Expected Results

Actual Results

Notes

Workaround

Attachments

Issue Links

Forms

Activity

Collapse comment: Ewelina Fiedorowicz added a comment - 22/Jul/2021 10:31 AM

Expand comment: Ewelina Fiedorowicz added a comment - 22/Jul/2021 10:31 AM

People

Dates