JDK-4990399 : JDWP: JFrame construction performance regression over 1.4.2 (method entry err?)
  • Type: Bug
  • Component: client-libs
  • Sub-Component: javax.swing
  • Affected Version: 5.0
  • Priority: P4
  • Status: Closed
  • Resolution: Won't Fix
  • OS: generic
  • CPU: generic
  • Submitted: 2004-02-06
  • Updated: 2016-01-20
  • Resolved: 2016-01-20
Related Reports
Relates :  
JDK-5106661 - XP L&F does not work on Windows Vista (Longhorn) - needs to use uxtheme api
Relates :  
JDK-4911240 - Reduce init time for Java2D rendering
Relates :  
JDK-4969969 - JDWP: Performance regression on using debbuger (step speed improvements)
Relates :  
JDK-4795932 - RFE: Java 2D should locate fonts by using the windows registry
Relates :  
JDK-5027400 - Creating UI with WindowsLookAndFeel is slow
Description
CAP bug report was originally 4969969. Since we were able to make some
basic improvements on the debugger side, we have kept that bug number,
this bug is being filed to track the method call increase
in JFrame construction.

It appears that the initial JFrame constructor is causing many more
methods to be executed than in 1.4.2, from 15,000 methods to 377,000
methods. Since the debugger 'step' functionality monitors the method
entry events, it experienced a slowdown.

This increase in method calls may be worth some investigation.

=======================================================================


Original debugger bug filed:

###@###.### 2003-12-17

J2SE Version (please include all output from java -version flag):
    java version "1.5.0-beta"
    Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0-beta-b30)
    Java HotSpot(TM) Client VM (build 1.5.0-beta-b30, mixed mode) 

Does this problem occur on J2SE 1.3 or 1.4.x?  Yes / No (pick one) 
    No, 1.4.2 only takes 1 sec. b30 takes 18 sec.

Operating System Configuration Information (be specific): 
    Windows XP (version 5.1 Service Pack 1 (Build 2600)) 

Hardware Configuration Information (be specific): 

    Platform configuration:

    CPU:     Intel 32bit Single Processor
    Processor Speed: 1893 MHz

    Operating System:
    Windows XP (version 5.1 Service Pack 1 (Build 2600))

    DirectX version: DirectX 8.1 or greater

    DirectX display devices:
    Device 0:
      Resolution (width x height x depth): 1024 x 768 x 32
      Device driver nv4_disp.dll version 6.13.10.3638

    GDI display devices:
    Primary: Name = \\.\DISPLAY1, Description = NVIDIA GeForce4 460 Go (Toshiba)

Bug Description: 

   Testing the VisualMust debugger with B30, there is a problem :
   when running the application step by step and entering into a "super()"
   to create a frame for example, the step takes 18 seconds and 100 % CPU 
   (with a Pentium 4, 1900 MHz). With the same machine, with Java 1.4.2. 
   the step takes less than 1 second.

Steps to Reproduce (be specific):
  - unzip VisualMust.zip
  - run java -Xmx128m -classpath ./VisualMust.jar;./VisualMustDocs.jar;./JbcBeansEvaluation.jar;c:/jdk/lib/tools.jar VisualMust
Comments
No further concern from the CAP member.
20-01-2016
EVALUATION If we are making more method calls in 1.5 than we were in 1.4.2, it doesn't appear to effect execution time/speed. I used the following test case: // Test to measure time to create JFrame import javax.swing.*; public class JFrameCreateTime { public static void main(String[] args) { JFrame f; long start, end; start = System.currentTimeMillis(); f = new JFrame("JFrame"); end = System.currentTimeMillis(); System.out.println("JFrame creation took " + (end - start) + " ms"); } } On Solaris, 1.5 shows a marked improvement over 1.4.2: 1.4.2 : ~1805 ms 1.5b38: ~706 ms Linux also shows an improvement: 1.4.2 : ~2090 ms 1.5b37: ~1360 ms Values are the mean average of 6 runs after discarding the first run. If this bug is ONLY visible on Win XP, that would indicate a bug in platform-dependant code, such as 2D or AWT. If submitter can also reproduce the problem on Solaris/Linux, we will need a test case which shows this. ###@###.### 2004-02-17 ###@###.### asks in the "Comments" section: "Could this be related to bug 4911240?" It appears there could be some relation. ###@###.### 2004-02-17 Name: drR10255 Date: 03/01/2004 I have tested example on Windows XP (CPU: Pentium 4 2.66GHz, 1.00 GB of RAM). I haven't noticed a big difference between JDK 1.4.2b25 and Tiger build 40. In both cases test usually shows time between 185 ms and 205 ms. So, I think, without debugger all is OK. ====================================================================== I instrumented the MethodEntry handler so that it captures the thread stack trace as method entry time. >90% of the method entry events in 1.5.0 stem from the font initialization - here's a sample stack trace :- java.nio.HeapByteBuffer._get java.nio.Bits.getShortB java.nio.ByteBufferAsShortBufferB.get sun.font.TrueTypeFont.initNames sun.font.TrueTypeFont.init sun.font.TrueTypeFont.<init> sun.font.FontManager.registerFontFile sun.font.FontManager.initialiseDeferredFont sun.font.FontManager.findDeferredFont sun.font.FontManager.findFont2D sun.font.FontManager.findFont2D java.awt.Font.getFont2D sun.font.FontManager.getFont2D sun.font.FontManager.fontSupportsDefaultEncoding com.sun.java.swing.plaf.windows.WindowsLookAndFeel$WindowsFontProperty.configureValue com.sun.java.swing.plaf.windows.DesktopProperty.createValue javax.swing.UIDefaults.getFromHashtable javax.swing.UIDefaults.get javax.swing.MultiUIDefaults.get javax.swing.UIDefaults.getFont javax.swing.UIManager.getFont javax.swing.LookAndFeel.installColorsAndFont javax.swing.plaf.basic.BasicPanelUI.installDefaults javax.swing.plaf.basic.BasicPanelUI.installUI javax.swing.JComponent.setUI javax.swing.JPanel.setUI javax.swing.JPanel.updateUI javax.swing.JPanel.<init> javax.swing.JPanel.<init> javax.swing.JPanel.<init> javax.swing.JRootPane.createGlassPane javax.swing.JRootPane.<init> javax.swing.JFrame.createRootPane javax.swing.JFrame.frameInit javax.swing.JFrame.<init> junk2_Abstract.<init> junk2.<init> junk2.main The font initialization is different in 1.5.0 and as a result the first step into the JFrame constructor results in about 370,000 step events to the debugger. In 1.4.2 there are about 14-15,000 step events. So this is not a debugger regression. In fact the step performance is better in 1.5.0 due to 4969969 to check the exclusion filters before checking for line numbers. So why is VisualMust running into this? The issue is that it's trying to "step into" the JFrame constructor but as there's an exclusion filter for javax.*. In this case the JDWP agent is forced to enable MethodEntry events so that it can return control to the debugger the thread gets to a non-excluded method or steps to the line following the JFrame constructor. Enabling method entry methods means that the execution is slow as it executes in interpreter and the handler must be executed at every method entry. 1.4.2 and 1.5.0 do essentially the same thing - it just happens that in this case there are a lot more method entry events. ###@###.### 2004-05-12 -------------------------------------------- Reassigning to classes_swing. I found that the stepping slowdown only occurs on windows, and only when the test program looks like this: // Test to measure time to create JFrame import javax.swing.*; public class vm { public static void main(String[] args) { JFrame f; long start, end; try { javax.swing.UIManager.setLookAndFeel( javax.swing.UIManager.getSystemLookAndFeelClassName()); } catch( Throwable exc) { } start = System.currentTimeMillis(); f = new JFrame("my frame"); end = System.currentTimeMillis(); System.out.println("JFrame creation took " + (end - start) + " ms"); } } Without that call to setLookAndFeel, the step slowdown does not occur. This can be seen with jdb; it is not necessary to run VisualMust. When the above test is run directly (ie, not under jdb), I see these times reported on my win 2k machine: 1.4.2: ~150 ms 5.0: ~500 ms Thus, we see the slowdown when no debugging is being performed. This slowdown is apparently caused by the large increase in the number of method calls being done in 5.0. In 5.0, JPDA stepping is actually faster than it was in 1.4.2 so this speed regression, should be considered to be a swing problem. We could try to make JPDA stepping even faster; I opened RFE 6221088: JDWP: Speed up stepping in the presence of filters to cover this. ###@###.### 2005-1-25 03:58:26 GMT This points to slowness related to the WindowsLookAndFeel. Other bugs have been filed against Tiger for this very issue, notably: 5027400 : Creating UI with WindowsLookAndFeel is slow I'm happy to report that great progress has been made on this bug due to fixing: 5106661 : XP L&F does not work on Longhorn - needs to use uxtheme api and 4795932 : RFE: Java 2D should locate fonts by using the windows registry My latest results show that the WindowsLookAndFeel is now within ~30ms of Ocean (see 5027400). This also greatly improves performance of the vm.java test case. My rather quick machine yields the following scores: 1.5.0: ~220ms 1.6.0b20: ~60ms. I would encourage you to look into a recent Mustang build, and confirm that this problem is resolved. ###@###.### 2005-1-25 21:34:23 GMT Customer just tried the latest Mustang build and have not noticed improvements :-( ###@###.### 2005-2-14 17:51:24 GMT Attach the new version of VisualMust that works for Mustang release. ###@###.### 2005-2-16 18:11:32 GMT
14-02-2005