Topic
  • 2 replies
  • Latest Post - ‏2013-08-21T12:28:05Z by Dario Bassan
caini_8
caini_8
1 Post

Pinned topic High CPU utilization relate to log4j

‏2013-08-01T16:04:40Z |

I encountered a performance issue relate to log4j.

 

Background:

My application is running in WAS instance in Linux server. It adopts log4j for logger. One day, there changed something on log4j.xml arms to extend the maximum number of backup log files from 5 to 30. The changed code as below. It used <!-- -- > to comment the value 5.

<appender name="OutputApp" class="org.apache.log4j.RollingFileAppender">

<param name="File" value="./logs/AppOutput${log4j.siteID}.log" />

<param name="MaxFileSize" value="10MB" />

<!--2P40-10287 Start -- >

<param name="MaxBackupIndex" value="5" />

<!--2P40-10287 End -->

<param name="MaxBackupIndex" value="30" />

<layout class="org.apache.log4j.PatternLayout">

<param name="ConversionPattern" value="[%d] %X{loginId} %t %m%n" />

</layout>

</appender>

 

Problem:

When starting the WAS server, there had below system error indicated that the log4j system were not initialized properly. I ignored the error and keep using the application. Then I found that 1) The application log could not be generated; 2) The CPU utilization was extremely higher then as usual. Further checked the server GC and found that the frequency of GC was much more higher than as usual (couple seconds compare to couple minutes). Besides, I tried to find if any exception when logging in debug mode but could not find any. I removed the comment and redeployed to the server, the application resumed normal then.

My question is that how can the parsing error of the comments result in high CPU utilization?

SystemErr R log4j:WARN Fatal parsing error 42 and column 27

SystemErr R log4j:WARN The string "--" is not permitted within comments.

SystemErr R log4j:ERROR Could not parse url [file:/opt/WebSphere70/AppServer/profiles/appprofile/installedApps/wascell/APP.ear/APP.war/WEB-INF/classes/log4j.xml].

SystemErr R org.xml.sax.SAXParseException: The string "--" is not permitted within comments.

SystemErr R at org.apache.xerces.parsers.DOMParser.parse(Unknown Source)

SystemErr R at org.apache.xerces.jaxp.DocumentBuilderImpl.parse(Unknown Source)

SystemErr R at javax.xml.parsers.DocumentBuilder.parse(Unknown Source)

SystemErr R at org.apache.log4j.xml.DOMConfigurator$2.parse(DOMConfigurator.java:690)

SystemErr R at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:789)

SystemErr R at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:696)

SystemErr R at org.apache.log4j.helpers.OptionConverter.selectAndConfigure(OptionConverter.java:471)

SystemErr R at org.apache.log4j.LogManager.<clinit>(LogManager.java:125)

SystemErr R at java.lang.J9VMInternals.initializeImpl(Native Method)

SystemErr R at java.lang.J9VMInternals.initialize(J9VMInternals.java:200)

SystemErr R at org.apache.log4j.Logger.getLogger(Logger.java:118)

SystemErr R at com.hsbc.carm.tools.js.StripAndCompress.<clinit>(StripAndCompress.java:69)

SystemErr R at java.lang.J9VMInternals.initializeImpl(Native Method)

SystemErr R at java.lang.J9VMInternals.initialize(J9VMInternals.java:200)

SystemErr R at java.lang.Class.forNameImpl(Native Method)

SystemErr R at java.lang.Class.forName(Class.java:172)

SystemErr R at java.beans.Beans.instantiate(Beans.java:184)

SystemErr R at java.beans.Beans.instantiate(Beans.java:75)

SystemErr R at com.ibm.ws.webcontainer.servlet.ServletWrapper$1.run(ServletWrapper.java:1909)

SystemErr R at com.ibm.ws.security.util.AccessController.doPrivileged(AccessController.java:118)

SystemErr R at com.ibm.ws.webcontainer.servlet.ServletWrapper.loadServlet(ServletWrapper.java:1900)

SystemErr R at com.ibm.ws.webcontainer.servlet.ServletWrapper.initialize(ServletWrapper.java:1795)

SystemErr R at com.ibm.wsspi.webcontainer.extension.WebExtensionProcessor.createServletWrapper(WebExtensionProcessor.java:98)

SystemErr R at com.ibm.ws.webcontainer.webapp.WebApp.getServletWrapper(WebApp.java:1037)

SystemErr R at com.ibm.ws.webcontainer.webapp.WebApp.getServletWrapper(WebApp.java:958)

SystemErr R at com.ibm.ws.webcontainer.webapp.WebApp.initializeTargetMappings(WebApp.java:637)

SystemErr R at com.ibm.ws.webcontainer.webapp.WebApp.commonInitializationFinally(WebApp.java:435)

SystemErr R at com.ibm.ws.webcontainer.webapp.WebAppImpl.initialize(WebAppImpl.java:304)

SystemErr R at com.ibm.ws.webcontainer.webapp.WebGroupImpl.addWebApplication(WebGroupImpl.java:100)

SystemErr R at com.ibm.ws.webcontainer.VirtualHostImpl.addWebApplication(VirtualHostImpl.java:166)

SystemErr R at com.ibm.ws.webcontainer.WSWebContainer.addWebApp(WSWebContainer.java:731)

SystemErr R at com.ibm.ws.webcontainer.WSWebContainer.addWebApplication(WSWebContainer.java:616)

SystemErr R at com.ibm.ws.webcontainer.component.WebContainerImpl.install(WebContainerImpl.java:376)

SystemErr R at com.ibm.ws.webcontainer.component.WebContainerImpl.start(WebContainerImpl.java:668)

SystemErr R at com.ibm.ws.runtime.component.ApplicationMgrImpl.start(ApplicationMgrImpl.java:1123)

SystemErr R at com.ibm.ws.runtime.component.DeployedApplicationImpl.fireDeployedObjectStart(DeployedApplicationImpl.java:1319)

SystemErr R at com.ibm.ws.runtime.component.DeployedModuleImpl.start(DeployedModuleImpl.java:610)

SystemErr R at com.ibm.ws.runtime.component.DeployedApplicationImpl.start(DeployedApplicationImpl.java:944)

SystemErr R at com.ibm.ws.runtime.component.ApplicationMgrImpl.startApplication(ApplicationMgrImpl.java:726)

SystemErr R at com.ibm.ws.runtime.component.ApplicationMgrImpl$1.run(ApplicationMgrImpl.java:1268)

SystemErr R at com.ibm.ws.security.auth.ContextManagerImpl.runAs(ContextManagerImpl.java:4678)

SystemErr R at com.ibm.ws.security.auth.ContextManagerImpl.runAsSystem(ContextManagerImpl.java:4766)

SystemErr R at com.ibm.ws.security.core.SecurityContext.runAsSystem(SecurityContext.java:255)

SystemErr R at com.ibm.ws.runtime.component.ApplicationMgrImpl.startApplicationDynamically(ApplicationMgrImpl.java:1273)

SystemErr R at com.ibm.ws.runtime.component.ApplicationMgrImpl.start(ApplicationMgrImpl.java:2045)

SystemErr R at com.ibm.ws.runtime.component.CompositionUnitMgrImpl.start(CompositionUnitMgrImpl.java:441)

SystemErr R at com.ibm.ws.runtime.component.CompositionUnitImpl.start(CompositionUnitImpl.java:123)

SystemErr R at com.ibm.ws.runtime.component.CompositionUnitMgrImpl.start(CompositionUnitMgrImpl.java:384)

SystemErr R at com.ibm.ws.runtime.component.CompositionUnitMgrImpl.startCompositionUnit(CompositionUnitMgrImpl.java:655)

SystemErr R at com.ibm.ws.runtime.component.CompositionUnitMgrImpl.startCompositionUnit(CompositionUnitMgrImpl.java:617)

SystemErr R at com.ibm.ws.runtime.component.ApplicationMgrImpl.startApplication(ApplicationMgrImpl.java:1180)

SystemErr R at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

SystemErr R at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)

SystemErr R at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)

SystemErr R at java.lang.reflect.Method.invoke(Method.java:589)

SystemErr R at sun.reflect.misc.Trampoline.invoke(MethodUtil.java:49)

SystemErr R at sun.reflect.GeneratedMethodAccessor56.invoke(Unknown Source)

SystemErr R at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)

SystemErr R at java.lang.reflect.Method.invoke(Method.java:611)

SystemErr R at sun.reflect.misc.MethodUtil.invoke(MethodUtil.java:256)

SystemErr R at javax.management.modelmbean.RequiredModelMBean.invokeMethod(RequiredModelMBean.java:1085)

SystemErr R at javax.management.modelmbean.RequiredModelMBean.invoke(RequiredModelMBean.java:966)

SystemErr R at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:848)

SystemErr R at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:773)

SystemErr R at com.ibm.ws.management.AdminServiceImpl$1.run(AdminServiceImpl.java:1332)

SystemErr R at com.ibm.ws.security.util.AccessController.doPrivileged(AccessController.java:118)

SystemErr R at com.ibm.ws.management.AdminServiceImpl.invoke(AdminServiceImpl.java:1225)

SystemErr R at com.ibm.ws.management.connector.AdminServiceDelegator.invoke(AdminServiceDelegator.java:181)

SystemErr R at com.ibm.ws.management.connector.ipc.CallRouter.route(CallRouter.java:242)

SystemErr R at com.ibm.ws.management.connector.ipc.IPCConnectorInboundLink.doWork(IPCConnectorInboundLink.java:353)

SystemErr R at com.ibm.ws.management.connector.ipc.IPCConnectorInboundLink$IPCConnectorReadCallback.complete(IPCConnectorInboundLink.java:595)

SystemErr R at com.ibm.ws.ssl.channel.impl.SSLReadServiceContext$SSLReadCompletedCallback.complete(SSLReadServiceContext.java:1784)

SystemErr R at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:165)

SystemErr R at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)

SystemErr R at com.ibm.io.async.AsyncChannelFuture.fireCompletionActions(AsyncChannelFuture.java:161)

SystemErr R at com.ibm.io.async.AsyncFuture.completed(AsyncFuture.java:138)

SystemErr R at com.ibm.io.async.ResultHandler.complete(ResultHandler.java:204)

SystemErr R at com.ibm.io.async.ResultHandler.runEventProcessingLoop(ResultHandler.java:775)

SystemErr R at com.ibm.io.async.ResultHandler$2.run(ResultHandler.java:905)

SystemErr R at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1604)

SystemErr R log4j:WARN No appenders could be found for logger (com.hsbc.carm.common.util.BackgroundTask).

SystemErr R log4j:WARN Please initialize the log4j system properly.

  • Dario Bassan
    Dario Bassan
    4 Posts

    Re: High CPU utilization relate to log4j

    ‏2013-08-21T12:25:39Z  

    I guess the problem is on how you commented the lines:

    This should work:

    <!--2P40-10287 Start 
    <param name="MaxBackupIndex" value="5" />
    2P40-10287 End -->

    or this:

    <!--2P40-10287 Start -->
    <!--<param name="MaxBackupIndex" value="5" /> -->
    <!--2P40-10287 End -->

    Ciao

     

  • Dario Bassan
    Dario Bassan
    4 Posts

    Re: High CPU utilization relate to log4j

    ‏2013-08-21T12:28:05Z  

    I guess the problem is on how you commented the lines:

    This should work:

    <!--2P40-10287 Start 
    <param name="MaxBackupIndex" value="5" />
    2P40-10287 End -->

    or this:

    <!--2P40-10287 Start -->
    <!--<param name="MaxBackupIndex" value="5" /> -->
    <!--2P40-10287 End -->

    Ciao

     

    Sorry... I miss your point:

    "My question is that how can the parsing error of the comments result in high CPU utilization?"