7 Replies Latest reply on Aug 4, 2013 4:11 AM by Yaniv Peleg

    Very slow performance using Log4J in JBoss EAP 6.1

    Yaniv Peleg Newbie

      Hi,

       

      We are using JBoss 6.1 EAP Alpha with Log4J (version 1.2.13) as the application log.

      The Log4J is excluded in jboss-deployment-structure.xml

      When running in our development machines (Windows based) everything worked fine.

      When running on our QA machines (Linux based) we experienced very slow response.

      After investigating this with profiler we noticed that the Log4J logging takes several seconds (for several hundreds of lines).

       

      We would be grateful if anyone can help.

        • 1. Re: Very slow performance using Log4J in JBoss EAP 6.1
          Tomaz Cerar Master

          Hi,

           

          can you post your logging configuration & thread dump from when system is running slowly.

           

           

           

           

          --

          tomaz

          • 2. Re: Very slow performance using Log4J in JBoss EAP 6.1
            Yaniv Peleg Newbie

            Logging configuration is standard, here a snippet from standalone.xml

             

            <subsystem xmlns="urn:jboss:domain:logging:1.2">

                <console-handler name="CONSOLE">

                    <level name="INFO"/>

                    <formatter>

                        <pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>

                    </formatter>

                </console-handler>

                <periodic-rotating-file-handler name="FILE" autoflush="true">

                    <formatter>

                        <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>

                    </formatter>

                    <file relative-to="jboss.server.log.dir" path="server.log"/>

                    <suffix value=".yyyy-MM-dd"/>

                    <append value="true"/>

                </periodic-rotating-file-handler>

                <logger category="com.arjuna">

                    <level name="WARN"/>

                </logger>

                <logger category="org.apache.tomcat.util.modeler">

                    <level name="WARN"/>

                </logger>

                <logger category="org.jboss.as.config">

                    <level name="DEBUG"/>

                </logger>

                <logger category="sun.rmi">

                    <level name="WARN"/>

                </logger>

                <logger category="jacorb">

                    <level name="WARN"/>

                </logger>

                <logger category="jacorb.config">

                    <level name="ERROR"/>

                </logger>

                <root-logger>

                    <level name="INFO"/>

                    <handlers>

                        <handler name="CONSOLE"/>

                        <handler name="FILE"/>

                    </handlers>

                </root-logger>

            </subsystem>

             

            Here is a thread dump from the profiler:

            jboss_logging_thread_dump.PNG

             

            Thanks,

            Yaniv

            • 3. Re: Very slow performance using Log4J in JBoss EAP 6.1
              jaikiran pai Master

              So you have your own logger implementation which the delegates to log4j loggers? What does your code which does the log4j logger instantiation, look like?

              • 4. Re: Very slow performance using Log4J in JBoss EAP 6.1
                Tomaz Cerar Master

                What looks fishy in your profiling is that there are logging messages being logged/processed for level of "debug"

                but configuration you posted does not enable debug level anywhere.

                 

                I would asume that you have some logging.properties somewhere or log4.xml/properties and you configure log4j as part of your application and not on app server scope.

                 

                fact that you have excluded server provided log4j does not change any of this.

                so real question is what does other logging configuration you have in application look like.

                • 5. Re: Very slow performance using Log4J in JBoss EAP 6.1
                  Yaniv Peleg Newbie

                  You are right Tomaz we are excluding Log4J in the application jboss-deployment-structure.xml, we also have log4j.xml file in our application.

                  I investigated this issue more and found that the cause to this problem is the fact that we are using customized appender.

                  We are extending Log4J RollingFileAppender and adding some functionality.

                  When using Log4J appender the problem is solved.

                   

                  My question now is why extending RollingFileAppender cause performance issue?

                   

                  I tried to use empty appender that just extends RollingFileAppender and the problem persists.

                  Below there is the code of our customized appender and the log4J.xml content.

                   

                  package com.praxell.sys.log;

                   

                  import com.praxell.sys.util.CalenderManipulation;

                  import org.apache.log4j.RollingFileAppender;

                  import org.apache.log4j.spi.LoggingEvent;

                   

                  import java.io.File;

                  import java.util.Calendar;

                   

                  public class DatedFileAppender extends RollingFileAppender {

                   

                      ;

                      // ----------------------------------------------------- Instance Variables

                      protected CalenderManipulation calManipulation = CalenderManipulation.HOUR;

                      /**

                       * The directory in which log files are created.

                       * Without a leading slash, this is relative to the Tomcat home directory.

                       */

                      protected String m_directory = "logs";

                   

                      /**

                       * The prefix that is added to log file filenames.

                       */

                      protected String m_prefix = "tomcat.";

                   

                      /**

                       * The suffix that is added to log file filenames.

                       */

                      protected String m_suffix = ".log";

                   

                      /**

                       * The quantum of time which will be use to roll over the log

                       * can be as in CalenderManipulation

                       */

                      protected String m_quantum = "minute";

                   

                      /**

                       * The quantum of time which will be use to roll over the log

                       * can be Day,Hour,Minute,Second

                       */

                      protected String m_quantum_amount = "2";

                      /**

                       * The File representation of the directory in which log files are created.

                       */

                      protected File m_path = null;

                   

                      /**

                       * A calendar object for manipulating dates and times.

                       */

                      protected Calendar m_calendar = null;

                   

                      /**

                       * The number of milliseconds since 1/1/1970 when tomorrow starts (local time).

                       */

                      protected long m_tomorrow = 0L;

                   

                      // ----------------------------------------------------------- Constructors

                   

                      /** The default constructor will create a Tomcat FileLogger

                      with the following characteristics:

                      <ul>

                      <li>directory: "logs"</li>

                      <li>prefix: "tomcat."</li>

                      <li>suffix: ".log"</li>

                      </ul>

                      */

                      public DatedFileAppender() {

                   

                      }

                   

                      /** Creates a new <code>DatedFileAppender</code>

                      with the specified characteristics.

                   

                      @param directory the directory in which log files are created.

                      @param prefix the prefix that is added to log file filenames.

                      @param suffix the suffix that is added to log file filenames.

                      */

                      public DatedFileAppender(String directory, String prefix, String suffix, String quantum,String quantum_amount) {

                          m_directory = directory;

                          m_prefix = prefix;

                          m_suffix = suffix;

                          m_quantum = quantum;

                          calManipulation = CalenderManipulation.getMyself(m_quantum);

                          m_quantum_amount = quantum_amount;

                          int qAmount  = Integer.parseInt(m_quantum_amount);

                          calManipulation.setQuantumAmount(qAmount);

                          activateOptions();

                      }

                   

                      // ------------------------------------------------------------- Properties

                   

                   

                      /**

                       * Return the directory in which we create log files.

                       */

                      public String getDirectory() {

                          return m_directory;

                      }

                   

                      /**

                       * Set the directory in which we create log files.

                       *

                       * @param directory The new log file directory

                       */

                      public void setDirectory(String directory) {

                          m_directory = directory;

                      }

                   

                      /**

                       * Return the log file prefix.

                       */

                      public String getPrefix() {

                          return m_prefix;

                      }

                   

                      /**

                       * Set the log file prefix.

                       *

                       * @param prefix The new log file prefix

                       */

                      public void setPrefix(String prefix) {

                          m_prefix = prefix;

                      }

                   

                      /**

                       * Return the log file suffix.

                       */

                      public String getSuffix() {

                          return m_suffix;

                      }

                   

                      /**

                       * Set the log file suffix.

                       *

                       * @param suffix The new log file suffix

                       */

                      public void setSuffix(String suffix) {

                          m_suffix = suffix;

                      }

                   

                      public String getM_quantum() {

                          return m_quantum;

                      }

                   

                      public void setQuantum(String quantum) {

                          m_quantum = quantum;

                      }

                   

                      public String getQuantumAmount() {

                          return m_quantum_amount;

                      }

                   

                      public void setQuantumAmount(String quantum_amount) {

                          m_quantum_amount = quantum_amount;

                      }

                      // --------------------------------------------------------- Public Methods

                   

                   

                      /**

                         Called once all options have been set on this Appender.

                         Calls the underlying FileLogger's start() method.

                      */

                      public void activateOptions() {

                      if (m_prefix == null) {

                          m_prefix = "";

                      }

                      if (m_suffix == null) {

                          m_suffix = "";

                      }

                      if ((m_directory == null) || (m_directory.length() == 0)) {

                          m_directory = ".";

                      }

                          m_path = new File(m_directory);

                          if (!m_path.isAbsolute()) {

                              String base = System.getProperty("catalina.base");

                              if (base != null) {

                                  m_path = new File(base, m_directory);

                              }

                          }

                          m_path.mkdirs();

                          if (m_path.canWrite()) {

                              m_calendar = Calendar.getInstance();        // initialized

                          }

                          calManipulation = CalenderManipulation.getMyself(m_quantum);

                          int qAmount  = Integer.parseInt(m_quantum_amount);

                          calManipulation.setQuantumAmount(qAmount);

                          //close();

                          super.activateOptions();

                      }

                   

                      /**

                         Called by AppenderSkeleton.doAppend() to write a log message formatted

                         according to the layout defined for this appender.

                      */

                      public void append(LoggingEvent event) {

                          if(this.layout == null) {

                              errorHandler.error("No layout set for the appender named ["+ name+"].");

                              return;

                          }

                          if (this.m_calendar == null) {

                              errorHandler.error("Improper initialization for the appender named ["+ name+"].");

                              return;

                          }

                          long n = System.currentTimeMillis();

                          if (n >= m_tomorrow) {

                              m_calendar.setTimeInMillis(n);        // set Calendar to current time

                              String dateStamp = dateTimeStamp(m_calendar);    // convert to string "yyyy-mm-dd"

                              calManipulation.addQuantum(m_calendar);

                              m_tomorrow = m_calendar.getTimeInMillis();    // time in milliseconds when tomorrow starts

                   

                              File newFile = new File(m_path, m_prefix + dateStamp + m_suffix);

                              this.fileName = newFile.getAbsolutePath();

                              super.activateOptions();            // close current file and open new file

                          }

                          if(this.qw == null) {                // should never happen

                              errorHandler.error("No output stream or file set for the appender named ["+

                                         name+"].");

                              return;

                          }

                          subAppend(event);

                      }

                   

                      /**

                       * Formats a dateStamp as yyyy-mm-dd using a Calendar source object.

                       *

                       * @param calendar a Calendar containing the date to format.

                       *

                       * @return a String in the form "yyyy-yy-dd".

                       */

                      public static String dateStamp(Calendar calendar) {

                      int year = calendar.get(Calendar.YEAR);

                      int month = calendar.get(Calendar.MONTH) + 1;

                      int day = calendar.get(Calendar.DAY_OF_MONTH);

                      StringBuffer sb = new StringBuffer();

                      if (year < 1000) {

                          sb.append('0');

                          if (year < 100) {

                          sb.append('0');

                          if (year < 10) {

                              sb.append('0');

                          }

                          }

                      }

                      sb.append(Integer.toString(year));

                      fillMissingZero(month, sb);

                      fillMissingZero(day, sb);

                      return sb.toString();

                      }

                   

                      /**

                       * Formats a dateStamp as yyyy-mm-dd-HH-mm-ss using a Calendar source object.

                       *

                       * @param calendar a Calendar containing the date to format.

                       *

                       * @return a String in the form "yyyy-yy-dd".

                       */

                      public static String dateTimeStamp(Calendar calendar) {

                      int year = calendar.get(Calendar.YEAR);

                      int month = calendar.get(Calendar.MONTH) + 1;

                      int day = calendar.get(Calendar.DAY_OF_MONTH);

                      int hour  = calendar.get(Calendar.HOUR_OF_DAY);

                      int minute = calendar.get(Calendar.MINUTE);

                      int second = calendar.get(Calendar.SECOND);

                      StringBuffer sb = new StringBuffer();

                      if (year < 1000) {

                          sb.append('0');

                          if (year < 100) {

                          sb.append('0');

                          if (year < 10) {

                              sb.append('0');

                          }

                          }

                      }

                      sb.append(Integer.toString(year));

                      fillMissingZero(month, sb);

                      fillMissingZero(day, sb);

                      fillMissingZero(hour, sb);

                      fillMissingZero(minute, sb);

                      fillMissingZero(second, sb);

                      return sb.toString();

                      }

                   

                      /**

                       * Format the date to display HH instead H with leading zero and -

                       * @param month

                       * @param sb

                       */

                      protected static void fillMissingZero(int month, StringBuffer sb) {

                          sb.append('-');

                          if (month < 10) {

                              sb.append('0');

                          }

                          sb.append(Integer.toString(month));

                      }

                   

                      /**

                       * Sets a calendar to the start of tomorrow,

                       * with all time values reset to zero.

                       *

                       * <p>Takes advantage of the fact that the Java Calendar implementations

                       * are mercifully accommodating in handling non-existent dates. For example,

                       * June 31 is understood to mean July 1. This allows you to simply add one

                       * to today's day of the month to generate tomorrow's date. It also works

                       * for years, so that December 32, 2004 is converted into January 1, 2005.</p>

                       */

                      public static void tomorrow(Calendar calendar) {

                          int year = calendar.get(Calendar.YEAR);

                          int month = calendar.get(Calendar.MONTH);

                          int day = calendar.get(Calendar.DAY_OF_MONTH) + 1;

                          calendar.clear();            // clear all fields

                          calendar.set(year, month, day);        // set tomorrow's date

                      }

                  }

                   

                   

                  log4J.xml:

                   

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

                  <!--Gateway log configuation file build 11-->

                  <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

                  <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

                      <appender name="com.praxell.appender" class="com.praxell.sys.log.DatedFileAppender">

                          <param name="Append" value="true"/>

                          <param name="Directory" value="c:/dev/simulator/logs/"/>

                          <param name="Prefix" value="simulatorserv.dev."/>

                          <param name="Suffix" value=".log"/>

                          <param name="Quantum" value="DAY"/>

                          <param name="QuantumAmount" value="1"/>

                          <param name="MaxFileSize" value="5000000"/>

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

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

                              <param name="ConversionPattern" value="%d %-5p %m [%t]%n"/>

                          </layout>

                      </appender>

                   

                      <category name="com.praxell">

                          <priority value="TRACE"/>

                          <appender-ref ref="com.praxell.appender"/>

                      </category>

                      <root>

                          <priority value="INFO"/>

                      </root>

                  </log4j:configuration>

                  • 6. Re: Very slow performance using Log4J in JBoss EAP 6.1
                    Tomaz Cerar Master

                    Yaniv Peleg wrote:

                     

                     

                        <category name="com.praxell">

                            <priority value="TRACE"/>

                            <appender-ref ref="com.praxell.appender"/>

                        </category>

                    Hi,

                     

                    This is your problem

                     

                    Basicly you are logging enormous ammounts of log messages to your appender, probably noting is wrong with appender, but just fact that you are logging probably tens of thousand messages per second.

                    and your appender is writing them to file synchornusly, so basicly you are limited by performance of your disk more than anything else.

                     

                    i would recommend you two things

                    1) lower amount of logging to at least INFO if possible

                    2) use async appender to do writing to file asynchrously in separte thread.

                    3) improve your appender to support buffer, so it would be writing more than one msg at time. (log4j file appender has bufferSize property)

                     

                    if 1) is not possible, at least do 2) & 3)

                    to use async appender it is quite simple, just change configuration to something like this

                     

                     

                    <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

                     

                        <appender name="com.praxell.appender" class="com.praxell.sys.log.DatedFileAppender">

                            <param name="Append" value="true"/>

                            <param name="Directory" value="c:/dev/simulator/logs/"/>

                            <param name="Prefix" value="simulatorserv.dev."/>

                            <param name="Suffix" value=".log"/>

                            <param name="Quantum" value="DAY"/>

                            <param name="QuantumAmount" value="1"/>

                            <param name="MaxFileSize" value="5000000"/>

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

                            <param name="BufferSize" value="100"/>

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

                                <param name="ConversionPattern" value="%d %-5p %m [%t]%n"/>

                            </layout>

                        </appender>

                        <appender name="async" class="org.apache.log4j.AsyncAppender">

                            <param name="BufferSize" value="500"/>

                            <appender-ref ref="com.praxell.appender"/>

                        </appender>

                       

                        <category name="com.praxell">

                            <priority value="TRACE"/>

                           <appender-ref ref="async"/>

                        </category>

                        <root>

                            <priority value="INFO"/>

                        </root>

                     

                    </log4j:configuration>

                     

                    that should improve your performance.

                     

                    --

                    tomaz

                    1 of 1 people found this helpful
                    • 7. Re: Very slow performance using Log4J in JBoss EAP 6.1
                      Yaniv Peleg Newbie

                      Thank you for your response Tomaz, it has useful info.

                       

                      We currently change the Log4j appender from our custom appender to Log4j standard appender.

                      We also removed the "console" appender-ref from the log4j.xml.

                      This seem to solve the problem and performance is satisfying now.

                       

                      Thanks

                      Yaniv

                      1 of 1 people found this helpful