Return-Path: 
 <general-return-477-apmail-logging-general-archive=logging.apache.org@logging.apache.org>
Delivered-To: apmail-logging-general-archive@www.apache.org
Received: (qmail 77990 invoked from network); 11 May 2005 09:12:37 -0000
Received: from hermes.apache.org (HELO mail.apache.org) (209.237.227.199)
  by minotaur.apache.org with SMTP; 11 May 2005 09:12:37 -0000
Received: (qmail 45748 invoked by uid 500); 11 May 2005 09:16:04 -0000
Delivered-To: apmail-logging-general-archive@logging.apache.org
Received: (qmail 45673 invoked by uid 500); 11 May 2005 09:16:03 -0000
Mailing-List: contact general-help@logging.apache.org; run by ezmlm
Precedence: bulk
list-help: <mailto:general-help@logging.apache.org>
list-unsubscribe: <mailto:general-unsubscribe@logging.apache.org>
List-Post: <mailto:general@logging.apache.org>
Reply-To: "Logging General" <general@logging.apache.org>
List-Id: <general.logging.apache.org>
Delivered-To: mailing list general@logging.apache.org
Received: (qmail 45643 invoked by uid 99); 11 May 2005 09:16:03 -0000
X-ASF-Spam-Status: No, hits=0.0 required=10.0
	tests=
X-Spam-Check-By: apache.org
Received-SPF: pass (hermes.apache.org: local policy)
Received: from Unknown (HELO server.taifook.net) (202.22.244.17)
  by apache.org (qpsmtpd/0.28) with ESMTP; Wed, 11 May 2005 02:16:03 -0700
Received: from tfsmail.tfprod.taifook.com ([192.168.96.154])
	by server.taifook.net (8.11.7/8.11.7) with ESMTP id j4B9C3S10909
	for <general@logging.apache.org>; Wed, 11 May 2005 17:12:04 +0800
Received: by tfsmail.tfprod.taifook.com with Internet Mail Service
 (5.5.2657.72)
	id <KK30KWM6>; Wed, 11 May 2005 17:12:03 +0800
Message-ID: 
 <ED05A0F2CAC79244A0FF6D820DD1272D563F19@tfsmail.tfprod.taifook.com>
From: Vincent Shek <wsshek@taifook.com>
To: Logging General <general@logging.apache.org>
Subject: Problem with String.intern() in CategoryKey
Date: Wed, 11 May 2005 17:11:53 +0800
MIME-Version: 1.0
X-Mailer: Internet Mail Service (5.5.2657.72)
Content-Type: multipart/mixed;
	boundary="----_=_NextPart_000_01C55609.7933F5F0"
X-Virus-Checked: Checked
X-Spam-Rating: minotaur.apache.org 1.6.2 0/1000/N

This message is in MIME format. Since your mail reader does not understand
this format, some or all of this message may not be legible.

------_=_NextPart_000_01C55609.7933F5F0
Content-Type: text/plain;
	charset="iso-8859-1"

Hi all,

I hesitate to send this email to this list as opposed to Bugzilla but I
would to get some opinion here first before I do so.  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!)

TIA for your help,

Vincent Shek


This email is confidential. If you are not the intended recipient, please
notify the sender immediately.  The unauthorized use, disclosure,
dissemination or copying of this email is prohibited.  Emails are
susceptible to alteration and their integrity cannot be guaranteed. Tai Fook
Securities Group " Tai Fook" does not accept liability for damage caused by
this email.
  


------_=_NextPart_000_01C55609.7933F5F0
Content-Type: application/octet-stream;
	name="st.java"
Content-Transfer-Encoding: quoted-printable
Content-Disposition: attachment;
	filename="st.java"

import java.io.*;=0A=
import java.net.*;=0A=
=0A=
public class st {=0A=
  public static void main(String[] args) {=0A=
    gc_monitor_thread gcm =3D new gc_monitor_thread();=0A=
    gcm.start();=0A=
    trace_thread  tt =3D new trace_thread();=0A=
    tt.start();=0A=
    for (int i =3D 0; i < 4; i++) {=0A=
      string_thread st =3D new string_thread();=0A=
      st.start();=0A=
    }=0A=
  }=0A=
}=0A=
=0A=
class string_thread extends Thread {=0A=
  boolean alive =3D false;=0A=
  String tstr =3D "abc";=0A=
  public void run() {=0A=
    alive =3D true; =0A=
    long lcnt =3D 0;=0A=
    int  mcnt =3D 0;=0A=
    while (alive) {=0A=
      String s =3D getName() + Long.toHexString(lcnt);=0A=
      if (s.equals(tstr)) mcnt++;=0A=
      s.intern();=0A=
      lcnt++; =0A=
      if (lcnt % 100000 =3D=3D 0) {=0A=
        try { Thread.sleep(10); } catch (InterruptedException ie) {}=0A=
      }=0A=
    }=0A=
  }=0A=
}=0A=
=0A=
class trace_thread extends Thread {=0A=
  boolean alive =3D false;=0A=
  public void run() {=0A=
    alive =3D true;=0A=
    while (alive) {=0A=
      long t0 =3D System.currentTimeMillis();=0A=
      for (int i =3D 0; i < 100; i++) {=0A=
        do_stack_trace_op();=0A=
      }=0A=
      long t1 =3D System.currentTimeMillis();=0A=
      =0A=
      System.out.println("time for trace: " + (t1 - t0));=0A=
      try { Thread.sleep(1000); } catch (InterruptedException ie) {}=0A=
    }=0A=
  }=0A=
  void do_stack_trace_op() {=0A=
    Throwable t =3D get_throwable();=0A=
    PrintWriter pw =3D null;=0A=
    // try {=0A=
      pw =3D new PrintWriter(new StringWriter());=0A=
      t.printStackTrace(pw);=0A=
    // } catch (IOException ioe) {=0A=
    //   System.out.println(ioe);=0A=
    //   System.exit(2);=0A=
    // }=0A=
  }=0A=
  Throwable get_throwable() {=0A=
    return new Throwable("dummy");=0A=
  }=0A=
}=0A=
=0A=
class gc_monitor_thread extends Thread {=0A=
  boolean alive =3D false;=0A=
  public void run() {=0A=
    alive =3D true;=0A=
    int try_limit =3D 100;=0A=
    int try_count =3D 0;=0A=
    while (alive) {=0A=
      int pn =3D 12345;=0A=
      ServerSocket ss =3D null;=0A=
      while (ss =3D=3D null) {=0A=
        try {=0A=
          ss =3D new ServerSocket(pn);=0A=
        } catch (IOException ioe) {=0A=
          pn++;=0A=
          try_count++;=0A=
          if (try_count > try_limit) {=0A=
            System.out.println("too many failures while creating server =
socket.");=0A=
            System.out.println("exitting...");=0A=
            System.exit(2);=0A=
          }=0A=
        }=0A=
      }      =0A=
=0A=
      if (ss =3D=3D null) {=0A=
        System.out.println("unexpected situation.  server socket =
null");=0A=
        System.exit(3);=0A=
      }=0A=
=0A=
      System.out.println("GC monitor thread started on port " +=0A=
        ss.getLocalPort() + ". Connect to this port to run GC.");=0A=
=0A=
      while (alive) {=0A=
        Socket s =3D null;=0A=
        try {=0A=
          s =3D ss.accept(); =0A=
        } catch (IOException ioe) {=0A=
          System.out.println("GC monitor thread got an exception in =
accept.");=0A=
          ioe.printStackTrace();=0A=
          System.exit(4);=0A=
        }=0A=
=0A=
        if (s =3D=3D null) {=0A=
          System.out.println("accept returned a null Socket.");=0A=
          System.exit(5); =0A=
        }=0A=
        System.out.print("Performing System.gc()...");=0A=
        System.out.flush();=0A=
        System.gc();=0A=
        System.out.println("done.");=0A=
        try {=0A=
          s.close(); =0A=
        } catch (IOException ioe) {=0A=
          System.out.println("error while closing socket.");=0A=
          ioe.printStackTrace();=0A=
        }=0A=
      }=0A=
    }=0A=
  }=0A=
}=0A=

------_=_NextPart_000_01C55609.7933F5F0--