java startup hanging on /dev/dtrace/helper

[Maidak Alexander J]

I have a T5240 running Solaris 10u9 (144488-07) and using java "1.6.0_23". Doing a simple "/bin/java -version" is terribly slow and and takes many seconds (12-30+). Looking at the startup with truss I see, it hang for many seconds on:

open64("/dev/dtrace/helper", O_RDWR) = 3

If I "export DTRACE_DOF_INIT_DISABLE=1" before running "/bin/java -version" the command takes less then 1 second. I assume this disables the dtrace helper program from loading/linking with java. I'm stumped as to why dtrace would be causing a performance slowdown in this situation. I have other similarly configured T5240's running the exact same Solaris and Java releases, but they're not exhibiting the same issue. Any advice as to what might be causing this issue would be much appreciated.

Thanks,

Alex

[Robert Harris]

Post by Maidak Alexander J
open64("/dev/dtrace/helper", O_RDWR) = 3
If I “export DTRACE_DOF_INIT_DISABLE=1” before running “/bin/java –version” the command takes less then 1 second. I assume this disables the dtrace helper program from loading/linking with java. I’m stumped as to why dtrace would be causing a performance slowdown in this situation. I have other similarly configured T5240’s running the exact same Solaris and Java releases, but they’re not exhibiting the same issue. Any advice as to what might be causing this issue would be much appreciated.

Can you post a snippet of 'truss -d' output surrounding the
open64()?

R

[Maidak Alexander J]

Post by Robert Harris

Post by Maidak Alexander J
I have a T5240 running Solaris 10u9 (144488-07) and using java "1.6.0_23". Doing a simple "/bin/java -version" is terribly slow and and takes many
open64("/dev/dtrace/helper", O_RDWR) = 3

Can you post a snippet of 'truss -d' output surrounding the
open64()?

See below...

0.5603 stat64("/usr/jdk/instances/jdk1.6.0/jre/../lib/sparc/libmp.so.2", 0xFFBFE198) Err#2 ENOENT
0.5608 stat64("/lib/libmp.so.2", 0xFFBFE198) = 0
0.5611 resolvepath("/lib/libmp.so.2", "/lib/libmp.so.2", 1023) = 15
0.5616 open("/lib/libmp.so.2", O_RDONLY) = 3
0.5619 mmap(0xFF1E0000, 32768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF1E0000
0.5621 mmap(0x00010000, 90112, PROT_NONE, MAP_PRIVATE|MAP_NORESERVE|MAP_ANON|MAP_ALIGN, -1, 0) = 0xFEF10000
0.5622 mmap(0xFEF10000, 10156, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_TEXT, 3, 0) = 0xFEF10000
0.5624 mmap(0xFEF24000, 797, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_INITDATA, 3, 16384) = 0xFEF24000
0.5625 munmap(0xFEF14000, 65536) = 0
0.5629 memcntl(0xFEF10000, 2092, MC_ADVISE, MADV_WILLNEED, 0, 0) = 0
0.5630 close(3) = 0
0.5632 stat64("/usr/jdk/instances/jdk1.6.0/jre/lib/sparc/server/libc.so.1", 0xFFBFE0D0) Err#2 ENOENT
0.5637 stat64("/usr/jdk/instances/jdk1.6.0/jre/lib/sparc/libc.so.1", 0xFFBFE0D0) Err#2 ENOENT
0.5642 stat64("/usr/jdk/instances/jdk1.6.0/jre/../lib/sparc/libc.so.1", 0xFFBFE0D0) Err#2 ENOENT
0.5669 munmap(0xFF1E0000, 32768) = 0
0.5673 sigfillset(0xFF33937C) = 0
0.5686 open64("/dev/dtrace/helper", O_RDWR) = 3
49.5328 ioctl(3, (('d'<<24)|('t'<<16)|('h'<<8)|3), 0xFFBFEC18) = 0
49.5332 close(3) = 0
49.5335 brk(0x0002D410) = 0
49.5336 brk(0x0002F410) = 0
49.5340 mmap(0x00000000, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANON, -1, 0) = 0xFEEF0000
49.5343 mmap(0x00000000, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANON, -1, 0) = 0xFEED0000
49.5346 sigaction(SIGCANCEL, 0xFFBFECA8, 0x00000000) = 0
49.5348 sysconfig(_CONFIG_STACK_PROT) = 3
49.5349 mmap(0x00000000, 524288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_NORESERVE|MAP_ANON, -1, 0) = 0xFE300000
49.5351 mmap(0x00010000, 65536, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANON|MAP_ALIGN, -1, 0) = 0xFEEB0000
49.5355 lwp_create(0xFFBFED90, LWP_SUSPENDED, 0xFFBFED8C) = 2
/2: 49.5355 lwp_create() (returning as new lwp ...) = 0
/1: 49.5361 schedctl() = 0xFF3E8000
/1: 49.5363 lwp_continue(2) = 0
/2: 49.5363 setustack(0xFEEB0288)
/2: 49.5366 schedctl() = 0xFF3E8010
/2: 49.5368 getpid() = 9630 [9629]
/2: 49.5370 sysconfig(_CONFIG_NPROC_CONF) = 128
/2: 49.5371 sysconfig(_CONFIG_NPROC_ONLN) = 128

[Alan Hargreaves]

See Sun Alert 1296670.1.

Regards,
Alan Hargreaves

Post by Maidak Alexander J
I have a T5240 running Solaris 10u9 (144488-07) and using java "1.6.0_23". Doing a simple "/bin/java -version" is terribly slow and and takes many
open64("/dev/dtrace/helper", O_RDWR) = 3

--
<http://www.oracle.com> * Hardware and Software, Engineered to Work
Together*

Alan Hargreaves | Senior Principal Technical Support Engineer |
Principal Field Technologist
Solaris and Networking | Global Systems Support
Email: alan.hargreaves-QHcLZuEGTsvQT0dZR+***@public.gmane.org <mailto:alan.hargreaves-QHcLZuEGTsvQT0dZR+***@public.gmane.org>
Blog: alanhargreaves.wordpress.com <http://alanhargreaves.wordpress.com>
Oracle Global Customer Services

Log, update, and monitor your Service Request online using My Oracle
Support <http://support.oracle.com>

[David Pacheco]

Post by Alan Hargreaves
See Sun Alert 1296670.1.

Alan,

Do you have a link to information about this Sun Alert?

Thanks,
Dave

Post by Alan Hargreaves
Regards,
Alan Hargreaves
I have a T5240 running Solaris 10u9 (144488-07) and using java "1.6.0_23". Doing a simple "/bin/java -version" is terribly slow and and takes many
open64("/dev/dtrace/helper", O_RDWR) = 3
--
<http://www.oracle.com> * Hardware and Software, Engineered to Work
Together*
Alan Hargreaves | Senior Principal Technical Support Engineer | Principal
Field Technologist
Solaris and Networking | Global Systems Support
Blog: alanhargreaves.wordpress.com
Oracle Global Customer Services
Log, update, and monitor your Service Request online using My Oracle
Support <http://support.oracle.com>
_______________________________________________
dtrace-discuss mailing list

[Robert Harris]

Post by Maidak Alexander J

Post by Robert Harris

Post by Maidak Alexander J
I have a T5240 running Solaris 10u9 (144488-07) and using java "1.6.0_23". Doing a simple "/bin/java -version" is terribly slow and and takes many
open64("/dev/dtrace/helper", O_RDWR) = 3

Can you post a snippet of 'truss -d' output surrounding the
open64()?

0.5686 open64("/dev/dtrace/helper", O_RDWR) = 3
49.5328 ioctl(3, (('d'<<24)|('t'<<16)|('h'<<8)|3), 0xFFBFEC18) = 0

By default, a library containing a USDT provider will offer the
corresponding DOF, stored in one of its ELF sections, to the
kernel's DTrace framework. It will do so whether or not any of the
probes are to be instrumented; the mechanism involves code
insinuated into the object's _init() during compilation with
'dtrace -G'.

I suspect that you are witnessing libjvm.so supplying the hotspot
provider and the jstack() action. You should be able to confirm
this by running 'pstack' against the process during the time that
it appears to be hanging; you should see this library's _init()
near the top of the stack. I would then be interested in verifying
that the same library is in use on your unaffected machines.

For short-lived processes with a lot of DOF the behaviour
described above may well result in unacceptable performance. The
solution is to regenerate the offending library with dtrace's
(undocumented) "lazyload" option. In the meantime, setting
DTRACE_DOF_INIT_DISABLE, as you have done, has (if I remember
correctly) precisely the same result. Note that deferred loading
of the DOF introduces a subtle change in behaviour for libjvm.so:
the jstack() action won't work unless you attempt to instrument a
pid or USDT probe in the java process.

R