[prev in list] [next in list] [prev in thread] [next in thread] 

List:       log4j-dev
Subject:    DO NOT REPLY [Bug 35052]  New:  -
From:       bugzilla () apache ! org
Date:       2005-05-25 2:47:37
Message-ID: 20050525024737.02C7417F () ajax ! apache ! org
[Download RAW message or body]

DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG·
RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT
<http://issues.apache.org/bugzilla/show_bug.cgi?id=35052>.
ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND·
INSERTED IN THE BUG DATABASE.

http://issues.apache.org/bugzilla/show_bug.cgi?id=35052

           Summary: Problem with String.intern() in CategoryKey
           Product: Log4j
           Version: 1.2
          Platform: Other
        OS/Version: All
            Status: NEW
          Severity: major
          Priority: P2
         Component: Other
        AssignedTo: log4j-dev@logging.apache.org
        ReportedBy: wsshek@taifook.com


I am facing a strange performance problem in our production environment when I
use the conversion pattern "C:L" to output class name and line number.  I DO
expect the performance to be slower but what I got was a gradual slowdown where
our application would literally slow down to a grinding halt after a few days of
running.  The application would get back to normal if I force it to run a full
GC.  After working with HP JVM engineer on this issue, the problem was found to
be the use of String.intern() in CategoryKey class AND the use of
java.lang.Throwable.getStackTraceElement() (to get line number and classname). 
The use of intern() causes the StringTable in JVM (in the Permanent heap) to
fill up very quickly as each call to Logger.getLogger() will create an instance
of CategoryKey object.  The method getStackTraceElement()  will use the
StringTable for lookup and it will take longer for it to run as time goes. The
StringTable may contain Strings which are not live in the java program. 
However, the collection of Strings in StringTable is done only in Full GC. 
That's the reason a Full GC recovered the application performance. I have
attached a sample program that will reproduce the problem easily on any
platforms using 1.4.2 JVM.

My question to the logging group is whether the call to intern() is necessary in
creating the CategoryKey? Is it used to speed up hash lookup?  This seems like a
VM bug but I doubt it will get fixed by Sun anytime soon and I am worried that
other system will experience the same problem I do. (took us a few weeks to
figure out the problem!)

My workaround is to adopt the use of Apache Common Logging API which will cache
each instance of logger and eliminate the need to call Logger.getLogger() which
in turn eliminate the need for CategoryKey to call String.intern().

The code that will duplicate the problem is here, run it as followed:

"java --XX:MaxPermSize=512m -XX:PermSize=512m st" and telnet to port 12345 to
trigger garbage collection


import java.io.*;
import java.net.*;

public class st {
  public static void main(String[] args) {
    gc_monitor_thread gcm = new gc_monitor_thread();
    gcm.start();
    trace_thread  tt = new trace_thread();
    tt.start();
    for (int i = 0; i < 4; i++) {
      string_thread st = new string_thread();
      st.start();
    }
  }
}

class string_thread extends Thread {
  boolean alive = false;
  String tstr = "abc";
  public void run() {
    alive = true; 
    long lcnt = 0;
    int  mcnt = 0;
    while (alive) {
      String s = getName() + Long.toHexString(lcnt);
      if (s.equals(tstr)) mcnt++;
      s.intern();
      lcnt++; 
      if (lcnt % 100000 == 0) {
        try { Thread.sleep(10); } catch (InterruptedException ie) {}
      }
    }
  }
}

class trace_thread extends Thread {
  boolean alive = false;
  public void run() {
    alive = true;
    while (alive) {
      long t0 = System.currentTimeMillis();
      for (int i = 0; i < 100; i++) {
        do_stack_trace_op();
      }
      long t1 = System.currentTimeMillis();
      
      System.out.println("time for trace: " + (t1 - t0));
      try { Thread.sleep(1000); } catch (InterruptedException ie) {}
    }
  }
  void do_stack_trace_op() {
    Throwable t = get_throwable();
    PrintWriter pw = null;
    // try {
      pw = new PrintWriter(new StringWriter());
      t.printStackTrace(pw);
    // } catch (IOException ioe) {
    //   System.out.println(ioe);
    //   System.exit(2);
    // }
  }
  Throwable get_throwable() {
    return new Throwable("dummy");
  }
}

class gc_monitor_thread extends Thread {
  boolean alive = false;
  public void run() {
    alive = true;
    int try_limit = 100;
    int try_count = 0;
    while (alive) {
      int pn = 12345;
      ServerSocket ss = null;
      while (ss == null) {
        try {
          ss = new ServerSocket(pn);
        } catch (IOException ioe) {
          pn++;
          try_count++;
          if (try_count > try_limit) {
            System.out.println("too many failures while creating server socket.");
            System.out.println("exitting...");
            System.exit(2);
          }
        }
      }      

      if (ss == null) {
        System.out.println("unexpected situation.  server socket null");
        System.exit(3);
      }

      System.out.println("GC monitor thread started on port " +
        ss.getLocalPort() + ". Connect to this port to run GC.");

      while (alive) {
        Socket s = null;
        try {
          s = ss.accept(); 
        } catch (IOException ioe) {
          System.out.println("GC monitor thread got an exception in accept.");
          ioe.printStackTrace();
          System.exit(4);
        }

        if (s == null) {
          System.out.println("accept returned a null Socket.");
          System.exit(5); 
        }
        System.out.print("Performing System.gc()...");
        System.out.flush();
        System.gc();
        System.out.println("done.");
        try {
          s.close(); 
        } catch (IOException ioe) {
          System.out.println("error while closing socket.");
          ioe.printStackTrace();
        }
      }
    }
  }
}


Vincent

-- 
Configure bugmail: http://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org

[prev in list] [next in list] [prev in thread] [next in thread]