Java startup is very slow in AIX7.1

aix, java, performance

Solution

I'm not 100% sure on this, but it's at least worth a try:

On AIX, the 32 bit Java VM uses IPv4 as the default IP protocol, while the 64 bit VM uses IPv6. If IPv6 is enabled in the operating system, but incorrectly configured, the 64 bit VM may seem to hang at different points, where it actually is waiting for network timeouts. This seem to match your analysis with truss.

You can try to start the 64 bit VM with IPv4 as the preferred network stack by adding the following option to the java command:

-Djava.net.preferIPv4Stack=true

Problem

AIX 64bit, 7G RAM ``` $ uname -a AIX server3 1 7 00036073D600 $ java -version java version "1.6.0" Java(TM) SE Runtime Environment (build pap6460_26sr1-20111114_01(SR1)) IBM J9 VM (build 2.6, JRE 1.6.0 AIX ppc64-64 20111113_94967 (JIT enabled, AOT enabled) J9VM - R26_Java626_SR1_20111113_1649_B94967 JIT - r11_20111028_21230 GC - R26_Java626_SR1_20111113_1649_B94967 J9CL - 20111113_94967) JCL - 20111112_01 $ time /opt/IBM/WebSphere/AppServer/java/bin/java ... real 0m40.62s user 0m0.43s sys 0m0.04s ``` It takes 40s to start java command without any application. The JRE(64bit) is part of WebSphere V8, and need 20 min. to start Application Server. In the same AIX, there is another JRE(32bit), it works very well. ``` $ /usr/java6/bin/java -version java version "1.6.0" Java(TM) SE Runtime Environment (build pap3260sr9fp2-20110627_03(SR9 FP2)) IBM J9 VM (build 2.4, JRE 1.6.0 IBM J9 2.4 AIX ppc-32 jvmap3260sr9-20110624_85526 (JIT enabled, AOT enabled) J9VM - 20110624_085526 JIT - r9_20101028_17488ifx17 GC - 20101027_AA) JCL - 20110530_01 $ time /usr/java6/bin/java real 0m0.70s user 0m0.64s sys 0m0.05s ``` I found some thing using truss.When java is going to startup, it is blocked at thread_tsleep() for a long time. Why? How to correct it? ``` kopen("/etc/irs.conf", O_RDONLY) Err#2 ENOENT _thread_self() = 26738737 getdomainname(0x09001000A00E44F8, 1024) = 0 _thread_self() = 26738737 _thread_self() = 26738737 _thread_self() = 26738737 getdomainname(0x09001000A00E44F8, 1024) = 0 _thread_self() = 26738737 _thread_self() = 26738737 _thread_self() = 26738737 kopen("/etc/hesiod.conf", O_RDONLY) Err#2 ENOENT _thread_self() = 26738737 getdomainname(0x09001000A00E44F8, 1024) = 0 _thread_self() = 26738737 _thread_self() = 26738737 _thread_self() = 26738737 getdomainname(0x09001000A00E44F8, 1024) = 0 _thread_self() = 26738737 _thread_self() = 26738737 _thread_self() = 26738737 getdomainname(0x09001000A00E44F8, 1024) = 0 _thread_self() = 26738737 _thread_self() = 26738737 socket(2, 2, 0) = 4 getsockopt(4, 65535, 4104, 0x000001001012A934, 0x000001001012A930) = 0 connext(4, 0x00000100103F37B8, 16) = 0 _esend(4, 0x000001001012B860, 40, 0, 0x0000000000000000) = 40 _poll(0x000001001012AA00, 1, 5000) = 1 _enrecvfrom(4, 0x000001001012CBB0, 1024, 0, 0x000001001012B1C0, 0x000001001012A9E8, 0x0000000000000000) = 56 close(4) = 0 socket(2, 2, 0) = 4 getsockopt(4, 65535, 4104, 0x000001001012A934, 0x000001001012A930) = 0 connext(4, 0x00000100103F37B8, 16) = 0 _esend(4, 0x000001001012B860, 40, 0, 0x0000000000000000) = 40 _poll(0x000001001012AA00, 1, 5000) = 1 _enrecvfrom(4, 0x000001001012CBB0, 1024, 0, 0x000001001012B1C0, 0x000001001012A9E8, 0x0000000000000000) = 94 _esend(4, 0x000001001012B860, 25, 0, 0x0000000000000000) = 25 _poll(0x000001001012AA00, 1, 5000) = 1 _enrecvfrom(4, 0x000001001012CBB0, 1024, 0, 0x000001001012B1C0, 0x000001001012A9E8, 0x0000000000000000) = 25 close(4) = 0 socket(2, 2, 0) = 4 _esendto(4, 0x000001001012B860, 25, 0, 0x00000100103F37C8, 16, 0x0000000000000000) = 25 thread_tsleep(0, 0x09001000A030F400, 0x0000000000000000, 0x0000000000000000) (sleeping...) _poll(0x000001001012AA00, 1, 5000) = 0 close(4) = 0 socket(2, 2, 0) = 4 _esendto(4, 0x000001001012B860, 25, 0, 0x00000100103F37C8, 16, 0x0000000000000000) = 25 thread_tsleep(0, 0x09001000A030F400, 0x0000000000000000, 0x0000000000000000) (sleeping...) _poll(0x000001001012AA00, 1, 5000) = 0 close(4) = 0 socket(2, 2, 0) = 4 _esendto(4, 0x000001001012B860, 25, 0, 0x00000100103F37C8, 16, 0x0000000000000000) = 25 thread_tsleep(0, 0x09001000A030F400, 0x0000000000000000, 0x0000000000000000) (sleeping...) _poll(0x000001001012AA00, 1, 10000) = 0 close(4) = 0 socket(2, 2, 0) = 4 _esendto(4, 0x000001001012B860, 25, 0, 0x00000100103F37C8, 16, 0x0000000000000000) = 25 thread_tsleep(0, 0x09001000A030F400, 0x0000000000000000, 0x0000000000000000) (sleeping...) _poll(0x000001001012AA00, 1, 20000) = 0 close(4) = 0 getdomainname(0x000001001012CD10, 256) = 0 kopen("/etc/hosts", O_RDONLY) = 4 kioctl(4, 22528, 0x0000000000000000, 0x0000000000000000) Err#25 ENOTTY kfcntl(4, F_SETFD, 0x0000000000000001) = 0 kioctl(4, 22528, 0x0000000000000000, 0x0000000000000000) Err#25 ENOTTY kread(0x0000000000000004, 0x0000010010416538, 0x0000000000001000) = 0x00000000000007B0 0x00000000: " # = = = = = = = = = =".. kread(0x0000000000000004, 0x0000010010416538, 0x0000000000001000) = 0x0000000000000000 0x00000000: " # = = = = = = = = = =".. close(4) = 0 __libc_sbrk(0x0000000000020020) = 0x0000010010421C20 ``` with timestamp ``` 1.8662: socket(2, 2, 0) = 4 1.8666: _esendto(4, 0x000001001012B860, 25, 0, 0x00000100103F38A8, 16, 0x0000000000000000) = 25 3.8671: thread_tsleep(0, 0x09001000A030F400, 0x0000000000000000, 0x0000000000000000) (sleeping...) 1.8669: _poll(0x000001001012AA00, 1, 5000) = 0 6.8705: close(4) = 0 6.8710: socket(2, 2, 0) = 4 6.8715: _esendto(4, 0x000001001012B860, 25, 0, 0x00000100103F38A8, 16, 0x0000000000000000) = 25 8.8723: thread_tsleep(0, 0x09001000A030F400, 0x0000000000000000, 0x0000000000000000) (sleeping...) 6.8720: _poll(0x000001001012AA00, 1, 5000) = 0 11.8726: close(4) = 0 11.8729: socket(2, 2, 0) = 4 11.8732: _esendto(4, 0x000001001012B860, 25, 0, 0x00000100103F38A8, 16, 0x0000000000000000) = 25 13.8738: thread_tsleep(0, 0x09001000A030F400, 0x0000000000000000, 0x0000000000000000) (sleeping...) 11.8736: _poll(0x000001001012AA00, 1, 10000) = 0 21.8741: close(4) = 0 21.8744: socket(2, 2, 0) = 4 21.8748: _esendto(4, 0x000001001012B860, 25, 0, 0x00000100103F38A8, 16, 0x0000000000000000) = 25 23.8754: thread_tsleep(0, 0x09001000A030F400, 0x0000000000000000, 0x0000000000000000) (sleeping...) 21.8752: _poll(0x000001001012AA00, 1, 20000) = 0 41.8756: close(4) = 0 41.8760: getdomainname(0x000001001012CD10, 256) = 0 41.8763: kopen("/etc/hosts", O_RDONLY) = 4 41.8767: kioctl(4, 22528, 0x0000000000000000, 0x0000000000000000) Err#25 ENOTTY 41.8770: kfcntl(4, F_SETFD, 0x0000000000000001) = 0 41.8773: kioctl(4, 22528, 0x0000000000000000, 0x0000000000000000) Err#25 ENOTTY kread(0x0000000000000004, 0x0000010010416618, 0x0000000000001000) = 0x00000000000007B0 0x00000000: " # = = = = = = = = = =".. kread(0x0000000000000004, 0x0000010010416618, 0x0000000000001000) = 0x0000000000000000 0x00000000: " # = = = = = = = = = =".. 41.8782: close(4) = 0 ``` tp ``` Quit in sem_wait at 0x9000000002632d8 ($t3) 0x9000000002632d8 (sem_wait+0x98) e8410028 ld r2,0x28(r1) thread state-k wchan state-u k-tid mode held scope function >$t1 run blocked 31391751 u no sys _event_sleep _event_sleep(??, ??, ??, ??, ??, ??) at 0x9000000008365c4 _event_wait(??, ??) at 0x900000000837064 _cond_wait_local(??, ??, ??) at 0x90000000084521c _cond_wait(??, ??, ??) at 0x900000000845808 pthread_join(??, ??) at 0x90000000082d2b0 unnamed block in ContinueInNewThread(continuation = 0x6c6f636b6c002e66, stack_size = 7310577395057127012, args = 0x5f6f72002e666574), line 2286 in "java_md.c" ContinueInNewThread(continuation = 0x6c6f636b6c002e66, stack_size = 7310577395057127012, args = 0x5f6f72002e666574), line 2286 in "java_md.c" unnamed block in main(argc = 0, argv = 0x000001001000c178), line 532 in "java.c" main(argc = 0, argv = 0x000001001000c178), line 532 in "java.c" thread state-k wchan state-u k-tid mode held scope function >$t2 run running 54329549 u no sys __fd_poll __fd_poll(??, ??, ??) at 0x90000000012c0d4 res_send.poll(??, ??, ??) at 0x9000000001021ac res_nsend(0x100103f37a8, 0x1001012b860, 0x1900000019, 0x1001012cbb0, 0x40000000400) at 0x9000000001011d4 res_nquery(??, ??, ??, ??, ??, ??) at 0x90000000012b5d8 res_nquerydomain(??, ??, ??, ??, ??, ??, ??) at 0x90000000012ab14 res_nsearch(??, ??, ??, ??, ??, ??) at 0x90000000012af08 res_search(??, ??, ??, ??, ??) at 0x900000000107b50 dns_ho.ho_byname2(??, ??, ??) at 0x90000000013a384 gen_ho.ho_byname2(??, ??, ??) at 0x900000000163888 gethostbyname2(??, ??) at 0x9000000001060ec getaddrinfo2(??, ??, ??, ??, ??) at 0x900000000102ba0 getaddrinfo(??, ??, ??, ??) at 0x900000000104d34 j9sock_getaddrinfo() at 0x9000000053caad8 populateRASNetData() at 0x900000005347fc0 VMInitStages() at 0x9000000053086b0 runJ9VMDllMain() at 0x90000000530bb9c pool.pool_do() at 0x9000000052f29c8 runInitializationStage() at 0x90000000530b890 protectedInitializeJavaVM() at 0x900000005306478 j9sig_protect() at 0x9000000053a2b9c initializeJavaVM() at 0x90000000530585c jniinv.JNI_CreateJavaVM() at 0x90000000530ea14 jvm.JNI_CreateJavaVM() at 0x900000000ccc510 redirector.JNI_CreateJavaVM() at 0x900000000cb5574 InitializeJVM(pvm = (nil), penv = (nil), ifn = (nil)), line 1801 in "java.c" main(argc = 0, argv = (nil)), line 810 in "java.c" thread state-k wchan state-u k-tid mode held scope function >$t3 run running 52887625 k no sys sem_wait sem_wait(??) at 0x9000000002632d8 asynchSignalReporter() at 0x9000000053a3dcc thread_wrapper() at 0x900000000d00ad0 !!!! ThreadDump Completed- detached from debugger !!!! ``` Update I found this topic, and test the program on my AIX. When using hostname, it delayed for about 40s for DNS query. IP Address is normal. Java cannot resolve DNS address from AIX: UnknownHostException By the way, the hostname shows server3, when I ping the name, it shows : PING server3.cf1.xx.xxxx.com ..... I run the program using server3.cf1.xx.xxxx.com, there is no delay. Update2: It is IPV6 problem. If I add -Djava.net.preferIPv4Stack=true, the java application runs well. But java command still uses IPV6 to query DNS. So java command has 40s delay, and java application has no deley on DNS query. Can I set the default protocol to IPV4 in AIX, not java parameter?

Original source