Name: gm110360 Date: 04/16/2003


See incident 153528.

FULL PRODUCT VERSION :
----------
java version "1.3.0_01"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.3.0_01)
Java HotSpot(TM) Client VM (build 1.3.0_01, mixed mode)
----------
java version "1.4.0"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.0-b92)
Java HotSpot(TM) Client VM (build 1.4.0-b92, mixed mode)


FULL OPERATING SYSTEM VERSION :

Windows 98 [Version 4.10.2222]

A DESCRIPTION OF THE PROBLEM :
===BACKGROUND===

I have a real world app that performs full frame animation,
which works remarkably well in Java 1.1. However, when the
app is run under Java 1.3 and 1.4, it looks horrible.
There are noticeable pauses in the application and there is
a significant reduction in the frame rate.

The attached sample application is the result of tracking
down the performance problems. It uses a frame size of
400x300 (120,000 pixels). So, assuming you want to use
Java to perform 'full-frame' animation, I am immediately
interested in knowing the following:

(1) IMAGE DRAW SPEED: How fast can Java bitblt an image
over and over to the screen. In other words, how well does
Java integrate into an OS and use native images.

(2) MAXIMUM FPS: Case 1 above, but with me telling Java
that it needs to recreate the entire image. This will
provide an 'upper bound' on the maximum fps (frame per
second) because I have told Java to recreate the entire
image, as if I have modified all pixels, but I have *not*
modified any pixels. This tests how fast Java can take an
integer pixel buffer and convert it into a native image.

(3) REALISTIC FPS: Case 2 above, but with all pixels in the
image really modified using a really simple algorithm.
This will give us a realistic upper bound on a frames per
second.

===THE TESTS===

All of the following tests were run on a Pentium III 650Mhz
laptop with 256MB memory (but each Java VM was run without
memory options, so the VM default heap size was used). The
video setup is a 8MB RAGE LT PRO AGP 2X (Mach64 chip set)
running in 24-bit true color mode.

Each test is run 1000 times and the elapsed time measured.
The total time is displayed as well as a calculated fps.
Terms used after each test:

  draw: the image is drawn
  flush: the image is regenerated using the 1.0 flush()
  newPixels: the image is regenerated using the 1.1
newPixels()
  modpix: the pixel array is modified

===Test1===

The program run under Sun's JDK 1.0:

  === Sun Microsystems Inc. 1.0.2 ===
  3070 ms 325 fps - draw
  16420 ms 60 fps - flush draw
  87050 ms 11 fps - modpix flush draw

Analysis: It takes 3.07 ms (3070/1000) to draw the image.
It takes 13.35 ms ((16420-3070)/1000) for Java to convert
the 120,000 pixel RGB array into a native image. It takes
70.63 ms ((87050-16420)/1000) for Java to modify the
120,000 element pixel array (or 383 clock cycles per array
element).

===Test2===

The program run under Sun's JDK 1.1:

  === Sun Microsystems Inc. 1.1.7B ===
  2860 ms 349 fps - draw
  16370 ms 61 fps - flush draw
  15050 ms 66 fps - newPixels draw
  20100 ms 49 fps - modpix flush draw
  18510 ms 54 fps - modpix newPixels draw

Analysis: It takes 2.86 (2860/1000) ms to draw the image.
It takes 13.51 ms ((16370-2860)/1000) for Java to convert
the 120,000 pixel RGB array into a native image. It takes
3.46 ms ((18510-15050)/1000) for Java to modify the 120,000
element pixel array (or 18.7 clock cycles per array
element).

So we can see a dramatic improvement from the JIT VM.
Also, using newPixels() instead of flush() to notify Java
of a frame update can shave 1.32 ms ((16370-15050)/1000)
off of each frame.

===Test3===

The program is run under Sun's JRE 1.3:

  === Sun Microsystems Inc. 1.3.0_01 (mixed mode) ===
  3620 ms 276 fps - draw
  32350 ms 30 fps - flush draw
  12250 ms 81 fps - newPixels draw
  37240 ms 26 fps - modpix flush draw
  17190 ms 58 fps - modpix newPixels draw

Analysis: It takes 3.62 (3620/1000) ms to draw the image.
It takes 28.73 ms ((32350-3620)/1000) for Java to convert
the 120,000 pixel RGB array into a native image. It takes
4.94 ms ((17190-12250)/1000) for Java to modify the 120,000
element pixel array (or 26.8 clock cycles per array
element).

BUG1: Why is there a huge performance hit when using flush
() to notify Java of a frame update. It takes 97% longer
than Java 1.1 and Java 1.0.

BUG2: Why does the image draw in Java 1.3 take 27% (3.62 vs
2.86) longer than Java 1.1? And more importantly, why does
it take 18% (3.62 vs 3.07) longer than in Java 1.0.2?

BUG3: Why does it appear that the JIT in Java 1.3 takes 43%
(26.8 vs 18.7 clock cycles) longer to modify each integer
in the pixel array?

===Test4===

The program is run under Sun's JRE 1.4:

  === Sun Microsystems Inc. 1.4.0 (mixed mode) ===
  2090 ms 478 fps - draw
  37510 ms 26 fps - flush draw
  11260 ms 88 fps - newPixels draw
  35590 ms 28 fps - modpix flush draw
  15600 ms 64 fps - modpix newPixels draw

Analysis: It takes 2.09 ms (2090/1000) to draw the image.
It takes 35.42 ms ((37510-2090)/1000) for Java to convert
the 120,000 pixel RGB array into a native image. It takes
4.34 ms ((15600-11260)/1000) for Java to convert the
120,000 pixel RGB array into a native image (23.5 clock
cycles per array element).

BUG1 GETS WORSE: Java 1.4 now takes 129% longer than Java
1.1 or Java 1.0. What is going on?

BUG2 RESOLVED: Java 1.4 appears to fix the Java 1.3 problem
of image draw times.

BUG3 AGAIN: Why does it appear that the JIT in Java 1.4
takes 25% (23.5 vs 18.7 clock cycles) longer to modify each
integer in the pixel array (than Java 1.1)?

Since there were noticeable 'delays' (jerks) in the
application, could the garbage collector be at fault? The
app was run with a huge heap size, which made no
difference. Then, the app was run with the '-Xincgc'
option...

===Test5===

Same as Test4, but with '-Xincgc' option:

  === Sun Microsystems Inc. 1.4.0 (mixed mode) ===
  2090 ms 478 fps - draw
  18340 ms 54 fps - flush draw [MUCH BETTER]
  11040 ms 90 fps - newPixels draw
  23180 ms 43 fps - modpix flush draw [MUCH BETTER]
  15870 ms 63 fps - modpix newPixels draw

Analysis: The garbage collector appears to be at fault and
the cause of the huge degradation in the 'flush()'
performance problems, but can we see that...

===REGENONLY===

  To examine the error test case more closely, the program
allows a command line argument of "regenonly", which then
runs only a single problem test case:

  === Sun Microsystems Inc. 1.4.0 (mixed mode) ===
  37020 ms 27 fps - flush draw

When run this way, and with '-Xloggc:file' turned on, it is
obvious that something is very wrong because the GC log
file has over 500 lines in it, with every other GC a 'full'
GC. Namely, line after line of something that looks like:

  [Full GC 4600K->2722K(5588K), 0.0831434 secs]
  [GC 4609K->4600K(5588K), 0.0040203 secs]
  [Full GC 4600K->2722K(5588K), 0.0827511 secs]
  [GC 4609K->4600K(5588K), 0.0040254 secs]
  [Full GC 4600K->2722K(5588K), 0.0829498 secs]

When all the 'secs' in this log file are added up, the
result is 21962 ms. But with the entire test taking 37020
ms, that means Java is spending 59% of the test time in the
garbage collector. What is causing so many 'Full GC'?

Running in '-Xincgc' mode results in:

  === Sun Microsystems Inc. 1.4.0 (mixed mode) ===
  19170 ms 52 fps - flush draw

and all the GC 'secs' add up to 1726 ms, or just 9% of the
total test run time.

So, it looks like something is very wrong with the default
garbage collector in Java 1.3 and Java 1.4

===CONCLUSION===

One of the things that I liked about Java 1.1 is that you
really could just code to the Java API and not worry about
the Java VM. With the Java 1.1 JIT VM, Java ran nice.

(1) However, with Java 1.3 and Java 1.4, there is now
strong evidence that you will always see jerky displays and
that in some cases, the garbage collector has taken a huge
turn for the worse and that it will dramatically negatively
affect the performance of your application, whereas the
same application (bytecode) running under an earlier Java
VM runs great.

(2) There is also some evidence to suggest that the 1.3/1.4
JIT VM is not performing as well as the 1.1 JIT VM (BUG3
above).


REGRESSION. Last worked in version 1.1.8

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
please review the detailed description, running the sample
code as needed.

This bug can be reproduced always.

---------- BEGIN SOURCE ----------
import java.awt.*;
import java.awt.image.*;

public class GraphicsTest extends Panel implements Runnable {
    private static final int F_ANIMATE=1;
    private static final int F_REGEN=2;
    private static final int F_MODPIX=4;
    private static final int SIZEX=400;
    private static final int SIZEY=300;
    private static final int EX=2;
    private Label iDesc = new Label("",Label.CENTER);
    private String m_testname;

    //----------------------------------------------------------------------
    public static void main( String[] args ) {
        String info = vminfo();
        System.out.println( "=== "+vminfo()+" ===" );
        Frame f = new Frame(info);
        String testname=args.length>0?args[0]:null;
        GraphicsTest test = new GraphicsTest(testname);
        f.add( "North", test.iDesc );
        f.add( "Center", test);
        f.pack();
        f.show();
        test.go();
        System.exit(0);
        }
    //----------------------------------------------------------------------
    private static String vminfo() {
        String vendor = System.getProperty("java.vendor");
        String version = System.getProperty("java.version");
        String info = System.getProperty("java.vm.info");
        return vendor+" "+version+((info!=null)?" ("+info+")":"");
        }
    //----------------------------------------------------------------------
    private GraphicsTest( String testname ) {
        m_testname = testname;
        setBackground( Color.red );
        }
    //----------------------------------------------------------------------
    private void go() {
        Thread th = new Thread(this);
        th.start();
        try { th.join(); } catch (Exception e) {}
        }
    //----------------------------------------------------------------------
    public Dimension preferredSize() {
        return minimumSize();
        }
    //----------------------------------------------------------------------
    public Dimension minimumSize() {
        return new Dimension(SIZEX+EX+EX,SIZEY+EX+EX);
        }
    //----------------------------------------------------------------------
    public void run() {
        if ("regenonly".equals(m_testname)) {
            runTest( F_REGEN );
            }
        else {
            boolean bJava10 = System.getProperty("java.version").startsWith
("1.0");
            runTest( 0 );
            runTest( F_REGEN );
            if (!bJava10) {
                runTest( F_REGEN | F_ANIMATE );
                }
            runTest( F_REGEN | F_MODPIX );
            if (!bJava10) {
                runTest( F_REGEN | F_MODPIX | F_ANIMATE );
                }
            }
        }
    //----------------------------------------------------------------------
    private void runTest( int flag ) {
        boolean bAnimated = (flag&F_ANIMATE)!=0;
        boolean bRegen = (flag&F_REGEN)!=0;
        boolean bModPix = (flag&F_MODPIX)!=0;

        int NTIMES=1000;
        int xx = EX;
        int yy = EX;

        int pixels[] = new int[SIZEX*SIZEY];
        for (int loop=0; loop<pixels.length; ++loop) {
            int r = (loop%SIZEX)*255/SIZEX;
            int g = (loop/SIZEX)*255/SIZEY;
            pixels[loop] = 0xFF000000 | (r<<16) | (g<<8);
            }

        String desc=(bModPix?" modpix":"") + (bRegen?(bAnimated?" newPixels":"
flush"):"") + " draw";
        iDesc.setText(desc);
        repaint();
        try { Thread.sleep(1000); } catch (Exception e) {}
        System.gc();

        MemoryImageSource mis = new MemoryImageSource(SIZEX, SIZEY, pixels, 0,
SIZEX);
        if (bAnimated) {
            mis.setAnimated(true);
            }
        Image image = createImage(mis);
        Graphics g = getGraphics();
        g.drawImage( image, xx, yy, null );

        long start = sync();
        for (int iter=0; iter<NTIMES; ++iter) {
            if (bModPix) {
                int len = pixels.length;
                for (int loop=0; loop<len; ++loop) {
                    pixels[loop] = 0xFF000000 | (pixels[loop]+0x00010101);
                    }
                }
            if (bRegen) {
                if (bAnimated) {
                    mis.newPixels();
                    }
                else {
                    image.flush();
                    }
                }
            g.drawImage( image, xx, yy, null );
            if ((iter%100)==0) {
                System.out.print(".");
                System.out.flush();
                }
            }
        long ms = Math.max(1,System.currentTimeMillis()-start);
        System.out.println( " "+ms+" ms "+(NTIMES*1000/ms)+" fps -"+desc );
        g.dispose();
        }
    //----------------------------------------------------------------------
    private long sync() {
        long start=System.currentTimeMillis();
        long now;
        while ((now=System.currentTimeMillis())==start) {
            }
        return now;
        }
    }

---------- END SOURCE ----------

CUSTOMER WORKAROUND :
Recommend to my customers to stay with the Java 1.1 VM
instead of installing Java 1.3 or Java 1.4 due to the jerky
GUI and bad performance of 1.3/1.4
(Review ID: 148125)
======================================================================