0

I am finding the below issue when I ran my profiler

BLOCKED CPU usage on sample: 62ms
org.apache.logging.log4j.core.layout.TextEncoderHelper.copyDataToDestination(ByteBuffer, ByteBufferDestination) TextEncoderHelper.java:61
org.apache.logging.log4j.core.layout.TextEncoderHelper.encodeTextWithCopy(CharsetEncoder, CharBuffer, ByteBuffer, StringBuilder, ByteBufferDestination) TextEncoderHelper.java:57

(or)

State: BLOCKED CPU usage on sample: 5ms
org.apache.logging.log4j.core.layout.StringBuilderEncoder.encodeSynchronized(CharsetEncoder, CharBuffer, StringBuilder, ByteBufferDestination) StringBuilderEncoder.java:83
org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilder, ByteBufferDestination) StringBuilderEncoder.java:61
org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(Object, ByteBufferDestination) StringBuilderEncoder.java:32
org.apache.logging.log4j.core.layout.PatternLayout.encode(LogEvent, ByteBufferDestination) PatternLayout.java:219
org.apache.logging.log4j.core.layout.PatternLayout.encode(Object, ByteBufferDestination) PatternLayout.java:57
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(LogEvent) AbstractOutputStreamAppender.java:177
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(LogEvent) AbstractOutputStreamAppender.java:170
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(LogEvent) AbstractOutputStreamAppender.java:161
org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(LogEvent) AppenderControl.java:156
org.apache.logging.log4j.core.config.AppenderControl.callAppender0(LogEvent) AppenderControl.java:129
org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(LogEvent) AppenderControl.java:120
org.apache.logging.log4j.core.config.AppenderControl.callAppender(LogEvent) AppenderControl.java:84
org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LogEvent) LoggerConfig.java:448
org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppendersInCurrentThread(LogEvent) AsyncLoggerConfig.java:106
org.apache.logging.log4j.core.async.EventRoute$2.logMessage(AsyncLoggerConfig, LogEvent) EventRoute.java:65
org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppenders(LogEvent) AsyncLoggerConfig.java:96
org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LogEvent) LoggerConfig.java:433
org.apache.logging.log4j.core.config.LoggerConfig.log(LogEvent) LoggerConfig.java:417
org.apache.logging.log4j.core.config.LoggerConfig.log(String, String, Marker, Level, Message, Throwable) LoggerConfig.java:403
org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(Supplier, String, String, Marker, Level, Message, Throwable) AwaitCompletionReliabilityStrategy.java:63
org.apache.logging.log4j.core.Logger.logMessage(String, Level, Marker, Message, Throwable) Logger.java:146
org.mule.module.launcher.log4j2.DispatchingLogger.logMessage(String, Level, Marker, Message, Throwable) DispatchingLogger.java:157  <2 recursive calls>
org.apache.logging.slf4j.Log4jLogger.log(Marker, String, int, String, Object[], Throwable) Log4jLogger.java:376
org.apache.commons.logging.impl.SLF4JLocationAwareLog.warn(Object) SLF4JLocationAwareLog.java:179
org.mule.api.processor.LoggerMessageProcessor$LogLevel$2.log(Log, Object) LoggerMessageProcessor.java:137
org.mule.api.processor.LoggerMessageProcessor.log(MuleEvent) LoggerMessageProcessor.java:81

Most of my blocked threads are pointing to this. Can any one help me on this? I am running mule application and when I tried to dig in the delay in mule processing, I found it landed into blocks due to log4j

What things can I try to resolve this?

log4j.xml -->

<?xml version="1.0" encoding="UTF-8" ?>
<Configuration status="debug">

  <!-- ================================================================================== -->
  <!--  Appenders                                                                         -->
  <!--                                                                                    -->
  <!-- Loggers can be associated with 1 or more appenders.                                -->
  <!-- rolling_file_appender is the default appender in this file.                        -->
  <!-- STDOUT appender can be added to Loggers below if needed.                           -->
  <!-- ================================================================================== -->

  <Appenders>
    <Console name="STDOUT" target="SYSTEM_OUT">    
      <PatternLayout pattern="%d [%p] %c{3} | %m%n" />
     </Console>
                

                 
    <RollingFile name="application-log" fileName="${env:LOG_HOME}/test-esb-bsns/application.log" filePattern="${env:LOG_HOME}/test-esb-bsns/application-%i.log" append="true" bufferedIO="true">
      <PatternLayout pattern="%d [%p] %c{3} | %X{mule.flow} | %X{mule.messageId}#%X{mule.correlationId} | %X{mule.incomingMessageId} | %m%n"/>
                  <Policies>
                      <SizeBasedTriggeringPolicy size="10 MB" />
    </Policies>
    <DefaultRolloverStrategy max="10"/>
   </RollingFile>
                
                <RollingFile name="mule_Logger" fileName="${env:LOG_HOME}/test-esb-bsns/mule-server.log" filePattern="${env:LOG_HOME}/test-esb-bsns/mule-server-%i.log" append="true" bufferedIO="true">
      <PatternLayout pattern="%d [%p] %c{3} | %X{mule.flow} | %X{mule.messageId}#%X{mule.correlationId} | %X{mule.incomingMessageId} | %m%n "/>
                  <Policies>
                     <SizeBasedTriggeringPolicy size="10 MB" />
    </Policies>
    <DefaultRolloverStrategy max="10"/>
   </RollingFile>
                
                 
    </Appenders>

  <!-- ========================================================================================== -->
  <!-- possible Logger threshold level values: all < debug < info < warn < error < fatal < off    -->
  <!-- ========================================================================================== -->

<!--   <Logger name="central.Logger"> -->
<!--     <level value="off" /> -->
<!--     <appender-ref ref="STDOUT" /> -->
<!--   </Logger> -->

  <!-- ===================================================================================== -->
  <!-- com.comverse.* will inherit these value unless overridden below                       -->
  <!-- Allows for logging of info, warn, error and fatal messages to the specified appenders -->
  <!-- ===================================================================================== -->
<Loggers>
   <AsyncLogger name="org.mule" level="INFO" additivity="false">
    <appender-ref ref="mule_Logger" />
    <appender-ref ref="STDOUT" />
  </AsyncLogger>
  
 <!--  <AsyncLogger name="com.test.esb" level="DEBUG" additivity="false">
    <appender-ref ref="application-log" />
     
     <appender-ref ref="application-log" />
   </AsyncLogger> -->
     
  <AsyncRoot level="INFO">
                <appender-ref ref="application-log" />
                <appender-ref ref="STDOUT" />
                
  </AsyncRoot>
  
  <!-- CXF Loggers -->
  <AsyncLogger name="org.apache.cxf" level="INFO" additivity="false">
                <appender-ref ref="application-log" />
                <appender-ref ref="STDOUT" />
  </AsyncLogger>
  
  <AsyncLogger name="com.ars.test" level="info" additivity="false">
                <appender-ref ref="application-log" />
                 <appender-ref ref="STDOUT" />
  </AsyncLogger>
  
  <AsyncLogger name="com.test" level="INFO" additivity="false">
                <appender-ref ref="application-log" />
                 <appender-ref ref="STDOUT" />
  </AsyncLogger>
  
<!--   <AsyncLogger name="org.hibernate" level="INFO" type="trace">
                <appender-ref ref="application-log" />
                 
  </AsyncLogger> -->
  
    <AsyncLogger name="org.hibernate.SQL" level="INFO" additivity="false">
                <appender-ref ref="application-log" />
                 <appender-ref ref="STDOUT" />
  </AsyncLogger>
  
    <AsyncLogger name="org.hibernate.type" level="INFO" additivity="false">
                <appender-ref ref="application-log" />
                 <appender-ref ref="STDOUT" />
  </AsyncLogger>
  
       
        <!-- Reduce startup noise -->
   <AsyncLogger name="org.springframework.beans.factory" level="WARN">
      <appender-ref ref="mule_Logger" />
      <appender-ref ref="STDOUT" />
   </AsyncLogger>

    <AsyncLogger name="com.mulesoft" level="INFO">
       <appender-ref ref="mule_Logger" />
       
    </AsyncLogger>
  
 </Loggers>
   
</Configuration>
Mahesh A R
  • 11
  • 4
  • 2
    Please read [Under what circumstances may I add “urgent” or other similar phrases to my question, in order to obtain faster answers?](//meta.stackoverflow.com/q/326569) - the summary is that this is not an ideal way to address volunteers, and is probably counterproductive to obtaining answers. Please refrain from adding this to your questions. – halfer May 26 '20 at 11:39
  • Please share log4j2.xml file. Also, how much logging are you doing? A lot of volume? Using a lot of debug? – aled May 26 '20 at 13:33
  • Additionally, add the names of threads. In Mule they provide more information about what is being processed. – aled May 26 '20 at 13:35
  • @aled : I've updated the log4j.xml – Mahesh A R May 26 '20 at 13:57
  • No debug, but i am sure we have quite a lot of logging. If I remove the file appender, for testing, will this be resolved? or should I manually reomve the llog4j calls in the code? – Mahesh A R May 26 '20 at 14:04
  • Log levels are meant to avoid having to change the log calls in code. You should try first to reduce the log level (DEBUG to INFO), then comment appenders, and remove code as a last resource. Unless you are logging a lot of information per log4j2 call. Is this happening in Java code, or Mule flows? – aled May 26 '20 at 15:18
  • Almost 70% logging happens from java code – Mahesh A R May 26 '20 at 17:12
  • If you log a lot you may be exceeding your system capacity. Is the logging done at debug level or info? Maybe you need to change some loggers to debug to avoid logging so much. – aled May 26 '20 at 17:17
  • Yes I am able to see some difference. Will update more after I test – Mahesh A R May 26 '20 at 19:46

1 Answers1

0

Without further information, I would say that the application is doing a log of logging, or using a pattern that requires a lot of processing, or a combination of both.

aled
  • 21,330
  • 3
  • 27
  • 34
  • what do you mean by pattern that requires a lot of processing? – Mahesh A R May 26 '20 at 14:06
  • Some log4j2 conversion patterns are more expensive to process than others: https://logging.apache.org/log4j/2.x/manual/layouts.html#PatternLayout That's why I asked for the log4j2.xml file, to see if you customized the configuration. – aled May 26 '20 at 15:09