Skip to main content

Dtrace/build 55, Issues with some probes

4 replies [Last post]
tayloral
Offline
Joined: 2005-10-11

hi.
i've been trying out the dtrace probes build into the 64bit amd build of the current mustang snapshot release.
why, mainly because i'm curious about dtrace, and i was wondering if i could build some funky scripts that would look for various locking/race conditions problems in a project we have.

unfortunately i don't seem able to get it working correctly, i'll include as much detail as possible below.

Basically, only a subset of the probes seem to return anything. The working probes are:
Thread start/stop GC start/stop and JVM shutdown.

Some of the ones which don't seem to be invoked are:
monitor wait/enter. object allocation, and method entry/exit.

The setup is as follows:
jdk build 055. invoked with -d64 parameter on an amd64 solaris 10 machine.

OS details:
# uname -a :
SunOS solberth 5.10 Generic_118844-08 i86pc i386 i86pc
running process details:
ajt1 8563 8562 5 22:39:31 pts/5 0:02 /opt/tp/jdk/jdk1.6.0/bin/amd64/java -verbose:gc -Xmx1G -Dxn.external.classpath=

runtime libraries:
# pldd 8563
8563: /opt/tp/jdk/jdk1.6.0/bin/amd64/java -verbose:gc -Xmx1G -Dxn.external.c
/lib/amd64/libthread.so.1
/lib/amd64/libdl.so.1
/lib/amd64/libc.so.1
/opt/tp/jdk/jdk1.6.0/jre/lib/amd64/server/libjvm.so
/lib/amd64/libsocket.so.1
/usr/lib/amd64/libsched.so.1
/usr/lib/amd64/libCrun.so.1
/lib/amd64/libm.so.2
/lib/amd64/libdoor.so.1
/lib/amd64/libnsl.so.1
/lib/amd64/libscf.so.1
/lib/amd64/libuutil.so.1
/lib/amd64/libmd5.so.1
/lib/amd64/libmp.so.2
/opt/tp/jdk/jdk1.6.0/jre/lib/amd64/native_threads/libhpi.so
/opt/tp/jdk/jdk1.6.0/jre/lib/amd64/libverify.so
/opt/tp/jdk/jdk1.6.0/jre/lib/amd64/libjava.so
/opt/tp/jdk/jdk1.6.0/jre/lib/amd64/libzip.so
/usr/lib/locale/en_GB.ISO8859-1/amd64/en_GB.ISO8859-1.so.3
/opt/tp/jdk/jdk1.6.0/jre/lib/amd64/libj2pkcs11.so
/usr/lib/amd64/libpkcs11.so.1
/usr/lib/amd64/libcryptoutil.so.1
/usr/lib/security/amd64/pkcs11_softtoken.so.1
/opt/tp/jdk/jdk1.6.0/jre/lib/amd64/libnet.so
/opt/tp/jdk/jdk1.6.0/jre/lib/amd64/libnio.so
/lib/amd64/librt.so.1
/lib/amd64/libaio.so.1

version information:
# /opt/tp/jdk/jdk1.6.0/bin/java -d64 -version
java version "1.6.0-ea"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.6.0-ea-b55)
Java HotSpot(TM) 64-Bit Server VM (build 1.6.0-ea-b55, mixed mode)

simple dtrace script to print verbose info on running app.
#!/usr/sbin/dtrace -s

hotspot$target:::object-alloc
{
printf(" object alloc");
}

hotspot$target:::gc-begin
{
printf("gc-begin %8d",timestamp);
}

hotspot$target:::gc-end
{
printf("gc-end");
}

hotspot$target:::monitor-waited
{
printf("mon waited %8d",timestamp);
}
hotspot$target:::monitor-wait
{
printf("mon wait %8d",timestamp);
}

hotspot$target:::monitor-notifyAll
{
printf("mon notify %8d",timestamp);
}

hotspot$target:::vm-shutdown
{
printf("SHUTDOWN %8d",timestamp);
}

hotspot$target:::thread-start
{
printf("mon notify %8d",timestamp);
}
hotspot$target:::thread-stop
{
printf("mon notify %8d",timestamp);
}
hotspot$target:::monitor-contended-enter
{
printf("mon notify %8d",timestamp);
}

The output from this dtrace script when invoked on an a test run of the app might look like the following:

0 483 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-end gc-end
0 507 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-begin gc-begin 7391539817384
0 483 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-end gc-end
0 507 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-begin gc-begin 7391689032937
0 483 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-end gc-end
0 507 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-begin gc-begin 7391821224659
0 483 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-end gc-end
0 478 __1cKJavaThreadDrun6M_v_:thread-start mon notify 7391827123747
0 478 __1cKJavaThreadDrun6M_v_:thread-start mon notify 7391827329045
0 478 __1cKJavaThreadDrun6M_v_:thread-start mon notify 7391827474064
0 478 __1cKJavaThreadDrun6M_v_:thread-start mon notify 7391827638981
0 478 __1cKJavaThreadDrun6M_v_:thread-start mon notify 7391827755911
0 507 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-begin gc-begin 7399019982012
0 483 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-end gc-end
dtrace: pid 8577 has exited
0 507 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-begin gc-begin 7399375027558
0 483 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-end gc-end
0 507 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-begin gc-begin 7399553334973
0 483 __1cbAVM_GenCollectForAllocationEdoit6M_v_:gc-end gc-end
0 478 __1cKJavaThreadDrun6M_v_:thread-start mon notify 7399693754427
0 478 __1cKJavaThreadDrun6M_v_:thread-start mon notify 7399693969909
0 478 __1cKJavaThreadDrun6M_v_:thread-start mon notify 7399703123573
0 485 __1cKJavaThreadRthread_main_inner6M_v_:thread-stop mon notify 7399703715019
0 501 __1cLbefore_exit6FpnKJavaThread__v_:vm-shutdown SHUTDOWN 7399762085643
0 500 __1cHvm_exit6Fi_v_:vm-shutdown SHUTDOWN 7399762099179

using 'dtrace -l | grep hotspot' the probes for allocation/monitors etc. do seem to be there. eg
488 hotspot8585 libjvm.so __1cNCompileBrokerZinvoke_compiler_on_method6FpnLCompileTask__v_ method-compile-begin
489 hotspot8585 libjvm.so __1cHThreadsJcreate_vm6FpnOJavaVMInitArgs_pb_i_ vm-init-end
490 hotspot8585 libjvm.so __1cNObjectMonitorFenter6MpnGThread__v_ monitor-contended-enter
491 hotspot8585 libjvm.so __1cHnmethodbFpost_compiled_method_load_event6M_v_ compiled-method-load
492 hotspot8585 libjvm.so __1cSObjectSynchronizerEwait6FnGHandle_xpnGThread__v_ monitor-wait
493 hotspot8585 libjvm.so __1cNSharedRuntimeYdtrace_method_entry_work6FpnKJavaThread_pnNmethodOopDesc__i_ method-entry
494 hotspot8585 libjvm.so __1cNSharedRuntimeTdtrace_object_alloc6FpnHoopDesc__i_ object-alloc
495 hotspot8585 libjvm.so __1cTClassLoadingServiceTnotify_class_loaded6FpnNinstanceKlass_b_v_ class-loaded

but i'm at a loss as to howto pick up the object creation events.
could it be either an issue with the script, a missing jvm startup flag or a bug in this build?

if any more information is required please don't hesitate to ask.

thanks
alistair.

(ps. i know the pid's of pldd and dtrace -l don't match i got the detail from seperate runs)

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
tayloral
Offline
Joined: 2005-10-11

hi, yes that setting does indeed enable all the probes.
thanks for that.

i can also confirm that i do not see any of the monitor probes unless that setting is enabled.

hopefully my simple test script is correct,

i see output like:
0 32856 __1cNObjectMonitorFenter6MpnGThread__v_:monitor-contended-enter
mon contended ENTER 0 19
mon contended ENTER 1 5511800
mon contended ENTER 2 com/ubs/eq/tes/raptor/util/UnboundedQueue\0
mon contended ENTER 3 41

0 32877 __1cNObjectMonitorKExitEpilog6MpnGThread_pnMObjectWaiter__v_:monitor-contended-exit
mon contended EXIT 0 17
mon contended EXIT 1 5505584
mon contended EXIT 2 com/ubs/eq/tes/raptor/util/Semaphore\0
mon contended EXIT 3 36

0 32868 __1cNObjectMonitorFenter6MpnGThread__v_:monitor-contended-entered
mon contended ENTERED 0 19
mon contended ENTERED 1 5511800
mon contended ENTERED 2 com/ubs/eq/tes/raptor/util/UnboundedQueue\0
mon contended ENTERED 3 41

libjvm.so`__1cNObjectMonitorFenter6MpnGThread__v_+0x482
libjvm.so`__1cSObjectSynchronizerKslow_enter6FnGHandle_pnJBasicLock_pnGThread__v_+0xc6
libjvm.so`__1cSObjectSynchronizerKfast_enter6FnGHandle_pnJBasicLock_bpnGThread__v_+0x71
libjvm.so`__1cSInterpreterRuntimeMmonitorenter6FpnKJavaThread_pnPBasicObjectLock__v_+0x183
0xfffffd7ffb40d215
0xfffffd7ffb402f49
0xfffffd7ffb403423
0xfffffd7ffb40032e
libjvm.so`__1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x1d2
libjvm.so`__1cCosUos_exception_wrapper6FpFpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v2468_v_+0x18
libjvm.so`__1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x2d

from this script fragment:
hotspot$target:::monitor-contended-exit
{
printf("\n");
printf(" mon contended EXIT 0 %d\n",(arg0));
printf(" mon contended EXIT 1 %d\n",(arg1));
printf(" mon contended EXIT 2 %S\n",copyinstr(arg2));
printf(" mon contended EXIT 3 %d\n",arg3);

}
hotspot$target:::monitor-contended-enter
{
printf("\n");
printf(" mon contended ENTER 0 %d\n",(arg0));
printf(" mon contended ENTER 1 %d\n",arg1);
printf(" mon contended ENTER 2 %S\n",copyinstr(arg2));
printf(" mon contended ENTER 3 %d\n",arg3);
}

hotspot$target:::monitor-contended-entered
{
printf("\n");
printf(" mon contended ENTERED 0 %d\n",(arg0));
printf(" mon contended ENTERED 1 %d\n",(arg1));
printf(" mon contended ENTERED 2 %S\n",copyinstr(arg2));
printf(" mon contended ENTERED 3 %d\n",arg3);
jstack(20, 8000);
}

but only when the setting is added on the command line used to start the jvm.
which brings me to a seperate question.
as i'm poking about with dtrace/mustang, which would be the most appropriate forum to ask questions, about the format of these monitors, and the data that can be extracted from them?
i realise that they are subject change, and are not for any serious use.

thanks
alistair.

kamg
Offline
Joined: 2005-06-16

Hi Alistair,

I've posted some details about the probes on my blog:

http://blogs.sun.com/roller/page/kamg?entry=built_in_dtrace_probes_in

alanb
Offline
Joined: 2005-08-08

At this time the method-entry, method-return, and object-alloc probes have a bit of performance impact so they aren't available by default. To enable these probes you need to run with the -XX:+ExtendedDtraceProbes option. Can you double check that you aren't seeing contented monitor related probes firing? They should be there by default.

kamg
Offline
Joined: 2005-06-16

Alan is right. Recent changes in the synchronization system and benchmark runs have indicated that the monitor probes are also having some negative probe effect, so those too, are only enabled when starting the VM with -XX:+ExtendedDtraceProbes.