setVisible takes too long to return

[Chantal Ackermann]

hello all,
I just wrote a little JComboBox test and I ran into a problem that I can't explain (and I couldn't find information on it in the net after a quick search). Maybe I just missed something obvious.
Here is the little program. It just adds a JComboBox to a JFrame. When I run this program the frame pops up, but it takes a while until the combo actually gets added.
the print statements show that the method setVisible takes unusually long to return. I say, unusually as I never noticed this problem before.
Could someone tell me what happens here?

/*
* ComboTest.java
*/
import java.awt.*;
import javax.swing.*;
public class ComboTest
{
public ComboTest()
{
final JFrame f = new JFrame("Combo Test");
f.getContentPane().setLayout(new BorderLayout());
System.out.println("created frame");
f.setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE);
String[] items = new String[20];
System.out.println("created data store");
for (int i = 0; i<20; i++)
{
items[i] = "item " + (i+1);
}
System.out.println("populated data store");
final JComboBox box = new JComboBox(new DefaultComboBoxModel(items));
System.out.println("created combo");
box.setPrototypeDisplayValue("item ##");
f.getContentPane().add(box, BorderLayout.NORTH);
System.out.println("combo added");
f.pack();
System.out.println("pack");
f.setVisible(true);
System.out.println("set visible");
}
public static void main(String[] args)
{
new ComboTest();
}
}

[Nathan Pruett]

I changed your code to calculate how many milliseconds it took to do each step... I don't see any problems..

/** ComboTest.java*/
import java.awt.*;
import javax.swing.*;
public class ComboTest {
public ComboTest(){
long time = System.currentTimeMillis();
final JFrame f = new JFrame("Combo Test");
f.getContentPane().setLayout(new BorderLayout());
long diff = System.currentTimeMillis() - time;
time = System.currentTimeMillis();
System.out.println("created frame - " + diff );
f.setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE);
String[] items = new String[20];
diff = System.currentTimeMillis() - time;
time = System.currentTimeMillis();
System.out.println("created data store - " + diff );
for (int i = 0; i<20; i++) {
items[i] = "item " + (i+1);
}
diff = System.currentTimeMillis() - time;
time = System.currentTimeMillis();
System.out.println("populated data store - " + diff );
final JComboBox box = new JComboBox(new DefaultComboBoxModel(items));
diff = System.currentTimeMillis() - time;
time = System.currentTimeMillis();
System.out.println("created combo - " + diff);
//box.setPrototypeDisplayValue("item ##");
f.getContentPane().add(box, BorderLayout.NORTH);
diff = System.currentTimeMillis() - time;
time = System.currentTimeMillis();
System.out.println("combo added - " + diff );
f.pack();
diff = System.currentTimeMillis() - time;
time = System.currentTimeMillis();
System.out.println("pack - " + diff );
f.setVisible(true);
diff = System.currentTimeMillis() - time;
time = System.currentTimeMillis();
System.out.println("set visible - " + diff);
}

public static void main(String[] args) {
new ComboTest();
}
}

I get output that looks like this...

created frame - 270
created data store - 0
populated data store - 0
created combo - 210
combo added - 0
pack - 30
set visible - 40

[Chantal Ackermann]

wuhh...
I am running this on linux, jdk 1.4.1-beta. I compiled it with a call to javac without setting any options.
The output is:
created frame - 825
created data store - 2
populated data store - 1
created combo - 308
combo added - 0
pack - 264
set visible - 5120
The really weird thing is, I am developing complex guis on this system and I never noticed this behaviour.
compiling with g:none (debugging of) results in:
created frame - 945
created data store - 1
populated data store - 1
created combo - 321
combo added - 1
pack - 273
set visible - 5133
that's even worse.
What's happening? is this a parallel universe?
Maybe I should sacrifice some profiler evaluation copy to see what's going on?!

[Chantal Ackermann]

just compiled and ran the program on different jdks: 1.4.0 and 1.4.1 doesn't defer much, but the result of jdk 1.3 (IBM jit-enabled) is:
created frame - 1009
created data store - 2
populated data store - 0
created combo - 778
combo added - 1
pack - 52
set visible - 323
jdk 1.3.1_04:
( haven't seen this error output (Font...) for a long time ;-) )
Font specified in font.properties not found [--symbol-medium-r-normal--*-%d-*-*-p-*-adobe-fontspecific]
created frame - 2219
created data store - 1
populated data store - 1
created combo - 470
combo added - 1
pack - 145
set visible - 5021
just to throw some more benchmarks at you: the combobox is not the problem. adding a JTextField instead of a JComboBox doesn't make it faster:
created frame - 903
created text field - 176
text field added - 1
pack - 230
set visible - 5029
any ideas, comments, experiences? I'm definitely interested. is this really a linux problem?

[Nathan Pruett]

Sorry for not mentioning this in my earlier post...

The system I am running it on is a Pentium 4 1.8Ghz with Windows2K with JDK 1.3.1_01 (my machine at work... )

I'll try this out on my (much slower) machines at home and see what the numbers work out to...

I'm betting that most of the "native-peer" stuff gets set up in the setVisible() call, so that may behave different ways on different systems depending on the native resources being called... so there may be a speed difference between Windows and Linux implementations of the "native-peer" JDK code...

Anyone else out there have any numbers from running this?

[Chantal Ackermann]

I paid more attention on how long my bigger apps take to come up. for example do I have a splash screen composed of a jframe and an image where the jframe pops up first and only after some moments the image is displayed.
so, obiously it's the jdk for linux. Although I have only (compared to you machine) 500Hz CPU, I don't (want to) think it's a CPU problem. 500Hz should be more than enough to process this little window!